Re: bin/40314: ktruss(1) reports incorrect filename

[Nicolas Joly <njoly%pasteur.fr@localhost>]

On Thu, Jan 01, 2009 at 06:00:01PM +0000, tron%zhadum.org.uk@localhost wrote:
> >Number:         40314
> >Category:       bin
> >Synopsis:       ktruss(1) reports incorrect filename
> >Confidential:   no
> >Severity:       serious
> >Priority:       medium
> >Responsible:    bin-bug-people
> >State:          open
> >Class:          sw-bug
> >Submitter-Id:   net
> >Arrival-Date:   Thu Jan 01 18:00:00 +0000 2009
> >Originator:     Matthias Scheler
> >Release:        NetBSD 5.0_BETA 2008-12-28 sources
> >Organization:
> Matthias Scheler                                  http://zhadum.org.uk/
> >Environment:
> System: NetBSD colwyn.zhadum.org.uk 5.0_BETA NetBSD 5.0_BETA (COLWYN.64) #0: 
> Sun Dec 28 16:23:56 GMT 2008 
> tron%colwyn.zhadum.org.uk@localhost:/src/sys/compile/COLWYN.64 amd64
> Architecture: x86_64
> Machine: amd64
> >Description:
> "ktruss" reports bogus filenames in when decoding an open(2) system call:
> 
> ktruss cat /etc/hosts |& grep open
>  26998      1 cat      open("/libexec/ld.elf_so", 0, 0) Err#2 ENOENT
>  26998      1 cat      open("/etc/ld.so.conf", 0, 0xff31302d6e722d62) = 3
>  26998      1 cat      open("/lib/libc.so.12", 0, 0x1b6) = 3
>  26998      1 cat      open("/etc/malloc.conf", 0x4, 0) = 3
>  26998      1 cat      open("/usr/lib/i18n", 0, 0xfefefeff332d332d) = 3
>  26998      1 cat      open("/usr/lib/i18n/libUTF8.so.4.4", 0, 
> 0xfefefefefefefeff) Err#2 ENOENT
>  26998      1 cat      open("/usr/lib/i18n/libc.so.12", 0, 
> 0x31302d6dff31302d) = 3
>  26998      1 cat      open("/usr/lib/libc.so.12", 0, 0) = 3
> 
> The last open(2) actually opens "/etc/hosts". But it is not the only one
> which gets decoded incorrectly.

The problems comes when a syscall has more than one NAMI entry for a
single argument ... In your case, this is execve(2).

  4982      1 ktrace   CALL  
execve(0x7f7fffffd570,0x7f7fffffda70,0x7f7fffffda88)
  4982      1 ktrace   NAMI  "/bin/cat"
  4982      1 ktrace   NAMI  "/libexec/ld.elf_so"
  4982      1 cat      EMUL  "netbsd"
  4982      1 cat      RET   syscall JUSTRETURN

As a work around we can restore the flushpendq call from ktrsysret
function, which was disabled in rev 1.28 ... It will cleanup extra
remaining NAMI entries.


But this is not correct as we need to handle more complex cases with
binaries running under emulation (PR#39722), for example :

 20550      1 ktrace   CALL  
execve(0x7f7ffffffc8b,0x7f7fffffda80,0x7f7fffffda90)
 20550      1 ktrace   NAMI  "/home/njoly/emul/linux/syscalls/sys_link"
 20550      1 ktrace   NAMI  "/emul/linux"
 20550      1 ktrace   NAMI  "/emul/linux/lib64/ld-linux-x86-64.so.2"
 20550      1 sys_link EMUL  "linux"
 20550      1 sys_link RET   syscall -1 errno -2 No such file or directory
[...]
 20550      1 sys_link CALL  access(0x7f7ffde11450,4)
 20550      1 sys_link NAMI  "/emul/linux/etc/ld.so.preload"
 20550      1 sys_link NAMI  "/etc/ld.so.preload"
 20550      1 sys_link RET   access -1 errno -2 No such file or directory
[...]
 20550      1 sys_link CALL  open(0x7f7ffde131d8,0,1)
 20550      1 sys_link NAMI  "/emul/linux/etc/ld.so.cache"
 20550      1 sys_link RET   open 3
[...]
 20550      1 sys_link CALL  link(0x4007fc,0x400820)
 20550      1 sys_link NAMI  "link1.test"
 20550      1 sys_link NAMI  "link2.test"
 20550      1 sys_link RET   link 0
[...]
  5970      1 sys_link CALL  link(0x400880,0x400877)
  5970      1 sys_link NAMI  "/emul/linux/tmp/foo"
  5970      1 sys_link NAMI  "/tmp/foo"
  5970      1 sys_link NAMI  "/emul/linux/tmp/bar"
  5970      1 sys_link NAMI  "/tmp/bar"
  5970      1 sys_link RET   link 0

Not really sure how to properly fix it yet.

-- 
Nicolas Joly

Biological Software and Databanks.
Institut Pasteur, Paris.