[syslog-ng] trailing spaces on udp messages (now with NULLs!)

Paul Krizak paul.krizak at amd.com
Fri Jan 19 18:28:09 CET 2007


It appears that the changes to logreader.c between rc1 and rc2 are what 
broke it.  Unfortunately this is where my debugging prowess ends, and 
hopefully Balazs picks up.

FYI, copying logreader.c from the 2.0rc1 release into the 2.0.1 release 
compiles and works fine, and will be my holdover solution until 2.0.2 is 
released with the appropriate fix.

Paul Krizak                         5900 E. Ben White Blvd. MS 625
Advanced Micro Devices              Austin, TX  78741
Linux/Unix Systems Engineering      Phone: (512) 602-8775
Silicon Design Division             Cell:  (512) 791-0686


Paul Krizak wrote:
> I have confirmed that this problem was introduced between 2.0rc1 (no 
> extraneous NULLs) and 2.0rc2 (broken).  I'll now start diffing the 
> releases to see if I can figure out what broke it.
> 
> Paul Krizak                         5900 E. Ben White Blvd. MS 625
> Advanced Micro Devices              Austin, TX  78741
> Linux/Unix Systems Engineering      Phone: (512) 602-8775
> Silicon Design Division             Cell:  (512) 791-0686
> 
> 
> Paul Krizak wrote:
>> OK I just confirmed that rolling back to syslog-ng-1.9.9 and 
>> eventlog-0.2.2 corrects this.  I will work on locating the revision 
>> that introduced this problem.
>>
>> Paul Krizak                         5900 E. Ben White Blvd. MS 625
>> Advanced Micro Devices              Austin, TX  78741
>> Linux/Unix Systems Engineering      Phone: (512) 602-8775
>> Silicon Design Division             Cell:  (512) 791-0686
>>
>>
>> Paul Krizak wrote:
>>> I think that I may be seeing this same thing, though I'm unsure 
>>> because of the very strange hoops I must go through to reproduce my 
>>> problem.  In my case, I'm getting NULL characters at the end of some 
>>> messages, particularly those left in the /dev/log buffer (I 
>>> think...keep reading for an explanation).
>>>
>>> Here's how I reproduce, using syslog-ng-2.0.1 stable.  I've attached 
>>> my syslog-ng.conf.
>>>
>>> 1. On a fresh install of RHEL3 U8 (it also happens in RHEL4 U4), stop 
>>> the syslog service twice:
>>>
>>> [skaven at byleth ~]$ sudo service syslog stop
>>> Shutting down kernel logger:                               [  OK  ]
>>> Shutting down system logger:                               [  OK  ]
>>> [skaven at byleth ~]$ sudo service syslog stop
>>> Shutting down kernel logger:                               [FAILED]
>>> Shutting down system logger:                               [FAILED]
>>>
>>> Now start up syslog-ng using the config file provided, and the 
>>> following messages will appear in /tmp/messages.log:
>>>
>>> 2007 Jan 18 18:52:22 byleth syslog.notice syslog-ng[15245]: syslog-ng 
>>> starting up; version='2.0.1'
>>> 2007 Jan 18 18:52:24 byleth local7.notice syslog: syslogd shutdown 
>>> succeeded ^@
>>> 2007 Jan 18 18:52:24 byleth auth.warning sudo:   skaven : TTY=pts/4 ; 
>>> PWD=/home/skaven ; USER=root ; COMMAND=/sbin/service syslog stop ^@
>>> 2007 Jan 18 18:52:24 byleth local7.notice syslog: klogd shutdown 
>>> failed ^@
>>> 2007 Jan 18 18:52:24 byleth local7.notice syslog: syslogd shutdown 
>>> failed ^@
>>>
>>> The ^@ are the NULL characters.
>>>
>>> So it appears that any syslog message generated after syslogd has 
>>> gone down (the syslogd shutdown message generated by initlog, the 
>>> sudo message, the klogd message, and the extra syslogd shutdown 
>>> messages from the second shutdown) are stored in some sort of 
>>> buffer.  When syslog-ng fires up, /dev/log dumps these messages, and 
>>> they for some reason contain NULLs at the end.
>>>
>>> Totally and completely bizarre.  Any ideas?
>>>
>>> Paul Krizak                         5900 E. Ben White Blvd. MS 625
>>> Advanced Micro Devices              Austin, TX  78741
>>> Linux/Unix Systems Engineering      Phone: (512) 602-8775
>>> Silicon Design Division             Cell:  (512) 791-0686
>>>
>>>
>>> Johan Fischer wrote:
>>>> Hi List,
>>>>
>>>> I'm using syslog-ng-2.0.1 on RHEL4 (centos4 actually) but I 
>>>> reproduced the same
>>>> problem on debian unstable using the debian package (currently 2.0.0).
>>>>
>>>> The clients are using sysklogd 1.4.1-20
>>>>
>>>> It seems that all my lines logs from udp() have one trailing space. 
>>>> The internal
>>>> logs and /dev/log don't have that space so I'm currently assuming 
>>>> either the
>>>> sender (sysklogd) or the receiver (udp module of syslog-ng) is not 
>>>> filtering
>>>> that space.
>>>>
>>>> This also seem to happen with the internal() source.
>>>>
>>>> A wireshark of the packet will show this:
>>>> Syslog message: USER.NOTICE: jfischer: blahklfdsfd\n
>>>>
>>>> I can see a \n at the end of the line but no space. I don't know 
>>>> what to think
>>>> of this yet.
>>>>
>>>> I attached the configuration used (stripped as much), and the logs 
>>>> created.
>>>>
>>>> This problem is affecting mostly logwatch which do from time to time 
>>>> strict
>>>> regex on the end of the string that I cannot match because of this 
>>>> trailing space.
>>>>
>>>> Cheers.
>>>> J.
>>>>
>>>>
>>>>
>>>>
>>>> ------------------------------------------------------------------------ 
>>>>
>>>>
>>>> Jan 17 12:45:01 clamp CRON[8797]: (pam_unix) session opened for user 
>>>> root by (uid=0)
>>>> Jan 17 12:45:01 clamp CRON[8799]: (pam_unix) session opened for user 
>>>> root by (uid=0)
>>>> Jan 17 12:45:01 clamp CRON[8801]: (pam_unix) session opened for user 
>>>> jfischer by (uid=0)
>>>> Jan 17 12:45:01 clamp /USR/SBIN/CRON[8798]: (root) CMD ([ -x 
>>>> /usr/lib/sysstat/sa1 ] && { [ -r "$DEFAULT" ] && . "$DEFAULT" ; [ 
>>>> "$ENABLED" = "true" ] && exec /usr/lib/sysstat/sa1 $SA1_OPTIONS 1 1 
>>>> ; })
>>>> Jan 17 12:45:01 clamp /USR/SBIN/CRON[8800]: (root) CMD (if [ -x 
>>>> /usr/bin/mrtg ] && [ -r /etc/mrtg.cfg ]; then env LANG=C 
>>>> /usr/bin/mrtg /etc/mrtg.cfg >> /var/log/mrtg/mrtg.log 2>&1; fi)
>>>> Jan 17 12:45:01 clamp /USR/SBIN/CRON[8802]: (jfischer) CMD 
>>>> (/home/jfischer/bin/chg_background >/dev/null)
>>>> Jan 17 12:45:01 clamp CRON[8801]: (pam_unix) session closed for user 
>>>> jfischer
>>>> Jan 17 12:45:01 clamp CRON[8797]: (pam_unix) session closed for user 
>>>> root
>>>> Jan 17 12:45:02 clamp CRON[8799]: (pam_unix) session closed for user 
>>>> root
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> VCore 1: +0.00 V (min = +1.14 V, max = +1.55 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> VCore 2: +0.00 V (min = +1.14 V, max = +1.55 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> +3.3V: +0.00 V (min = +2.82 V, max = +3.79 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> +5V: +5.03 V (min = +4.01 V, max = +1.10 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> +12V: +0.00 V (min = +14.29 V, max = +11.31 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> -12V: -14.91 V (min = -4.55 V, max = -10.39 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> -5V: -7.71 V (min = -3.39 V, max = +5.00 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> V5SB: +5.59 V (min = +2.93 V, max = +2.53 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> VBat: +0.00 V (min = +2.99 V, max = +1.84 V) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> fan1: 0 RPM (min = 2812 RPM, div = 2) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> fan2: 0 RPM (min = 3183 RPM, div = 2) [ALARM]
>>>> Jan 17 12:45:09 clamp sensord: Sensor alarm: Chip w83627hf-isa-0290: 
>>>> fan3: 0 RPM (min = 25000 RPM, div = 2) [ALARM]
>>>> Jan 17 12:45:44 clamp fetchmail[2500]: awakened at Wed 17 Jan 2007 
>>>> 12:45:44 EST
>>>> Jan 17 12:45:44 clamp fetchmail[2500]: Server CommonName mismatch: 
>>>> localhost.localdomain != pop.cmcrc.com
>>>> Jan 17 12:45:44 clamp fetchmail[2500]: Server certificate 
>>>> verification error: self signed certificate
>>>> Jan 17 12:45:44 clamp fetchmail[2500]: sleeping at Wed 17 Jan 2007 
>>>> 12:45:44 EST for 300 seconds
>>>>
>>>>
>>>> ------------------------------------------------------------------------ 
>>>>
>>>>
>>>> Jan 17 12:45:01 192.168.15.19 CRON[2871]: (pam_unix) session opened 
>>>> for user root by (uid=0) Jan 17 12:45:01 192.168.15.19 
>>>> /USR/SBIN/CRON[2872]: (root) CMD ([ -x /usr/lib/sysstat/sa1 ] && { [ 
>>>> -r "$DEFAULT" ] && . "$DEFAULT" ; [ "$ENABLED" = "true" ] && exec 
>>>> /usr/lib/sysstat/sa1 $SA1_OPTIONS 1 1 ; }) Jan 17 12:45:01 
>>>> 192.168.15.19 CRON[2871]: (pam_unix) session closed for user root 
>>>> Jan 17 12:45:59 192.168.15.19 sshd[3586]: Accepted password for 
>>>> jfischer from 192.168.15.17 port 49664 ssh2 Jan 17 12:45:59 
>>>> 192.168.15.19 sshd[3606]: (pam_unix) session opened for user 
>>>> jfischer by (uid=0)
>>>>
>>>> ------------------------------------------------------------------------ 
>>>>
>>>>
>>>> options {
>>>>         chain_hostnames(0);
>>>>         time_reopen(10);
>>>>         time_reap(360);
>>>>         log_fifo_size(2048);
>>>>         create_dirs(yes);
>>>>         group(adm);
>>>>         perm(0640);
>>>>         dir_perm(0755);
>>>>         use_dns(no);
>>>>     stats_freq(0);
>>>> };
>>>>
>>>> source s_internal {
>>>>         internal();
>>>> };
>>>>
>>>> source s_local {
>>>>         unix-stream("/dev/log");
>>>>         file("/proc/kmsg" log_prefix("kernel: "));
>>>> };
>>>>
>>>> source s_remote {
>>>>     udp();
>>>>     tcp();
>>>> };
>>>>
>>>> destination df_internal { file("/var/log/test/internal.log"); };
>>>> destination df_local { file("/var/log/test/local.log"); };
>>>> destination df_remote { file("/var/log/test/remote.log"); };
>>>>
>>>> log { source(s_internal); destination(df_internal); };
>>>> log { source(s_local); destination(df_local); };
>>>> log { source(s_remote); destination(df_remote); };
>>>>
>>>>
>>>>
>>>> ------------------------------------------------------------------------ 
>>>>
>>>>
>>>> Jan 17 12:44:30 clamp syslog-ng[8783]: syslog-ng starting up; 
>>>> version='2.0.0'
>>>>
>>>> ------------------------------------------------------------------------ 
>>>>
>>>>
>>>> _______________________________________________
>>>> syslog-ng maillist  -  syslog-ng at lists.balabit.hu
>>>> https://lists.balabit.hu/mailman/listinfo/syslog-ng
>>>> Frequently asked questions at http://www.campin.net/syslog-ng/faq.html
>>>>
>>>
>>> ------------------------------------------------------------------------
>>>
>>> #options {
>>> #    sync(0);                     # The number of lines buffered 
>>> before written to file: we want immediate output to our destinations
>>> #    mark_freq(300);              # The number of seconds between two 
>>> MARK lines.
>>> #    stats_freq(60);              # The number of seconds between two 
>>> STATS. (number of dropped messages)
>>> #    log_fifo_size(10000);        # The number of lines fitting to 
>>> the output queue: we want to be able to handle a flood
>>> #    chain_hostnames(no);         # Enable or disable the chained 
>>> hostname format.
>>> #    keep_hostname(no);           # Enable or disable hostname 
>>> rewriting.  We rewrite hostnames because our systems send all their 
>>> names as IPs.
>>> #    owner("root"); #    group("root");
>>> #    perm(0644);
>>> #    create_dirs(yes);
>>> #    dir_owner("root");
>>> #    dir_group("root");
>>> #    dir_perm(0755);
>>> #    use_dns(yes) ;               # Enable or disable DNS usage. 
>>> **syslog-ng blocks on DNS queries**
>>> #    dns_cache(yes);              # Enable or disable DNS cache 
>>> usage. (not implemented)
>>> #    dns_cache_size(10000);       # Number of hostnames in the DNS 
>>> cache: lets try to keep all hosts in the cache (not implemented)
>>> #    dns_cache_expire(3600);      # Number of seconds while a 
>>> successful lookup is cached: 1 hr seems reasonable (not implemented)
>>> #    dns_cache_expire_failed(30); # Number of seconds while a failed 
>>> lookup is cached: 30 seconds seems reasonable (not implemented)
>>> #    use_fqdn(no);                # Add Fully Qualified Domain Name 
>>> instead of short hostname.
>>> #};
>>>
>>> # Local syslog
>>> source s_internal_syslog {
>>>     unix-dgram("/dev/log");
>>>     file("/proc/kmsg" log_prefix("kernel:"));
>>> };
>>>
>>> # Sylog-ng's internal log
>>> source s_syslog-ng {
>>>     internal();
>>> };
>>>
>>> # This template reformats incoming messages for use in human-readable 
>>> logfiles
>>> template t_human_readable {
>>>     template("$R_FULLDATE $HOST $FACILITY.$PRIORITY $MESSAGE\n");
>>>     template-escape(no);
>>> };
>>>
>>> # The big monolithic syslog file
>>> destination d_big_messages {
>>>     file (
>>>         "/tmp/messages.log"
>>>         template(t_human_readable)
>>>         owner("root")
>>>         group("root")
>>>         perm(0644)
>>>     );
>>> };
>>>
>>> # log local syslog stuff to /var/log/messages
>>> log {
>>>     source(s_internal_syslog);
>>>     source(s_syslog-ng);
>>>     destination(d_big_messages);
>>> };
>>>
>>>
>>>
>>> ------------------------------------------------------------------------
>>>
>>> _______________________________________________
>>> syslog-ng maillist  -  syslog-ng at lists.balabit.hu
>>> https://lists.balabit.hu/mailman/listinfo/syslog-ng
>>> Frequently asked questions at http://www.campin.net/syslog-ng/faq.html
>>>
>>
>>
>> _______________________________________________
>> syslog-ng maillist  -  syslog-ng at lists.balabit.hu
>> https://lists.balabit.hu/mailman/listinfo/syslog-ng
>> Frequently asked questions at http://www.campin.net/syslog-ng/faq.html
>>
>>
> 
> 
> _______________________________________________
> syslog-ng maillist  -  syslog-ng at lists.balabit.hu
> https://lists.balabit.hu/mailman/listinfo/syslog-ng
> Frequently asked questions at http://www.campin.net/syslog-ng/faq.html
> 
> 




More information about the syslog-ng mailing list