Skip site navigation (1)Skip section navigation (2)
Date:      Wed, 20 Jan 2016 15:15:06 -0800 (PST)
From:      Don Lewis <truckman@FreeBSD.org>
To:        jhb@freebsd.org
Cc:        freebsd-current@freebsd.org
Subject:   Re: panic: sbuf_vprintf called with a NULL sbuf pointer
Message-ID:  <201601202315.u0KNF687077387@gw.catspoiler.org>
In-Reply-To: <2246380.LId0aa2Jcy@ralph.baldwin.cx>

next in thread | previous in thread | raw e-mail | index | archive | help
On  8 Dec, John Baldwin wrote:
> On Tuesday, December 08, 2015 11:39:56 AM Don Lewis wrote:
>> On  8 Dec, John Baldwin wrote:
>> > On Monday, December 07, 2015 10:10:51 PM Don Lewis wrote:
>> >> On  2 Dec, John Baldwin wrote:
>> >> > On Wednesday, December 02, 2015 01:25:56 PM Don Lewis wrote:
>> >> >> > If you want to look at this further, try going to frame 16 and dissassembling the
>> >> >> > instructions before the call to see if you can spot which register the first
>> >> >> > parameter (saved in %rdi IIRC) comes from.
>> >> >> 
>> >> >> Dump of assembler code for function sbuf_printf:
>> >> >>    0xffffffff80a673e0 <+0>:	push   %rbp
>> >> >>    0xffffffff80a673e1 <+1>:	mov    %rsp,%rbp
>> >> >>    0xffffffff80a673e4 <+4>:	push   %r14
>> >> >>    0xffffffff80a673e6 <+6>:	push   %rbx
>> >> >>    0xffffffff80a673e7 <+7>:	sub    $0x50,%rsp
>> >> >>    0xffffffff80a673eb <+11>:	mov    %rsi,%r14
>> >> >>    0xffffffff80a673ee <+14>:	mov    %rdi,%rbx
>> >> >>    0xffffffff80a673f1 <+17>:	mov    %r9,-0x38(%rbp)
>> >> >>    0xffffffff80a673f5 <+21>:	mov    %r8,-0x40(%rbp)
>> >> >>    0xffffffff80a673f9 <+25>:	mov    %rcx,-0x48(%rbp)
>> >> >>    0xffffffff80a673fd <+29>:	mov    %rdx,-0x50(%rbp)
>> >> >>    0xffffffff80a67401 <+33>:	lea    -0x60(%rbp),%rax
>> >> >>    0xffffffff80a67405 <+37>:	mov    %rax,-0x20(%rbp)
>> >> >>    0xffffffff80a67409 <+41>:	lea    0x10(%rbp),%rax
>> >> >>    0xffffffff80a6740d <+45>:	mov    %rax,-0x28(%rbp)
>> >> >>    0xffffffff80a67411 <+49>:	movl   $0x30,-0x2c(%rbp)
>> >> >>    0xffffffff80a67418 <+56>:	movl   $0x10,-0x30(%rbp)
>> >> >>    0xffffffff80a6741f <+63>:	mov    $0xffffffff8137bdf8,%rdi
>> >> >>    0xffffffff80a67426 <+70>:	mov    %rbx,%rsi
>> >> >>    0xffffffff80a67429 <+73>:	callq  0xffffffff80a66c00 <_assert_sbuf_integrity>
>> >> >> 
>> >> >> 
>> >> >>    0xffffffff80a237b9 <+825>:	jmpq   0xffffffff80a236fd <sigexit+637>
>> >> >>    0xffffffff80a237be <+830>:	mov    $0xffffffff80fd8ad3,%rsi
>> >> >>    0xffffffff80a237c5 <+837>:	xor    %eax,%eax
>> >> >>    0xffffffff80a237c7 <+839>:	mov    %r12,%rdi
>> >> >>    0xffffffff80a237ca <+842>:	mov    -0x228(%rbp),%rdx
>> >> >>    0xffffffff80a237d1 <+849>:	callq  0xffffffff80a673e0 <sbuf_printf>
>> >> >> => 0xffffffff80a237d6 <+854>:	inc    %r14d
>> >> >>    0xffffffff80a237d9 <+857>:	jmpq   0xffffffff80a236fd <sigexit+637>
>> >> > 
>> >> > So maybe try 'p $r12' in the corefile_open() frame.
>> >> 
>> >> #17 0xffffffff80a237d6 in corefile_open (compress=0, comm=<optimized out>, 
>> >>     uid=<optimized out>, pid=<optimized out>, td=<optimized out>, 
>> >>     vpp=<optimized out>, namep=<optimized out>)
>> >>     at /usr/src/sys/kern/kern_sig.c:3188
>> >> 3188					sbuf_printf(&sb, "%s", comm);
>> >> (kgdb) p $r12
>> >> $1 = 0
>> > 
>> > So it's definitely zero. :(  The next step is probably to disassemble the
>> > corefile_open function (ugh) and walk backwards to find where %r12 is read
>> > from.  It might be from a local variable on the stack, so then you would
>> > want to examine that memory in the stack and the surrounding memory to see
>> > if there is memory corruption and perhaps if there is anything recognizable
>> > about it (e.g. if the corruption contains some sort of data you recognize,
>> > or if the corruption is bounded by a certain length, etc.).  It's a bit of
>> > a shot in the dark though.
>> > 
>> > Is this reproducible?
>> 
>> No it's not.  The only time it happened was when there was a swap
>> timeout, probably because of a lengthy deep recovery on one of the
>> mirrored swap devices.
>> 
>> The code in question is:
>>         struct sbuf sb;
>> [snip]
>>         (void)sbuf_new(&sb, name, MAXPATHLEN, SBUF_FIXEDLEN);
>> [snip]
>>         for (i = 0; format[i] != '\0'; i++) {
>>                 switch (format[i]) {
>>                 case '%':       /* Format character */
>>                         i++;
>>                         switch (format[i]) {
>> [snip]
>>                         case 'N':       /* process name */
>>                                 sbuf_printf(&sb, "%s", comm);
>>                                 break;
>> 
>> 
>> &sb is used in a bunch of places, so the compiler probably computes its
>> value once by adding the proper offset to the stack pointer and stashing
>> the result in a register.  Since kern.corefile is "%N.core", the failure
>> is happening on the first interation of the loop, so there isn't much
>> opportunity for things to get corrupted.  Also, the control flow in this
>> function only depends on the format, so there shouldn't be anything
>> special about a swap timeout vs. a segfault generated core.
> 
> Yes, r12 is call-safe (IIRC), so I expect it only computes it once as well,
> but I've sometimes seen the compiler spill local vars onto the stack due to
> register pressure.  That said, I think it is unlikely it would have to spill
> &sb during the early part of the function. :(

I had some more time to look at this.  It's a bit messy because
corefile_open() and coredump() both get inlined into sig_exit().  Here's
the section of code from the malloc() call and sbuf_new() to the failing
sbuf_printf() call:

   0xffffffff80a23685 <+517>:   callq  0xffffffff80a00680 <malloc>
   0xffffffff80a2368a <+522>:   mov    %rax,-0x238(%rbp)
   0xffffffff80a23691 <+529>:   lea    -0x138(%rbp),%r12
   0xffffffff80a23698 <+536>:   mov    $0x400,%edx
   0xffffffff80a2369d <+541>:   xor    %ecx,%ecx
   0xffffffff80a2369f <+543>:   mov    %r12,%rdi
   0xffffffff80a236a2 <+546>:   mov    %rax,%rsi
   0xffffffff80a236a5 <+549>:   callq  0xffffffff80a66830 <sbuf_new>
   0xffffffff80a236aa <+554>:   mov    $0xffffffff81ccd6f0,%rdi
   0xffffffff80a236b1 <+561>:   xor    %esi,%esi
   0xffffffff80a236b3 <+563>:   mov    $0xffffffff813757c7,%rdx
   0xffffffff80a236ba <+570>:   mov    $0xc5d,%ecx
   0xffffffff80a236bf <+575>:   callq  0xffffffff80a27d00 <_sx_slock>
   0xffffffff80a236c4 <+580>:   mov    $0xffffffff,%ebx
   0xffffffff80a236c9 <+585>:   xor    %r14d,%r14d
   0xffffffff80a236cc <+588>:   xor    %r15d,%r15d
   0xffffffff80a236cf <+591>:   jmp    0xffffffff80a236fd <sigexit+637>
   0xffffffff80a236d1 <+593>:   data16 data16 data16 data16 data16 nopw %cs:0x0(
%rax,%rax,1)
   0xffffffff80a236e0 <+608>:   mov    $0x3,%edi
   0xffffffff80a236e5 <+613>:   mov    $0xffffffff81375c89,%rsi
   0xffffffff80a236ec <+620>:   mov    $0xffffffff8186d900,%rcx
   0xffffffff80a236f3 <+627>:   xor    %eax,%eax
   0xffffffff80a236f3 <+627>:   xor    %eax,%eax
   0xffffffff80a236f5 <+629>:   callq  0xffffffff80a61a20 <log>
   0xffffffff80a236fa <+634>:   inc    %r14d
   0xffffffff80a236fd <+637>:   movslq %r14d,%rax
   0xffffffff80a23700 <+640>:   movsbl -0x7e792700(%rax),%esi
   0xffffffff80a23707 <+647>:   cmp    $0x25,%esi
   0xffffffff80a2370a <+650>:   jne    0xffffffff80a2380f <sigexit+911>
   0xffffffff80a23710 <+656>:   inc    %r14d
   0xffffffff80a23713 <+659>:   movslq %r14d,%rax
   0xffffffff80a23716 <+662>:   movsbl -0x7e792700(%rax),%edx
   0xffffffff80a2371d <+669>:   lea    -0x48(%rdx),%eax
   0xffffffff80a23720 <+672>:   cmp    $0x8,%eax
   0xffffffff80a23723 <+675>:   jbe    0xffffffff80a23740 <sigexit+704>
   0xffffffff80a23725 <+677>:   cmp    $0x55,%edx
   0xffffffff80a23728 <+680>:   je     0xffffffff80a237ef <sigexit+879>
   0xffffffff80a2372e <+686>:   cmp    $0x25,%edx
   0xffffffff80a23731 <+689>:   jne    0xffffffff80a236e0 <sigexit+608>
   0xffffffff80a23733 <+691>:   mov    $0x25,%esi
   0xffffffff80a23738 <+696>:   jmpq   0xffffffff80a23814 <sigexit+916>
   0xffffffff80a2373d <+701>:   nopl   (%rax)
   0xffffffff80a23740 <+704>:   jmpq   *-0x7ec8a8b8(,%rax,8)
   0xffffffff80a23747 <+711>:   test   %r15,%r15
   0xffffffff80a2374a <+714>:   jne    0xffffffff80a23765 <sigexit+741>
   0xffffffff80a2374c <+716>:   mov    $0x100,%edi
   0xffffffff80a23751 <+721>:   mov    $0xffffffff818668a0,%rsi
   0xffffffff80a23758 <+728>:   mov    $0x2,%edx
   0xffffffff80a2375d <+733>:   callq  0xffffffff80a00680 <malloc>
   0xffffffff80a23762 <+738>:   mov    %rax,%r15
   0xffffffff80a23765 <+741>:   mov    -0x220(%rbp),%rax
   0xffffffff80a2376c <+748>:   mov    0x140(%rax),%rdi
   0xffffffff80a23773 <+755>:   mov    $0x100,%edx
   0xffffffff80a23778 <+760>:   mov    %r15,%rsi
   0xffffffff80a2377b <+763>:   callq  0xffffffff809f0ef0 <getcredhostname>
   0xffffffff80a23780 <+768>:   mov    $0xffffffff80fd8ad3,%rsi
   0xffffffff80a23787 <+775>:   xor    %eax,%eax
   0xffffffff80a23789 <+777>:   mov    %r12,%rdi
   0xffffffff80a2378c <+780>:   mov    %r15,%rdx
   0xffffffff80a2378f <+783>:   jmp    0xffffffff80a237d1 <sigexit+849>
   0xffffffff80a23791 <+785>:   mov    $0xffffffff81373ba2,%rsi
   0xffffffff80a23798 <+792>:   xor    %eax,%eax
   0xffffffff80a2379a <+794>:   mov    %r12,%rdi
   0xffffffff80a2379d <+797>:   callq  0xffffffff80a673e0 <sbuf_printf>
   0xffffffff80a237a2 <+802>:   mov    %r12,%rdi
   0xffffffff80a237a5 <+805>:   callq  0xffffffff80a67760 <sbuf_len>
   0xffffffff80a237aa <+810>:   mov    $0xfffff103,%ecx
   0xffffffff80a237af <+815>:   lea    0xefc(%rcx,%rax,1),%ebx
   0xffffffff80a237b6 <+822>:   inc    %r14d
   0xffffffff80a237b9 <+825>:   jmpq   0xffffffff80a236fd <sigexit+637>
   0xffffffff80a237be <+830>:   mov    $0xffffffff80fd8ad3,%rsi
   0xffffffff80a237c5 <+837>:   xor    %eax,%eax
   0xffffffff80a237c7 <+839>:   mov    %r12,%rdi
   0xffffffff80a237ca <+842>:   mov    -0x228(%rbp),%rdx
   0xffffffff80a237d1 <+849>:   callq  0xffffffff80a673e0 <sbuf_printf>
=> 0xffffffff80a237d6 <+854>:   inc    %r14d
   0xffffffff80a237d9 <+857>:   jmpq   0xffffffff80a236fd <sigexit+637>
   0xffffffff80a237de <+862>:   mov    $0xffffffff81361469,%rsi

Basically it's:
	lea    -0x138(%rbp),%r12
	[ snip ]
	mov     %r12,%rdi
	callq	sbuf_printf




Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201601202315.u0KNF687077387>