NetBSD Problem Report #39910
From jukka+moray@salmi.ch Wed Nov 12 22:27:57 2008
Return-Path: <jukka+moray@salmi.ch>
Received: from mail.netbsd.org (mail.netbsd.org [204.152.190.11])
by narn.NetBSD.org (Postfix) with ESMTP id 15E7E63B898
for <gnats-bugs@gnats.NetBSD.org>; Wed, 12 Nov 2008 22:27:57 +0000 (UTC)
Message-Id: <20081112222753.196B21A411@moray.salmi.ch>
Date: Wed, 12 Nov 2008 23:27:53 +0100 (CET)
From: Jukka Salmi <j+nbsd@2008.salmi.ch>
Reply-To: Jukka Salmi <j+nbsd@2008.salmi.ch>
To: gnats-bugs@gnats.NetBSD.org
Subject: syslog regression after SoC code import
X-Send-Pr-Version: 3.95
>Number: 39910
>Category: bin
>Synopsis: syslog regression after SoC code import
>Confidential: no
>Severity: non-critical
>Priority: medium
>Responsible: bin-bug-people
>State: closed
>Class: sw-bug
>Submitter-Id: net
>Arrival-Date: Wed Nov 12 22:30:00 +0000 2008
>Closed-Date: Thu Nov 13 15:51:45 +0000 2008
>Last-Modified: Thu Nov 13 15:51:45 +0000 2008
>Originator: Jukka Salmi
>Release: NetBSD 5.99.01
>Organization:
>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:/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:
>Release-Note:
>Audit-Trail:
From: Jukka Salmi <j+nbsd@2008.salmi.ch>
To: gnats-bugs@NetBSD.org
Cc:
Subject: Re: bin/39910: syslog regression after SoC code import
Date: Thu, 13 Nov 2008 11:56:40 +0100
Jukka Salmi --> netbsd-bugs (2008-11-12 22:30:00 +0000):
[...]
> 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.
While 2) has already been fixed (I missed a commit, sorry...), I can
still reproduce 1) with the latest HEAD sources.
--
bashian roulette:
$ ((RANDOM%6)) || rm -rf ~
From: Jukka Salmi <j+nbsd@2008.salmi.ch>
To: gnats-bugs@NetBSD.org
Cc:
Subject: Re: bin/39910: syslog regression after SoC code import
Date: Thu, 13 Nov 2008 15:29:27 +0100
The patch from PR bin/39912 fixes the problem with logger(1).
State-Changed-From-To: open->closed
State-Changed-By: christos@NetBSD.org
State-Changed-When: Thu, 13 Nov 2008 10:51:45 -0500
State-Changed-Why:
submitter verifies it has been fixed.
>Unformatted:
(Contact us)
$NetBSD: query-full-pr,v 1.39 2013/11/01 18:47:49 spz Exp $
$NetBSD: gnats_config.sh,v 1.8 2006/05/07 09:23:38 tsutsui Exp $
Copyright © 1994-2007
The NetBSD Foundation, Inc. ALL RIGHTS RESERVED.
Home