From owner-freebsd-current@FreeBSD.ORG Thu Jun 18 09:43:23 2009 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id D7EB21065670; Thu, 18 Jun 2009 09:43:23 +0000 (UTC) (envelope-from serenity@exscape.org) Received: from ch-smtp01.sth.basefarm.net (ch-smtp01.sth.basefarm.net [80.76.149.212]) by mx1.freebsd.org (Postfix) with ESMTP id 634DA8FC14; Thu, 18 Jun 2009 09:43:23 +0000 (UTC) (envelope-from serenity@exscape.org) Received: from c83-253-252-234.bredband.comhem.se ([83.253.252.234]:50390 helo=mx.exscape.org) by ch-smtp01.sth.basefarm.net with esmtp (Exim 4.69) (envelope-from ) id 1MHE9E-0001ev-3E; Thu, 18 Jun 2009 11:43:10 +0200 Received: from [192.168.1.5] (macbookpro [192.168.1.5]) (using TLSv1 with cipher AES128-SHA (128/128 bits)) (No client certificate requested) by mx.exscape.org (Postfix) with ESMTPSA id 243326AD73; Thu, 18 Jun 2009 11:43:04 +0200 (CEST) Message-Id: From: Thomas Backman To: Wesley Shields In-Reply-To: <20090617225849.GB28509@atarininja.org> Content-Type: text/plain; charset=ISO-8859-1; format=flowed; delsp=yes Content-Transfer-Encoding: quoted-printable Mime-Version: 1.0 (Apple Message framework v935.3) Date: Thu, 18 Jun 2009 11:43:03 +0200 References: <949B5884-5303-4EFF-AC7D-293640FFA012@exscape.org> <0C235698-3ED2-4AE9-A7D1-5DC56D8324A4@exscape.org> <200905212129.47892.mel.flynn+fbsd.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> X-Mailer: Apple Mail (2.935.3) X-Originating-IP: 83.253.252.234 X-Scan-Result: No virus found in message 1MHE9E-0001ev-3E. X-Scan-Signature: ch-smtp01.sth.basefarm.net 1MHE9E-0001ev-3E 5cdb634c05b145d39d3ab2a49d867da8 Cc: freebsd-current@freebsd.org Subject: Re: DTrace panic while probing syscall::open (and possibly many others) X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 18 Jun 2009 09:43:24 -0000 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=