NetBSD Problem Report #43611

From Wolfgang.Stukenbrock@nagler-company.com  Tue Jul 13 12:34:03 2010
Return-Path: <Wolfgang.Stukenbrock@nagler-company.com>
Received: from mail.netbsd.org (mail.netbsd.org [204.152.190.11])
	by www.NetBSD.org (Postfix) with ESMTP id EF3E663BACE
	for <gnats-bugs@gnats.NetBSD.org>; Tue, 13 Jul 2010 12:34:02 +0000 (UTC)
Message-Id: <20100713123353.B94102E478F@s013.nagler-company.com>
Date: Tue, 13 Jul 2010 14:33:53 +0200 (CEST)
From: Wolfgang.Stukenbrock@nagler-company.com
Reply-To: Wolfgang.Stukenbrock@nagler-company.com
To: gnats-bugs@gnats.NetBSD.org
Subject: kernel-trace (via ktruss) reports wrong parameter/result values
X-Send-Pr-Version: 3.95

>Number:         43611
>Notify-List:    gson@gson.org
>Category:       kern
>Synopsis:       kernel-trace (via ktruss) reports wrong parameter/result values
>Confidential:   no
>Severity:       serious
>Priority:       high
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Tue Jul 13 12:35:00 +0000 2010
>Last-Modified:  Sat Jan 17 14:27:57 +0000 2015
>Originator:     W. Stukenbrock
>Release:        NetBSD 5.0.2
>Organization:
Dr. Nagler & Company GmbH

>Environment:


System: NetBSD s013 5.0.2 NetBSD 5.0.2 (NSW-S013) #2: Fri Jul 9 11:02:34 CEST 2010 root@s013:/usr/src/sys/arch/amd64/compile/NSW-S013 amd64
Architecture: x86_64
Machine: amd64
>Description:
	While debugging a tape-device problem we have traced the dd(1) command in order to validate the correct system calls.
	Accedently this was not possible due to the fact that "ktruss -T dd if=/dev/zero of=/dev/nrst1 bs=32k count=10" does not
	report all system calls and - even worse - reports wrong data for the open(2) call!
	We've added some printouts of the internal variables to the dd.c (e.g. the fd-numbers).
	The output of command above follows:

s013#  ktruss -T ./dd-tst if=/dev/zero of=$TAPE bs=32k count=20
in.fd = 3
out.fd = 5
io-buffer: in 0x7f7ffd801000 out 0x7f7ffd801000 - offsets 0/0
file-cnt loop ...
i-loop start cpy-cnt 20 in-full 0 in_part 0
 21158      1 ktruss   1279024020.645948480 emul(netbsd)
 21158      1 ktruss   1279024020.645947153 fktrace = 0
 21158      1 ktruss   1279024020.645956442 fcntl(0x4, 0x3, 0) = 1
 21158      1 ktruss   1279024020.645957978 fcntl(0x4, 0x4, 0x1) = 0
 21158      1 dd-tst   1279024020.646061899 emul(netbsd)
 21158      1 dd-tst   1279024020.646062877 execve("./dd-tst", 0x7f7fffffdc60, 0x7f7fffffdc90) JUSTRETURN
 21158      1 dd-tst   1279024020.646078730 mmap(0, 0x8000, 0x3, 0x1002, 0xffffffff, 0, 0) = 0x7f7ffdff8000
 21158      1 dd-tst   1279024020.646088787 open("/usr/libexec/ld.elf_so", 0, 0) Err#2 ENOENT
 21158      1 dd-tst   1279024020.646107644 open("/etc/ld.so.conf", 0, 0xfefeff362d6e722d) = 3
 21158      1 dd-tst   1279024020.646109460 __fstat30(0x3, 0x7f7fffffd3c0) = 0
 21158      1 dd-tst   1279024020.646112812 mmap(0, 0x1000, 0x1, 0x1, 0x3, 0, 0) = 0x7f7ffdff7000
 21158      1 dd-tst   1279024020.646117771 munmap(0x7f7ffdff7000, 0x1000) = 0
 21158      1 dd-tst   1279024020.646120285 mmap(0, 0x116000, 0x5, 0x14000002, 0x3, 0, 0) = 0x7f7ffdc00000
 21158      1 dd-tst   1279024020.646123707 mmap(0x7f7ffdd12000, 0x2000, 0x3, 0x12, 0x3, 0, 0x12000) = 0x7f7ffdd12000
 21158      1 dd-tst   1279024020.646126012 mmap(0x7f7ffdd14000, 0x2000, 0x3, 0x1012, 0xffffffff, 0, 0) = 0x7f7ffdd14000
 21158      1 dd-tst   1279024020.646128037 mprotect(0x7f7ffdc12000, 0x100000, 0) = 0
 21158      1 dd-tst   1279024020.646136976 close(0x3) = 0
 21158      1 dd-tst   1279024020.646154716 open("/usr/lib/libutil.so.7", 0, 0xfefeff35ff31302d) = 3
 21158      1 dd-tst   1279024020.646156950 __fstat30(0x3, 0x7f7fffffd3c0) = 0
 21158      1 dd-tst   1279024020.646160023 mmap(0, 0x1000, 0x1, 0x1, 0x3, 0, 0) = 0x7f7ffdff7000
 21158      1 dd-tst   1279024020.646164353 munmap(0x7f7ffdff7000, 0x1000) = 0
 21158      1 dd-tst   1279024020.646167007 mmap(0, 0x218000, 0x5, 0x14000002, 0x3, 0, 0) = 0x7f7ffd900000
 21158      1 dd-tst   1279024020.646170569 mmap(0x7f7ffdafa000, 0xc000, 0x3, 0x12, 0x3, 0, 0xfa000) = 0x7f7ffdafa000
 21158      1 dd-tst   1279024020.646172804 mmap(0x7f7ffdb06000, 0x12000, 0x3, 0x1012, 0xffffffff, 0, 0) = 0x7f7ffdb06000
 21158      1 dd-tst   1279024020.646175248 mprotect(0x7f7ffd9fa000, 0x100000, 0) = 0
 21158      1 dd-tst   1279024020.646183769 close(0x3) = 0
 21158      1 dd-tst   1279024020.646201019 open("/usr/lib/libc.so.12", 0, 0xff31302d6e722d62) = 3
 21158      1 dd-tst   1279024020.646203044 __fstat30(0x3, 0x7f7fffffd3c0) = 0
 21158      1 dd-tst   1279024020.646204651 close(0x3) = 0
 21158      1 dd-tst   1279024020.646396150 __sysctl(0x7f7fffffdb50, 0x2, 0x7f7ffdb159c0, 0x7f7fffffdb48, 0, 0) = 0
 21158      1 dd-tst   1279024020.646429882 issetugid() = 0
 21158      1 dd-tst   1279024020.646472065 open("/lib/libc.so.12", 0, 0) = 3
 21158      1 dd-tst   1279024020.646496579 write(0x2, 0x7f7fffffd290, 0xa) = 10
       "in.fd = 3\n"
 21158      1 dd-tst   1279024020.646499791 __fstat30(0x3, 0x7f7fffffdaf0) = 0
 21158      1 dd-tst   1279024020.646502166 ioctl(0x3, MTIOCGET, 0x7f7fffffdb80) Err#45 EOPNOTSUPP
 21158      1 dd-tst   1279024020.652129884 open("/dev/zero", 0x602, 0x1b6) = 5
 21158      1 dd-tst   1279024020.652135820 write(0x2, 0x7f7fffffd290, 0xb) = 11
       "out.fd = 5\n"
 21158      1 dd-tst   1279024020.652138544 __fstat30(0x5, 0x7f7fffffdaf0) = 0
 21158      1 dd-tst   1279024020.655394311 ioctl(0x5, MTIOCGET, 0x7f7fffffdb80) = 0
       "\a\0\^C\0\0\0\0\0\0\0\0\0\r\0\0\0\0\0\0\0\M^B\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.655398920 __sysctl(0x7f7fffffd730, 0x2, 0x7f7ffdb0e090, 0x7f7fffffd728, 0, 0) = 0
 21158      1 dd-tst   1279024020.655409466 __sysctl(0x7f7fffffd650, 0x2, 0x7f7ffdb15e40, 0x7f7fffffd648, 0, 0) = 0
 21158      1 dd-tst   1279024020.655414704 readlink("/dev/nrst1", 0x7f7fffffd740, 0x400) Err#2 ENOENT
 21158      1 dd-tst   1279024020.655420989 mmap(0, 0x1000, 0x3, 0x1002, 0xffffffff, 0, 0) = 0x7f7ffdff7000
 21158      1 dd-tst   1279024020.655440894 mmap(0, 0x1000, 0x3, 0x1002, 0xffffffff, 0, 0) = 0x7f7ffdff6000
 21158      1 dd-tst   1279024020.655455420 mmap(0, 0x100000, 0x3, 0x14001002, 0xffffffff, 0, 0) = 0x7f7ffd800000
 21158      1 dd-tst   1279024020.655469528 write(0x2, 0x7f7fffffd290, 0x3e) = 62
       "io-buffer: in 0x7f7ffd801000 out 0x7f7ffd801000 - offsets 0/0\n"
 21158      1 dd-tst   1279024020.655473648 gettimeofday(0x505820, 0) = 0
 21158      1 dd-tst   1279024020.655478258 __sigaction_sigtramp(0x1d, 0x7f7fffffdbd0, 0x7f7fffffdbb0, 0x7f7ffd981710, 0x2) = 0
 21158      1 dd-tst   1279024020.655481261 __sigaction_sigtramp(0x2, 0x7f7fffffdbd0, 0x7f7fffffdbb0, 0x7f7ffd981710, 0x2) = 0
 21158      1 dd-tst   1279024020.655506054 write(0x2, 0x404779, 0x12) = 18
       "file-cnt loop ...\n"
 21158      1 dd-tst   1279024020.655511222 write(0x2, 0x7f7fffffd2a0, 0x2c) = 44
       "i-loop start cpy-cnt 20 in-full 0 in_part 0\n"
i-loop read on 3 - req 32768 - result 32768
calling dd_out(1) ...
write on 5 - req 32768 - res 0
dd-tst: /dev/nrst1: end of device
1+0 records in
0+0 records out
0 bytes transferred in 0.004 secs (0 bytes/sec)
 21158      1 dd-tst   1279024020.655587975 read(0x3, 0x7f7ffd801000, 0x8000) = 32768
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.655994021 write(0x2, 0x7f7fffffd2a0, 0x2c) = 44
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.655997024 write(0x2, 0x4048b0, 0x16) = 22
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.656000306 __sigprocmask14(0x1, 0x5057b0, 0x7f7fffffdb50) = 0
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.659109690 write(0x5, 0x7f7ffd801000, 0x8000) = 0
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.659116185 write(0x2, 0x7f7fffffd1f0, 0x1f) = 31
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.659118979 __sigprocmask14(0x3, 0x7f7fffffdb50, 0) = 0
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.659138604 write(0x2, 0x7f7fffffd130, 0x8) = 8
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.659143143 write(0x2, 0x7f7fffffd210, 0x19) = 25
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
 21158      1 dd-tst   1279024020.659155505 write(0x2, 0x505517, 0x1) = 1
       "i-loop read on 3 - req 32768 - result 32768\n"
 21158      1 dd-tst   1279024020.659159206 gettimeofday(0x7f7fffffd980, 0) = 0
       "calling dd_out(1) ...\n"
 21158      1 dd-tst   1279024020.659166679 write(0x2, 0x7f7fffffd990, 0x1f) = 31
       ""
 21158      1 dd-tst   1279024020.659172755 write(0x2, 0x7f7fffffd990, 0x30) = 48
       "write on 5 - req 32768 - res 0\n"
 21158      1 dd-tst   1279024020.659177085 exit(0x1)
s013# 

	Our prints addedto dd reports that fd = 3 is the input and fd = 5 is the output.
	This corresponds to the read(2) and write(2) calles done later.
	But ktruss reports ' 21158      1 dd-tst   1279024020.652129884 open("/dev/zero", 0x602, 0x1b6) = 5', and that is
	simply nonsence!
	The call to open("/dev/zero", ...) has returned 3 as stated by our print outs and due to the fact that read(2) is done from 3
	and the open("/dev/nrst1", ...) that is missing in the output has returned 5.
	It looks like the ktruss command has combined theese two calls to open into one line of output.

>How-To-Repeat:
	e.g. try to trace the dd command - at least on our machine the problem is reproducable.
>Fix:
	not known up to now - sorry

>Release-Note:

>Audit-Trail:
From: David Laight <david@l8s.co.uk>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
Date: Tue, 13 Jul 2010 18:40:14 +0100

 On Tue, Jul 13, 2010 at 12:35:00PM +0000, Wolfgang.Stukenbrock@nagler-company.com wrote:
 > >Synopsis:       kernel-trace (via ktruss) reports wrong parameter/result values
 ...
 > 	While debugging a tape-device problem we have traced the dd(1) command in order to validate the correct system calls.

 ktrace+kdump tends to work much better than ktruss.

 ktruss tries to convert the ktrace data to system call parameters and
 fails when the data is unexpected (due to extra traces).

 ktruss probably should be rewritten to use system call entry/exit
 breakpoints and then userspace controlled reads of the traced programs
 memory (which is how truss works on SYSV).

 	David

 -- 
 David Laight: david@l8s.co.uk

From: christos@zoulas.com (Christos Zoulas)
To: gnats-bugs@NetBSD.org, kern-bug-people@netbsd.org, 
	gnats-admin@netbsd.org, netbsd-bugs@netbsd.org, 
	Wolfgang.Stukenbrock@nagler-company.com
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
Date: Tue, 13 Jul 2010 13:42:06 -0400

 On Jul 13,  5:40pm, david@l8s.co.uk (David Laight) wrote:
 -- Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter

 | The following reply was made to PR kern/43611; it has been noted by GNATS.
 | 
 | From: David Laight <david@l8s.co.uk>
 | To: gnats-bugs@NetBSD.org
 | Cc: 
 | Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
 | Date: Tue, 13 Jul 2010 18:40:14 +0100
 | 
 |  On Tue, Jul 13, 2010 at 12:35:00PM +0000, Wolfgang.Stukenbrock@nagler-company.com wrote:
 |  > >Synopsis:       kernel-trace (via ktruss) reports wrong parameter/result values
 |  ...
 |  > 	While debugging a tape-device problem we have traced the dd(1) command in order to validate the correct system calls.
 |  
 |  ktrace+kdump tends to work much better than ktruss.
 |  
 |  ktruss tries to convert the ktrace data to system call parameters and
 |  fails when the data is unexpected (due to extra traces).
 |  
 |  ktruss probably should be rewritten to use system call entry/exit
 |  breakpoints and then userspace controlled reads of the traced programs
 |  memory (which is how truss works on SYSV).

 Well, this is PT_SYSCALL and /usr/pkg/bin/strace :-)

 christos

From: David Holland <dholland-bugs@netbsd.org>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong
 parameter/result values
Date: Wed, 14 Jul 2010 01:45:23 +0000

 On Tue, Jul 13, 2010 at 05:40:04PM +0000, David Laight wrote:
  >  ktruss probably should be rewritten to use system call entry/exit
  >  breakpoints and then userspace controlled reads of the traced programs
  >  memory (which is how truss works on SYSV).

 Using ptrace for this purpose is not desirable because it monkeys with
 the parent/child process relationships and tends to break things,
 particularly shell scripts.

 (I'm not particularly clear on exactly what ktruss does that's
 different from running kdump afterwards, but then I've never been
 particularly clear on why ktruss is desirable relative to running
 kdump afterwards, either.)

 -- 
 David A. Holland
 dholland@netbsd.org

From: christos@zoulas.com (Christos Zoulas)
To: gnats-bugs@NetBSD.org, kern-bug-people@netbsd.org, 
	gnats-admin@netbsd.org, netbsd-bugs@netbsd.org, 
	Wolfgang.Stukenbrock@nagler-company.com
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
Date: Wed, 14 Jul 2010 08:36:07 -0400

 On Jul 14,  1:50am, dholland-bugs@netbsd.org (David Holland) wrote:
 -- Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter

 |  On Tue, Jul 13, 2010 at 05:40:04PM +0000, David Laight wrote:
 |   >  ktruss probably should be rewritten to use system call entry/exit
 |   >  breakpoints and then userspace controlled reads of the traced programs
 |   >  memory (which is how truss works on SYSV).
 |  
 |  Using ptrace for this purpose is not desirable because it monkeys with
 |  the parent/child process relationships and tends to break things,
 |  particularly shell scripts.

 It is desirable because it stops the process and lets you examine the
 syscall arguments in detail.

 |  (I'm not particularly clear on exactly what ktruss does that's
 |  different from running kdump afterwards, but then I've never been
 |  particularly clear on why ktruss is desirable relative to running
 |  kdump afterwards, either.)

 Interactivity; you can watch processes that stop and wait for events
 and see what they do as you supply the different events.

 christos

From: David Laight <david@l8s.co.uk>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
Date: Wed, 14 Jul 2010 22:18:51 +0100

 On Wed, Jul 14, 2010 at 12:40:03PM +0000, Christos Zoulas wrote:
 >  On Jul 14,  1:50am, dholland-bugs@netbsd.org (David Holland) wrote:
 >  |  On Tue, Jul 13, 2010 at 05:40:04PM +0000, David Laight wrote:
 >  |   >  ktruss probably should be rewritten to use system call entry/exit
 >  |   >  breakpoints and then userspace controlled reads of the traced programs
 >  |   >  memory (which is how truss works on SYSV).
 >  |  
 >  |  Using ptrace for this purpose is not desirable because it monkeys with
 >  |  the parent/child process relationships and tends to break things,
 >  |  particularly shell scripts.
 >  
 >  It is desirable because it stops the process and lets you examine the
 >  syscall arguments in detail.

 Actually the systrace code would have let you do this, except that
 someone decided to use to try to implement security not tracing.
 IIRC that didn't mess with lineage of processes.

 	David

 -- 
 David Laight: david@l8s.co.uk

From: David Holland <dholland-bugs@netbsd.org>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong
 parameter/result values
Date: Thu, 15 Jul 2010 20:13:45 +0000

 On Wed, Jul 14, 2010 at 12:40:03PM +0000, Christos Zoulas wrote:
  >|>  ktruss probably should be rewritten to use system call entry/exit
  >|>  breakpoints and then userspace controlled reads of the traced programs
  >|>  memory (which is how truss works on SYSV).
  >|  
  >|  Using ptrace for this purpose is not desirable because it monkeys with
  >|  the parent/child process relationships and tends to break things,
  >|  particularly shell scripts.
  >  
  >  It is desirable because it stops the process and lets you examine the
  >  syscall arguments in detail.

 Mm, point. Maybe we ought to invent a new kind of tracing for this
 purpose (since supervised execution was trendy in research for a while
 and it's getting to the point of moving to production...)

 I'm not sure if it makes sense for that to be different from a
 debugger interface or not.

  >  |  (I'm not particularly clear on exactly what ktruss does that's
  >  |  different from running kdump afterwards, but then I've never been
  >  |  particularly clear on why ktruss is desirable relative to running
  >  |  kdump afterwards, either.)
  >  
  >  Interactivity; you can watch processes that stop and wait for events
  >  and see what they do as you supply the different events.

 Ah. Yeah, I guess that can be useful. The main problem I've always had
 with strace and truss and whatnot is that the trace output gets mixed
 with the program's output; when I first found ktrace years ago it was
 a big step forward.

 -- 
 David A. Holland
 dholland@netbsd.org

From: christos@zoulas.com (Christos Zoulas)
To: gnats-bugs@NetBSD.org, kern-bug-people@netbsd.org, 
	gnats-admin@netbsd.org, netbsd-bugs@netbsd.org, 
	Wolfgang.Stukenbrock@nagler-company.com
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
Date: Thu, 15 Jul 2010 17:57:18 -0400

 On Jul 15,  8:15pm, dholland-bugs@netbsd.org (David Holland) wrote:
 -- Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter

 |  Mm, point. Maybe we ought to invent a new kind of tracing for this
 |  purpose (since supervised execution was trendy in research for a while
 |  and it's getting to the point of moving to production...)
 |  
 |  I'm not sure if it makes sense for that to be different from a
 |  debugger interface or not.

 We already support PT_SYSCALL, although it might be broken in current.
 |  
 |   >  |  (I'm not particularly clear on exactly what ktruss does that's
 |   >  |  different from running kdump afterwards, but then I've never been
 |   >  |  particularly clear on why ktruss is desirable relative to running
 |   >  |  kdump afterwards, either.)
 |   >  
 |   >  Interactivity; you can watch processes that stop and wait for events
 |   >  and see what they do as you supply the different events.
 |  
 |  Ah. Yeah, I guess that can be useful. The main problem I've always had
 |  with strace and truss and whatnot is that the trace output gets mixed
 |  with the program's output; when I first found ktrace years ago it was
 |  a big step forward.

 For that you can use -o fname and tail -f fname in another pty.

 christos

From: David Holland <dholland-bugs@netbsd.org>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong
 parameter/result values
Date: Thu, 15 Jul 2010 23:17:17 +0000

 On Thu, Jul 15, 2010 at 10:00:07PM +0000, Christos Zoulas wrote:
  >  |  Mm, point. Maybe we ought to invent a new kind of tracing for this
  >  |  purpose (since supervised execution was trendy in research for a while
  >  |  and it's getting to the point of moving to production...)
  >  |  
  >  |  I'm not sure if it makes sense for that to be different from a
  >  |  debugger interface or not.
  >  
  >  We already support PT_SYSCALL, although it might be broken in current.

 Well, a new kind of tracing that doesn't get entangled with wait() and
 mess up parent process ids.

  >  |  Ah. Yeah, I guess that can be useful. The main problem I've always had
  >  |  with strace and truss and whatnot is that the trace output gets mixed
  >  |  with the program's output; when I first found ktrace years ago it was
  >  |  a big step forward.
  >  
  >  For that you can use -o fname and tail -f fname in another pty.

 I have no idea why I didn't do that at the time, but it was a long
 time ago and may have involved HPUX.

 -- 
 David A. Holland
 dholland@netbsd.org

From: matthew sporleder <msporleder@gmail.com>
To: gnats-bugs@netbsd.org, gnats-admin@netbsd.org
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong
 parameter/result values
Date: Wed, 3 Aug 2011 20:49:40 -0400

 See how ktruss claims to open /usr/local/lib/libm but kdump
 (correctly) reports "No such file or directory".

 NetBSD vc136-15.vc.panix.com 5.1 NetBSD 5.1 (PANIX-VC) #0: Thu Mar 10
 01:49:14 EST 2011
 root@juggler.panix.com:/misc/obj/misc/devel/netbsd/5.1/src/sys/arch/amd64/compile/PANIX-VC
 amd64

 ktrace/kdump - correct:

  22799      1 perl     NAMI  "/etc/ld.so.conf"
  22799      1 perl     RET   open -1 errno 2 No such file or directory
  22799      1 perl     CALL  open(0x7f7fffffcfb0,0,0xfeff2f2d6e722d6c)
  22799      1 perl     NAMI  "/usr/pkg/lib/libm.so.0"
  22799      1 perl     RET   open -1 errno 2 No such file or directory
  22799      1 perl     CALL  open(0x7f7fffffcfb0,0,0xfefefefefefefeff)
  22799      1 perl     NAMI  "/usr/local/lib/libm.so.0"
  22799      1 perl     RET   open -1 errno 2 No such file or directory
  22799      1 perl     CALL  open(0x7f7fffffcfb0,0,0x2f2d6e722cff2f2d)
  22799      1 perl     NAMI  "/usr/lib/libm.so.0"
  22799      1 perl     RET   open 3


 ktruss - incorrect:

  11347      1 perl     open("/usr/libexec/ld.elf_so", 0, 0) Err#2 ENOENT
  11347      1 perl     open("/etc/ld.so.conf", 0, 0xfeff2f2d6e722d6c)
 Err#2 ENOENT
  11347      1 perl     open("/usr/pkg/lib/libm.so.0", 0,
 0xfefefefefefefeff) Err#2 ENOENT
  11347      1 perl     open("/usr/local/lib/libm.so.0", 0,
 0x2f2d6e722cff2f2d) = 3
  11347      1 perl     __fstat30(0x3, 0x7f7fffffcee0) = 0
  11347      1 perl     mmap(0, 0x1000, 0x1, 0x1, 0x3, 0, 0) = 0x7f7ffdff7000
  11347      1 perl     munmap(0x7f7ffdff7000, 0x1000) = 0
  11347      1 perl     mmap(0, 0x11c000, 0x5, 0x14000002, 0x3, 0, 0) =
 0x7f7ffdc00000
  11347      1 perl     mmap(0x7f7ffdd1b000, 0x1000, 0x3, 0x12, 0x3, 0,
 0x1b000) = 0x7f7ffdd1b000
  11347      1 perl     mmap(0x7f7ffdd1c000, 0, 0x3, 0x1012,
 0xffffffff, 0, 0) = 0x7f7ffdd1c000
  11347      1 perl     mprotect(0x7f7ffdc1b000, 0x100000, 0) = 0
  11347      1 perl     close(0x3)                  = 0
  11347      1 perl     open("/usr/lib/libm.so.0", 0,
 0xfefefefefeff2f2d) Err#2 ENOENT

From: Andreas Gustafsson <gson@gson.org>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
Date: Wed, 10 Aug 2011 23:03:30 +0300

 I also ran into problems with ktruss recently, on NetBSD 5.0.1/i386.
 For example, an open() system call which ktrace + kdump reported like
 this:

  15159      1 testprog CALL  open(0xbb80208c,0,0xbfbfe7e8)
  15159      1 testprog NAMI  "/dev/rwd0a"
  15159      1 testprog RET   open 3

 ktruss reported like this:

  11230      1 testprog open("/etc/malloc.conf", 0, 0xbfbfe7e8) = 3

 Note how the argument "/dev/rwd0a" has turned into "/etc/malloc.conf".
 -- 
 Andreas Gustafsson, gson@gson.org

>Unformatted:

Home	PR Database Search