kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values

To: kern-bug-people%netbsd.org@localhost,gnats-admin%netbsd.org@localhost,netbsd-bugs%netbsd.org@localhost
Subject: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
From: Wolfgang.Stukenbrock%nagler-company.com@localhost
Date: Tue, 13 Jul 2010 12:35:00 +0000 (UTC)
>Number:         43611
>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
>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

>Unformatted:
Prev by Date: PR/43605 CVS commit: src/tests/fs/vfs
Next by Date: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
Previous by Thread: PR/43605 CVS commit: src/tests/fs/vfs
Next by Thread: Re: kern/43611: kernel-trace (via ktruss) reports wrong parameter/result values
Indexes:
Home | Main Index | Thread Index | Old Index