Date: Thu, 18 Jun 2009 11:43:03 +0200 From: Thomas Backman <serenity@exscape.org> To: Wesley Shields <wxs@FreeBSD.org> Cc: freebsd-current@freebsd.org Subject: Re: DTrace panic while probing syscall::open (and possibly many others) Message-ID: <B2F32C8F-810B-4EA5-9E34-39ADD5E5CED4@exscape.org> In-Reply-To: <20090617225849.GB28509@atarininja.org> References: <949B5884-5303-4EFF-AC7D-293640FFA012@exscape.org> <0C235698-3ED2-4AE9-A7D1-5DC56D8324A4@exscape.org> <200905212129.47892.mel.flynn%2Bfbsd.current@mailing.thruhere.net> <44F486FA-E798-448D-BE31-F7A51EF1F612@exscape.org> <60173AF0-7E54-4BDD-8927-0DADA9DAD1B4@exscape.org> <20090522200306.GE2630@atarininja.org> <20090617225849.GB28509@atarininja.org>
next in thread | previous in thread | raw e-mail | index | archive | help
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: =20
>>>> syscall::open:entry):
>>>> invalid address (0xffffff803e9afae0) in action #1 at DIF offset 28
>>>> dtrace: error on enabled probe ID 1 (ID 38977: =20
>>>> syscall::open:entry):
>>>> invalid address (0xffffff803e9afae0) in action #1 at DIF offset 28
>>>> dtrace: error on enabled probe ID 1 (ID 38977: =20
>>>> syscall::open:entry):
>>>> invalid address (0xffffff803e9afae0) in action #1 at DIF offset 28
>>>>
>>>
>>> Actually, I still get these. Bummer.
>>>
>>> [root@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 =20
>>> 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 =20
>> that is
>> broken in the same fashion. I just installed a 7.1 VM and tried it =20=
>> 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: =20=
Thu Jun 18 10:44:21 CEST 2009 root@chaos.exscape.org:/usr/obj/usr/=20=
src/sys/DTRACE amd64
I removed my funny printf-before-ASSERT hack, updated to the latest =20
revision and built it, then ran:
dtrace -n 'syscall::open:entry { self->path =3D arg0; } =20
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=3DVariable "format" is =20=
not available.
)
at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/=20
opensolaris/uts/common/dtrace/dtrace.c:600
#12 0xffffffff816b309d in dtrace_assfail (
a=3D0xffffffff816d4b88 "kaddr >=3D kernelbase && kaddr + size >=3D =20=
kaddr",
f=3D0xffffff803e770370 "=C0=E0F\201=FF=FF=FF=FF=C0=E0F\201=FF=FF=FF=FF=
0\005w>\200=FF=FF=FF=C7=E0=20
\206\200=FF=FF=FF=FFWD\210\200=FF=FF=FF=FF`&t~", l=3DVariable "l" is not =
available.
)
at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/=20
opensolaris/uts/common/dtrace/dtrace.c:607
#13 0xffffffff816b3140 in dtrace_copycheck (uaddr=3D34365163021, =20
kaddr=3DVariable "kaddr" is not available.
)
at dtrace_isa.c:527
#14 0xffffffff816b31fc in dtrace_copyinstr (uaddr=3D34365163021,
kaddr=3D18446743524025463312, size=3D256, flags=3D0xffffffff8146e0c0)=
at dtrace_isa.c:558
#15 0xffffffff816c10f1 in dtrace_dif_emulate (difo=3D0xffffffff80884457,
mstate=3D0xffffff803e770a10, vstate=3D0xffffff0002930c38,
state=3D0xffffff0002930c00)
at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/=20
opensolaris/uts/common/dtrace/dtrace.c:3452
#16 0xffffffff816c233a in dtrace_probe (id=3DVariable "id" is not =20
available.
)
at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/=20
opensolaris/uts/common/dtrace/dtrace.c:6226
#17 0xffffffff817f2145 in systrace_probe () from /boot/kernel/=20
systrace.ko
#18 0xffffffff80887c7d in syscall (frame=3D0xffffff803e770c90)
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=
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?B2F32C8F-810B-4EA5-9E34-39ADD5E5CED4>