bin/39910: syslog regression after SoC code import

[Jukka Salmi <j+nbsd%2008.salmi.ch@localhost>]

>Number:         39910
>Category:       bin
>Synopsis:       syslog regression after SoC code import
>Confidential:   no
>Severity:       non-critical
>Priority:       medium
>Responsible:    bin-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed Nov 12 22:30:00 +0000 2008
>Originator:     Jukka Salmi
>Release:        NetBSD 5.99.01
>Environment:
System: NetBSD moray.salmi.ch 5.99.01 NetBSD 5.99.01 (MORAY.APM) #0: Thu Nov 6 
18:00:22 CET 2008 
build%moray.salmi.ch@localhost:/b/build/nbsd/c/i386/sys/arch/i386/compile/MORAY.APM
 i386
Architecture: i386
Machine: i386
>Description:
The recently committed syslog changes cause at least two problems.

1) When sending a log message using logger(1), the first argument is
   not logged.

2) Using +@ and -@ lines in syslog.conf doesn not work correctly
   anymore.

>How-To-Repeat:
$ cat /etc/syslog.conf
#       $NetBSD: syslog.conf,v 1.9 2004/07/23 03:45:42 mycroft Exp $
+@
*.err;kern.*;auth.notice;authpriv.none;mail.crit        /dev/console
*.info;auth,authpriv,cron,ftp,kern,lpr,mail.none        /var/log/messages
kern.debug                                              /var/log/messages
[...]
-@
*.debug                                                 /var/log/foreign

This used to work fine with the "old" syslogd, logging messages from
the local host to /var/log/messages and those of remote hosts to
/var/log/foreign.  But with the new code (and the same configuration
file) all messages from the local hosts end up in /var/log/foreign:

$ logger -p daemon.info this is a test
$ tail /var/log/messages
[... nothing ...]
$ tail /var/log/foreign
[...]
Nov 12 21:08:19 moray jukka: is a test - -

Also notice that the first word (`this') was not logged.

This is what syslogd prints while running with -d (after adding D_DATA
to D_DEFAULT) and while receiving a message from logger(1):

$ ( sleep 10; logger -p daemon.info and yet another test ) &
[1] 21801
$ sudo ./syslogd -d -s
2008-11-12T23:08:34.282855+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:logpath_add:0775
   Adding `/var/run/log' to the 0x0 logpath list
2008-11-12T23:08:34.283186+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:main:0473  
Making unix dgram socket `/var/run/log'
2008-11-12T23:08:34.284097+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:main:0485  
Listening on unix dgram socket `/var/run/log'
2008-11-12T23:08:34.284238+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:main:0492  
Listening on kernel log `/dev/klog' with fd 4
2008-11-12T23:08:34.299721+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:main:0504  
Initializing PRNG
2008-11-12T23:08:34.300838+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:main:0521  
Attempt to chroot to `/'
2008-11-12T23:08:34.300973+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:main:0526  
Attempt to set GID/EGID to `0'
2008-11-12T23:08:34.301039+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:main:0531  
Attempt to set UID/EUID to `0'
2008-11-12T23:08:34.301247+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:init:3240  
init
2008-11-12T23:08:34.301340+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:read_config_file:3017
      read_config_file()
2008-11-12T23:08:34.301540+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(8, "*.err;kern.*;auth.notice;authpriv.none;mail.crit     
/dev/console", f, "*", "+moray")
2008-11-12T23:08:34.301694+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(9, "*.info;auth,authpriv,cron,ftp,kern,lpr,mail.none     
/var/log/messages", f, "*", "+moray")
2008-11-12T23:08:34.301786+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(10, "kern.debug                                          
/var/log/messages", f, "*", "+moray")
2008-11-12T23:08:34.303790+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(15, "auth,authpriv.info                                  
/var/log/authlog", f, "*", "+moray")
2008-11-12T23:08:34.304070+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(17, "cron.info                                           
/var/log/cron", f, "*", "+moray")
2008-11-12T23:08:34.304192+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(18, "ftp.info                                            
/var/log/xferlog", f, "*", "+moray")
2008-11-12T23:08:34.304323+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(19, "lpr.info                                            
/var/log/lpd-errs", f, "*", "+moray")
2008-11-12T23:08:34.304442+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(20, "mail.info                                           
/var/log/maillog", f, "*", "+moray")
2008-11-12T23:08:34.304574+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(23, "*.emerg                                                     
*", f, "*", "+moray")
2008-11-12T23:08:34.304689+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(26, "local5.*                                            
/var/log/smart", f, "*", "+moray")
2008-11-12T23:08:34.304805+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(27, "*.err                                                       
/var/log/errors", f, "*", "+moray")
2008-11-12T23:08:34.304932+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(29, "local0.debug                                                
/var/log/debug", f, "*", "+moray")
2008-11-12T23:08:34.305056+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:cfline:3575
        cfline(49, "*.debug                                             
/var/log/foreign", f, "*", "-moray")
2008-11-12T23:08:34.305191+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:init:3359  
read_config_file() returned newf=0xbb80f000
8 3 2 3 5 3 3 3 3 3 X 3 3 3 3 3 3 3 3 3 3 3 3 3 X CONSOLE: /dev/console
X 6 X 6 X 6 X 6 6 X X X 6 6 6 6 6 6 6 6 6 6 6 6 X FILE: /var/log/messages
7 X X X X X X X X X X X X X X X X X X X X X X X X FILE: /var/log/messages
X X X X 6 X X X X X 6 X X X X X X X X X X X X X X FILE: /var/log/authlog
X X X X X X X X X 6 X X X X X X X X X X X X X X X FILE: /var/log/cron
X X X X X X X X X X X 6 X X X X X X X X X X X X X FILE: /var/log/xferlog
X X X X X X 6 X X X X X X X X X X X X X X X X X X FILE: /var/log/lpd-errs
X X 6 X X X X X X X X X X X X X X X X X X X X X X FILE: /var/log/maillog
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 X WALL:
X X X X X X X X X X X X X X X X X X X X X 8 X X X FILE: /var/log/smart
3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 X FILE: /var/log/errors
X X X X X X X X X X X X X X X X 7 X X X X X X X X FILE: /var/log/debug
7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 7 X FILE: /var/log/foreign
2008-11-12T23:08:34.305959+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:init:3530  
Preparing sockets for TLS
2008-11-12T23:08:34.306076+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:loginfo:2756
       restart
2008-11-12T23:08:34.306164+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:logmsg_async:1598
  logmsg_async(46, "(null)", "restart", 4)
2008-11-12T23:08:34.306295+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:logmsg:1784
        logmsg: buffer@0xbb82b280, pri 056/46, flags 0x4, timestamp "Nov 12 
23:08:34", from "moray.salmi.ch", sd "(null)", msg "restart"
2008-11-12T23:08:34.306433+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:fprintlog:2107
     fprintlog(0xbb80f800, 0xbb82b280, 0x0)
2008-11-12T23:08:34.306526+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:format_buffer:1944
 format_buffer(0xbb82b280)
2008-11-12T23:08:34.306626+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:format_buffer:2069
 formatted 52 octets to: '49 <46>Nov 12 23:08:34 moray syslogd[18352]: restart' 
(linelen 52, msglen 49, tlsprefixlen 3, prilen 4)
2008-11-12T23:08:34.306731+01:00:/usr/src/usr.sbin/syslogd/sign.c:sign_get_sg:0596
      sign_get_sg(46, 0xbb80f800) --> 0x0
2008-11-12T23:08:34.306822+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:fprintlog:2372
     Logging to FILE /var/log/messages
2008-11-12T23:08:34.307065+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:main:0630  
Off & running....
2008-11-12T23:08:40.875336+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:dispatch_read_funix:0708
   Unix socket (/var/run/log) active (3, 2 0xbb813470) with linebuf@0xbb87b000, 
size 32752)
2008-11-12T23:08:40.876530+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline:1443
     printline("moray.salmi.ch", "<30>1 2008-11-12T23:08:40.874798+01:00 
moray.salmi.ch jukka - and yet another test - -", 0)
2008-11-12T23:08:40.876727+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1024
      printline_syslogprotocol("moray.salmi.ch", 
"2008-11-12T23:08:40.874798+01:00 moray.salmi.ch jukka - and yet another test - 
-", 0, 30)
2008-11-12T23:08:40.876835+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:check_timestamp:1633
       check_timestamp(0xbb87b006 = "2008-11-12T23:08:40.874798+01:00 
moray.salmi.ch jukka - and yet another test - -", from_iso=1, to_iso=0)
2008-11-12T23:08:40.876941+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:check_timestamp:1715
       check_timestamp(): convert ISO->BSD
2008-11-12T23:08:40.877090+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1030
      Got timestamp "Nov 12 23:08:40"
2008-11-12T23:08:40.877180+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1048
      Got host "moray.salmi.ch"
2008-11-12T23:08:40.877270+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1065
      Got prog "jukka"
2008-11-12T23:08:40.877357+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1083
      Got pid "(null)"
2008-11-12T23:08:40.877445+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1102
      Got msgid "and"
2008-11-12T23:08:40.877532+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1108
      check_sd("yet another test - -") returned 0
2008-11-12T23:08:40.877621+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1117
      format error
2008-11-12T23:08:40.877706+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1121
      Got SD "(null)"
2008-11-12T23:08:40.877799+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:printline_syslogprotocol:1159
      Got msg "yet another test - -"
2008-11-12T23:08:40.877888+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:logmsg:1784
        logmsg: buffer@0xbb82b2c0, pri 036/30, flags 0x0, timestamp "Nov 12 
23:08:40", from "moray.salmi.ch", sd "(null)", msg "yet another test - -"
2008-11-12T23:08:40.878003+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:fprintlog:2107
     fprintlog(0xbb80f800, 0xbb82b2c0, 0x0)
2008-11-12T23:08:40.878093+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:format_buffer:1944
 format_buffer(0xbb82b2c0)
2008-11-12T23:08:40.878192+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:format_buffer:2069
 formatted 56 octets to: '53 <30>Nov 12 23:08:40 moray jukka: yet another test 
- -' (linelen 56, msglen 53, tlsprefixlen 3, prilen 4)
2008-11-12T23:08:40.878291+01:00:/usr/src/usr.sbin/syslogd/sign.c:sign_get_sg:0596
      sign_get_sg(30, 0xbb80f800) --> 0x0
2008-11-12T23:08:40.878379+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:fprintlog:2372
     Logging to FILE /var/log/messages
^C2008-11-12T23:08:44.110587+01:00:/usr/src/usr.sbin/syslogd/sign.c:sign_global_free:0453
       sign_global_free()
2008-11-12T23:08:44.110680+01:00:/usr/src/usr.sbin/syslogd/sign.c:sign_free_string_queue:0717
   sign_free_string_queue(0x8068aa0)
2008-11-12T23:08:44.110823+01:00:/usr/src/usr.sbin/syslogd/syslogd.c:logerror:2736
      Exiting on signal 2
[1]+  Done                    ( sleep 10; logger -p daemon.info and yet another 
test )

Hmm, `Got prog "jukka"' clearly seems to be wrong...

>Fix: