Re: linux syslog problems (now linux-2.2.1+glibc-2.0.112)

[John Kennedy <jk@csuchico.edu>]

[Zack Weinberg]
>  Please do `strace -p 1117' which will reveal the system call
>  arguments.  While strace is still running, send process 1117 a
>  non-lethal signal (SIGHUP probably works) - that will hopefully
>  cause the send() to return EINTR.  Then watch the system call trace
>  until it gets stuck again, loops, or exits, and send us the output.

  Doing a strace got me this (just leaving it run until it croaked):

	time([917975878])                       = 917975878
	recvfrom(7, "\1\1\6\1\262\334sF\0\1\0\0\0\0\0"..., 1540, 0, {sin_family=AF_INET, sin_port=htons(68), sin_addr=inet_addr("132.241.200.1")}, [16]) = 548
	read(8, "\0`\227\337I\25\0`/q\372@\10\0E\0"..., 1500) = 590
	time([917975878])                       = 917975878
	SYS_174(0xd, 0xbfffdfd0, 0xbfffdf44, 0x8, 0xd) = 0
	send(3, "<30>Feb  2 09:17:58 dhcpd: DHCPR"..., 100, 0) = 100
	SYS_174(0xd, 0xbfffdfd0, 0, 0x8, 0xd)   = 0
	time([917975878])                       = 917975878
	SYS_174(0xd, 0xbffff2b4, 0xbffff228, 0x8, 0xd) = 0
	send(3, "<30>Feb  2 09:17:58 dhcpd: DHCPO"..., 93, 0 <unfinished ...>

  Can't strace and gdb at the same time, so I killed strace and ran
gdb.  This is dhcpd-2.0b1pl8 staticly linked against glibc-2.0.112 now:

	#0  0x806d212 in __libc_send ()
	#1  0x806cc08 in vsyslog (pri=6, fmt=0x9 <Address 0x9 out of bounds>, 
	    ap=0xbffff548) at syslog.c:209
	#2  0x806c8fd in syslog (pri=6, 
	    fmt=0x80e01a0 "DHCPOFFER on 132.241.11.34 to 00:05:02:3e:96:5f via 132.241.200.1") at syslog.c:106
	#3  0x8059119 in note (fmt=0x80be8d4 "%s on %s to %s via %s") at errwarn.c:133
	#4  0x804bab0 in dhcp_reply (lease=0x81b24a8) at dhcp.c:1114
	#5  0x80489e3 in lease_ping_timeout (vlp=0x81b24a8) at dhcpd.c:344
	#6  0x8051bce in dispatch () at dispatch.c:643
	#7  0x804887e in main (argc=1, argv=0xbffffdb4, envp=0xbffffdbc) at dhcpd.c:279
	#8  0x805a4a3 in __libc_start_main (main=0x8048190 <main>, argc=1, 
	    argv=0xbffffdb4, init=0x80480b4 <_init>, fini=0x80be220 <_fini>, 
	    rtld_fini=0, stack_end=0xbffffdac) at ../sysdeps/generic/libc-start.c:78

  Grr.  Forgot to grab my new version of strace!  It bails when I
SIGPIPE it:

	send(3, "<30>Feb  2 09:17:58 dhcpd: DHCPO"..., 93, 0) = ? ERESTARTSYS (To be restarted)
	--- SIGPIPE (Broken pipe) ---
	close(3)                                = 0
	sigreturn(Segmentation fault

  Now, at this point, strace and gdb aren't showing anything.  With
strace showing no activity and gdb not falling through to a prompt,
I don't know what that means.  I probably botched it at this point and
unstuck it enough that an extra SIGPIPE killed it (having fallen though
glibc's syslog() eventually).

>  Incidentally, debug info is substantially smaller if you use -ggdb
>  instead of plain -g.

  Smaller, but not tiny.  Enough to fit though...


>  This might be a bug in strace or it might be the kernel returning
>  something totally unexpected.  Probably the first.  Ulrich has an
>  updated strace somewhere, check ftp.cygnus.com.

  I grabbed strace-3.1ud-b9 off of cygnus.  I forgot to use it when
I did the above strace, but I put it on that computer for next time.
I had to patch it to get it to compile (see patch).  I was guessing
at the EXEC_vfork/SYS_vfork bit, but it seems to be doing what it is
supposed to be doing.

>  Then the bug is unlikely to be in syslogd, unless the pipe has
>  gotten lost from syslogd's select() fdset.  You ought to be able
>  to check that with lsof and strace.

  Joy.  I'll crunch up lsof and stare at it.


  For extra ammo, up till now the linux-2.2.1 kernel was compiled with
gcc-2.7.2.3.  I also tried egcs-1.1.1 with the same results.
								--- john