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

[Wesley Shields]

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