Re: DTrace panic while probing syscall::open (and possibly many others)

On Jun 18, 2009, at 12:58 AM, Wesley Shields wrote:

> On Fri, May 22, 2009 at 04:03:06PM -0400, Wesley Shields wrote:
>> On Fri, May 22, 2009 at 10:00:56AM +0200, Thomas Backman wrote:
>>> On May 22, 2009, at 09:31 AM, Thomas Backman wrote:
>>>>
>>>> ...
>>>> dtrace: error on enabled probe ID 1 (ID 38977:  
>>>> syscall::open:entry):
>>>> invalid address (0xffffff803e9afae0) in action #1 at DIF offset 28
>>>> dtrace: error on enabled probe ID 1 (ID 38977:  
>>>> syscall::open:entry):
>>>> invalid address (0xffffff803e9afae0) in action #1 at DIF offset 28
>>>> dtrace: error on enabled probe ID 1 (ID 38977:  
>>>> syscall::open:entry):
>>>> invalid address (0xffffff803e9afae0) in action #1 at DIF offset 28
>>>>
>>>
>>> Actually, I still get these. Bummer.
>>>
>>> [root_at_chaos /usr/local/sbin]# execsnoop
>>>   UID    PID   PPID ARGS
>>>     0   1931   1924 /bin/sh
>>>     0   1931   1924 /bin/sh
>>>     0   1932   1931 /bin/mkdir
>>>     0   1932   1931 /bin/mkdir
>>> dtrace: error on enabled probe ID 2 (ID 39086:
>>> syscall::execve:return): invalid address (0xffffff803e8cfae0) in
>>> action #8
>>> dtrace: error on enabled probe ID 3 (ID 39086:
>>> syscall::execve:return): invalid address (0xffffff803e8cfae0) in
>>> action #8
>>>     0   1944   1933 mktemp
>>>     0   1944   1933 mktemp
>>> dtrace: error on enabled probe ID 2 (ID 39086:
>>> syscall::execve:return): invalid address (0xffffff803ea58ae0) in
>>> action #8
>>> dtrace: error on enabled probe ID 3 (ID 39086:
>>> syscall::execve:return): invalid address (0xffffff803ea58ae0) in
>>> action #8
>>> dtrace: error on enabled probe ID 2 (ID 39086:
>>> syscall::execve:return): invalid address (0xffffff803ea9eae0) in
>>> action #8
>>> dtrace: error on enabled probe ID 3 (ID 39086:
>>> syscall::execve:return): invalid address (0xffffff803ea9eae0) in
>>> action #8
>>>     0   1948   1947 /bin/sh
>>>     0   1948   1947 /bin/sh
>>>     0   1949   1948 vnstat
>>>     0   1949   1948 vnstat
>>>     0   1950   1933 /bin/rm
>>>     0   1950   1933 /bin/rm
>>>     0   1951   1907 /bin/sh
>>>     0   1951   1907 /bin/sh
>>>     0   1952   1951 make
>>>     0   1952   1951 make
>>>
>>> (No idea why everything is printed twice either.)
>>> Also, the DTrace variable "walltimestamp" seems to return "1970  
>>> Jan  1
>>> 01:00:00" (I'm in GMT+2 right now, btw) every time.
>>
>> This leads me to believe it's a race somewhere.
>>
>> Another datapoint: whatever was changed also made it into 7.2 as  
>> that is
>> broken in the same fashion. I just installed a 7.1 VM and tried it  
>> there
>> and it works.
>
> I just updated a -current machine to r194361 and the race condition is
> still there but not triggered as often, and it no longer leads to a
> panic. I still get occasional output like what is listed above but no
> panic.
>
> -- WXS
No luck here. :(

FreeBSD chaos.exscape.org 8.0-CURRENT FreeBSD 8.0-CURRENT #8 r194428:  
Thu Jun 18 10:44:21 CEST 2009     root_at_chaos.exscape.org:/usr/obj/usr/ 
src/sys/DTRACE  amd64

I removed my funny printf-before-ASSERT hack, updated to the latest  
revision and built it, then ran:
dtrace -n 'syscall::open:entry { self->path = arg0; }  
syscall::open:return { printf("%s\n", copyinstr(self->path)); }'
again, same crash.

dtrace_copycheck() seeems to be the culprit yet again, as expected.
I guess I'll have to add back the printf hack, heh.

#10 0xffffffff816c9140 in vpanic_common () from /boot/kernel/dtrace.ko
#11 0xffffffff816b3067 in dtrace_panic (format=Variable "format" is  
not available.
)
     at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/ 
opensolaris/uts/common/dtrace/dtrace.c:600
#12 0xffffffff816b309d in dtrace_assfail (
     a=0xffffffff816d4b88 "kaddr >= kernelbase && kaddr + size >=  
kaddr",
     f=0xffffff803e770370 "ÀàF\201ÿÿÿÿÀàF\201ÿÿÿÿ0\005w>\200ÿÿÿÇà 
\206\200ÿÿÿÿWD\210\200ÿÿÿÿ`&t~", l=Variable "l" is not available.
)
     at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/ 
opensolaris/uts/common/dtrace/dtrace.c:607
#13 0xffffffff816b3140 in dtrace_copycheck (uaddr=34365163021,  
kaddr=Variable "kaddr" is not available.
)
     at dtrace_isa.c:527
#14 0xffffffff816b31fc in dtrace_copyinstr (uaddr=34365163021,
     kaddr=18446743524025463312, size=256, flags=0xffffffff8146e0c0)
     at dtrace_isa.c:558
#15 0xffffffff816c10f1 in dtrace_dif_emulate (difo=0xffffffff80884457,
     mstate=0xffffff803e770a10, vstate=0xffffff0002930c38,
     state=0xffffff0002930c00)
     at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/ 
opensolaris/uts/common/dtrace/dtrace.c:3452
#16 0xffffffff816c233a in dtrace_probe (id=Variable "id" is not  
available.
)
     at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/ 
opensolaris/uts/common/dtrace/dtrace.c:6226
#17 0xffffffff817f2145 in systrace_probe () from /boot/kernel/ 
systrace.ko
#18 0xffffffff80887c7d in syscall (frame=0xffffff803e770c90)
     at /usr/src/sys/amd64/amd64/trap.c:997
#19 0xffffffff8086e350 in Xfast_syscall ()
     at /usr/src/sys/amd64/amd64/exception.S:364
#20 0x000000080050c3ac in ?? ()
Previous frame inner to this frame (corrupt stack?)

Regards,
Thomas