On Wed, 2005-05-18 at 23:51, Balazs Scheidler wrote:

On Wed, 2005-05-18 at 17:53 -0700, Mike Tremaine wrote:

...

I just converted a Redhat 9 machine to syslog-ng yesterday and I'm having a littel problem with 2 lines running together. Here are the specs in question.

mgt@quasar ~ [1] rpm -q syslog-ng syslog-ng-1.6.7-2 mgt@quasar ~ [2] rpm -q sendmail sendmail-8.13.3-2.rhl9 mgt@quasar ~ [3] rpm -q libol libol-0.3.16-1 mgt@quasar ~ [4] uname -a Linux quasar 2.4.20-37.9.legacy #1 Mon Sep 27 19:40:23 EDT 2004 i686 i686 i386 GNU/Linux

The problem I'm seeing is every so often sendmail will log like so...

May 18 17:45:46 quasar sendmail[30415]: j4J0jdNg030415: from=<millie.zuniga_om@southtrust.com>, size=2520, class=0, nrcpts=1, msgid=<2.2.32.2004051809282400312642@southtrust.com>, proto=ESMTP, daemon=MTA, relay=[220.80.216.171]<22>May 18 17:45:46 sendmail[30415]: j4J0jdNg030415: Milter add: header: Received-SPF: none (quasar.stellarcore.net: 220.80.216.171 is neither permitted nor denied by domain of southtrust.com) receiver=quasar.stellarcore.net; client-ip=220.80.216.171; helo=localhost; envelope-from=millie.zuniga_om@southtrust.com; x-software=spfmilter 0.93 http://www.acme.com/software/spfmilter/;

Notice the 22 that should be a line break between the 2 log lines. Has anyone noticed something like this?

There used to be problems like this, but I haven't encountered this for a time now.

What is your configuration, are you using unix-dgram or unix-stream to get local messages?

unix-stream ("/dev/log"); I kept the standard syslog-ng.conf file that was packaged in the rpm with very few changes. [ log_fifo_size (64000); and 1 extra destination ] In looking through yesterdays logs I can confirm that this is only happening to sendmail logs. But like I said I just installed syslog-ng 2 days ago and was not having this issue with the standard syslog. -- Mike Tremaine mgt@stellarcore.net http://www.stellarcore.net

On Thu, 2005-05-19 at 11:01 -0700, Mike Tremaine wrote:

On Thu, 2005-05-19 at 08:12, Mike Tremaine wrote:

...

On Wed, 2005-05-18 at 23:51, Balazs Scheidler wrote:

...

On Wed, 2005-05-18 at 17:53 -0700, Mike Tremaine wrote:

In looking through yesterdays logs I can confirm that this is only happening to sendmail logs. But like I said I just installed syslog-ng 2 days ago and was not having this issue with the standard syslog.

Just to follow up a little. I tried tweaking a few configuration options [sync, fifo, max connections] but with out success. I also tried two older version syslog-ng-1.6.5-4 and syslog-1.6.5-2. The problem [for me atleast] exists under these version also.

Very odd, almost like sendmail is not giving a proper EOL. I looked in sources.c [do_read_line] but my c is weak and nothing jumped out at me.

I'm open to suggestions, I'm also willing to move up to 1.9 if this is not worth debugging.

If your log volume is bearable, it would help if you could attach strace to the syslog-ng process with a large -s parameter while a broken message is received. e.g. something like: strace -s 4096 -o syslog-ng.trace -p <syslog-ngpid> That would help to identify whether syslog-ng or sendmail is at fault. Standard syslogd uses unix-dgram sockets, but if sendmail uses the standard syslog() routines from libc it should simply work with unix-stream() as well. -- Bazsi

On Fri, 2005-05-20 at 12:14 -0700, Mike Tremaine wrote:

On Fri, 2005-05-20 at 04:49, Balazs Scheidler wrote:

Luckly it is... Attached is a trimmed down trace file with a few examples of the problem [about 200lines let me know if more would be useful...]

To my [uneducated] eye it looks like sendmail is the problem but like I said sometimes it does it right sometime it doesn't.

Example:

read(16, "<20>May 20 07:48:02 sendmail[16668]: j4KEkWOv016668: collect: premature EOM: unexpected close", 2048) = 93

Notice no \0 or \n

Then the next read

read(16, "<21>May 20 07:48:02 sendmail[16668]: j4KEkWOv016668: collect: unexpected close on connection from [61.43.165.161], sender=<Hager@indiatimes.com>\0<22>May 20 07:48:02 sendmail[16668]: j4KEkWOv016668: from=<Hager@indiatimes.com>, size=0, class=0, nrcpts=1, proto=SMTP, daemon=MTA, relay=[61.43.165.161]\0", 1955) = 300

A null terminator That leads to the output

write(22, "2005-05-20 07:48:02 quasar mail.warning sendmail[16668]: j4KEkWOv016668: collect: premature EOM: unexpected close<21>May 20 07:48:02 sendmail[16668]: j4KEkWOv016668: collect: unexpected close on connection from [61.43.165.161], sender=<Hager@indiatimes.com>\n2005-05-20 07:48:02 quasar mail.info sendmail[16668]: j4KEkWOv016668: from=<Hager@indiatimes.com>, size=0, class=0, nrcpts=1, proto=SMTP, daemon=MTA, relay=[61.43.165.161]\n", 430) = 430 .

So the null was caught and turned into \n but the line before it runs together. With some weird <21> [and more often <22> see trace file].

Hm. Sendmail really seems to be the culprit, it is only hidden by sysklogd using unix-dgram() sockets in which case the syslog daemon does not care whether the message was NL or \0 terminated or not. The manpage for syslogd, mentions: ... "A trailing newline is added when needed." This does not seem to be true. After judging the source it seems to be adding the NL character only if LOG_PERROR is specified to openlog() which clearly isn't the case for sendmail. I'd say this is a libc bug which you can work around by avoiding using unix-stream and sticking to unix-dgram instead. (a solution which I myself do not like). -- Bazsi