Re: r269147: NULL mp in getnewvnode() via kern_proc_filedesc_out()

On 8/8/2014 6:46 AM, Konstantin Belousov wrote:
> On Thu, Aug 07, 2014 at 08:11:11AM +0200, Peter Holm wrote:
>> On Wed, Aug 06, 2014 at 09:15:12PM +0300, Konstantin Belousov wrote:
>>> On Wed, Aug 06, 2014 at 12:48:28PM -0500, Bryan Drewery wrote:
>>>> On 8/5/2014 10:56 PM, Bryan Drewery wrote:
>>>>> On 8/5/2014 10:19 PM, Konstantin Belousov wrote:
>>>>>> On Tue, Aug 05, 2014 at 09:47:57PM -0500, Bryan Drewery wrote:
>>>>>>> Has anyone else encountered this? Got it while running poudriere.
>>>>>>>
>>>>>>>> NULL mp in getnewvnode()
>>>>>>>> [...]
>>>>>>>> vn_fullpath1() at vn_fullpath1+0x19d/frame 0xfffffe1247d8e540
>>>>>>>> vn_fullpath() at vn_fullpath+0xc1/frame 0xfffffe1247d8e590
>>>>>>>> export_fd_to_sb() at export_fd_to_sb+0x489/frame 0xfffffe1247d8e7c0
>>>>>>>> kern_proc_filedesc_out() at kern_proc_filedesc_out+0x234/frame
>>>>>>>> 0xfffffe1247d8e840
>>>>>>>> sysctl_kern_proc_filedesc() at sysctl_kern_proc_filedesc+0x84/frame
>>>>>>>> 0xfffffe1247d8e900
>>>>>>>> sysctl_root_handler_locked() at
>>>>>>>> sysctl_root_handler_locked+0x68/frame 0xfffffe1247d8e940
>>>>>>>> sysctl_root() at sysctl_root+0x18e/frame 0xfffffe1247d8e990
>>>>>>>> userland_sysctl() at userland_sysctl+0x192/frame 0xfffffe1247d8ea30
>>>>>>>> sys___sysctl() at sys___sysctl+0x74/frame 0xfffffe1247d8eae0
>>>>>>>> amd64_syscall() at amd64_syscall+0x25a/frame 0xfffffe1247d8ebf0
>>>>>>>> Xfast_syscall() at Xfast_syscall+0xfb/frame 0xfffffe1247d8ebf0
>>>>>>>
>>>>>>> Unfortunately I have no dump as the kmem was too large compared to my
>>>>>>> swap, and I didn't get to the console before some of the text was
>>>>>>> overwritten. Perhaps it will hit it again soon after reboot and I'll get
>>>>>>> a core.
>>>>>>
>>>>>> "NULL mp in getnewvnode()" is only the printf(), it is not a panic or
>>>>>> KASSERT.  The event does not stop the machine, nor it prints the
>>>>>> backtrace.
>>>>>>
>>>>>> You mentioned that you was unable to dump, so did the system paniced ?
>>>>>> Without full log of the panic messages and backtrace, it is impossible
>>>>>> to start guessing what the problem is.
>>>>>>
>>>>>> That said, the printf seemingly outlived its usefulness.
>>>>>>
>>>>>
>>>>> Got it. I've set debug.debugger_on_panic=1 to not auto reboot on panic
>>>>> next time this happens. I had it at 0 which was causing the lack of
>>>>> information in these.
>>>>
>>>> Here is the full trace:
>>>>
>>>>
>>>>> NULL mp in getnewvnode()
>>>>> VNASSERT failed
>>>>> 0xfffff806071dc760: tag null, type VDIR
>>>>>     usecount 1, writecount 0, refcount 1 mountedhere 0
>>>>>     flags ()
>>>>>     lock type zfs: EXCL by thread 0xfffff8009a53f490 (pid 1028, tmux, tid 100881)
>>>>>         vp=0xfffff806071dc760, lowervp=0xfffff8013157f588
>>>>> panic: Don't call insmntque(foo, NULL)
>>>>> cpuid = 5
>>>>> KDB: stack backtrace:
>>>>> db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe1247e76b50
>>>>> kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe1247e76c00
>>>>> vpanic() at vpanic+0x126/frame 0xfffffe1247e76c40
>>>>> kassert_panic() at kassert_panic+0x139/frame 0xfffffe1247e76cb0
>>>>> insmntque1() at insmntque1+0x230/frame 0xfffffe1247e76cf0
>>>>> null_nodeget() at null_nodeget+0x158/frame 0xfffffe1247e76d60
>>>>> null_lookup() at null_lookup+0xeb/frame 0xfffffe1247e76dd0
>>>>> VOP_LOOKUP_APV() at VOP_LOOKUP_APV+0xf1/frame 0xfffffe1247e76e00
>>>>> lookup() at lookup+0x5ad/frame 0xfffffe1247e76e90
>>>>> namei() at namei+0x4e4/frame 0xfffffe1247e76f50
>>>>> vn_open_cred() at vn_open_cred+0x27a/frame 0xfffffe1247e770a0
>>>>> vop_stdvptocnp() at vop_stdvptocnp+0x161/frame 0xfffffe1247e773e0
>>>>> null_vptocnp() at null_vptocnp+0x2b/frame 0xfffffe1247e77440
>>>>> VOP_VPTOCNP_APV() at VOP_VPTOCNP_APV+0xf7/frame 0xfffffe1247e77470
>>>>> vn_vptocnp_locked() at vn_vptocnp_locked+0x118/frame 0xfffffe1247e774e0
>>>>> vn_fullpath1() at vn_fullpath1+0x19d/frame 0xfffffe1247e77540
>>>>> vn_fullpath() at vn_fullpath+0xc1/frame 0xfffffe1247e77590
>>>>> export_fd_to_sb() at export_fd_to_sb+0x489/frame 0xfffffe1247e777c0
>>>>> kern_proc_filedesc_out() at kern_proc_filedesc_out+0x234/frame 0xfffffe1247e77840
>>>>> sysctl_kern_proc_filedesc() at sysctl_kern_proc_filedesc+0x84/frame 0xfffffe1247e77900
>>>>> sysctl_root_handler_locked() at sysctl_root_handler_locked+0x68/frame 0xfffffe1247e77940
>>>>> sysctl_root() at sysctl_root+0x18e/frame 0xfffffe1247e77990
>>>>> userland_sysctl() at userland_sysctl+0x192/frame 0xfffffe1247e77a30
>>>>> sys___sysctl() at sys___sysctl+0x74/frame 0xfffffe1247e77ae0
>>>>> amd64_syscall() at amd64_syscall+0x25a/frame 0xfffffe1247e77bf0
>>>>> Xfast_syscall() at Xfast_syscall+0xfb/frame 0xfffffe1247e77bf0
>>>>> --- syscall (202, FreeBSD ELF64, sys___sysctl), rip = 0x801041fca, rsp = 0x7fffffffd878, rbp = 0x7fffffffd8b0 ---
>>>>> KDB: enter: panic
>>>>> [ thread pid 1028 tid 100881 ]
>>>>> Stopped at      kdb_enter+0x3e: movq    $0,kdb_why
>>>>> db> call doadump()
>>>>>
>>>>> Dump failed. Partition too small.
>>>>> = 0
>>>>
>>>
>>> Try this.
>>>
>>> diff --git a/sys/fs/nullfs/null_vnops.c b/sys/fs/nullfs/null_vnops.c
>>> index 481644c..e803c24 100644
>>> --- a/sys/fs/nullfs/null_vnops.c
>>
>> With this patch I get a 
>> panic: Lock (lockmgr) null not locked _at_ kern/vfs_default.c:523.
>>
>> Details _at_ http://people.freebsd.org/~pho/stress/log/kostik698.txt
>>
> 
> Peter tested the updated version of the patch, which fixed both issues
> in his setup.  I committed this variant of the fix as r269708.
> 

Thanks! I had been running it for a few days and not hit any issues.

-- 
Regards,
Bryan Drewery