Urgent: Mangled messages in pipe() destinations in version 1.5.19
Hello Balazs, in version 1.5.19 (and in other versions between >1.5.7 and <=1.5.19, too) we observing obscure message mangling in pipe() destinations. Imagine the config below and the scenario: syslog-ng --write(2)--> pipe() --read(2)--> application All four log paths below, writes lines to the pipe '/tmp/pipe'. With 1.5.7 we read from the pipe exactly that, what syslog-ng (using the config below) writes to it. But with all newer versions (espec. 1.5.19) we read (with the same config): message_1 message_2 messagmessage_4 !!! ... message_n if we try to let syslog-ng write: message_1 message_2 message_3 message_4 ... message_n (The numbers and terms are only examples, because of the different sources and high message load.) Seems, that write(2) to fifo skips some message ends now. (espec. the terminating newline)
# example config: # source sys { sun-streams ("/dev/log" door("/var/run/syslog_door")); }; source net { udp (ip(w.x.y.z) port(n)); }; destination d_cisco { pipe("/tmp/pipe" template("@cisco: | $MSG\n")); }; destination d_icmp { pipe("/tmp/pipe" template("@icmpd: | $MSG\n")); }; log { source(net); filter(fa); destination(da); destination(d_cisco); }; log { source(net); filter(fb); destination(db); destination(d_cisco); }; log { source(sys); filter(f1); destination(d1); destination(d_icmp); }; log { source(sys); filter(f2); destination(d2); destination(d_icmp); };
We are running a config similar to this above, with 1.5.7 since a lot of months very successfully in production ennvironment with very high message load. Since 1.5.1? the message mangling occurs. But now, some of your newer features becomes mission critical for us. Have you any idea, what happens? Versions <= 1.5.7 works well. Thanks a lot. -- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | | sh# cat>$$.c<<EOT | main(l,a,n,d)char**a;{for(d=atoi(a[1])/10*80-atoi(a[2])/5-596;n="@NK\ | ACLCCGZAAQBEAADAFaISADJABBA^SNLGAQABDAXIMBAACTBATAHDBANZcEMMCCCCAAhE\ | IJFAEAAABAfHJETBdFLDAANEfDNBPHdBcBBBEA_AL H E L L O, W O R L D! " | [l++-3];)for(;n-->64;)putchar(!d+++33^l&1);} | EOT | gcc -o$$ $$.c;clear;./$$ 52 8;rm -f $$*
On Fri, Aug 02, 2002 at 05:26:25PM +0200, Andreas Schulze wrote:
Hello Balazs,
in version 1.5.19 (and in other versions between >1.5.7 and <=1.5.19, too) we observing obscure message mangling in pipe() destinations.
Imagine the config below and the scenario: syslog-ng --write(2)--> pipe() --read(2)--> application
All four log paths below, writes lines to the pipe '/tmp/pipe'. With 1.5.7 we read from the pipe exactly that, what syslog-ng (using the config below) writes to it.
But with all newer versions (espec. 1.5.19) we read (with the same config):
message_1 message_2 messagmessage_4 !!! ... message_n
if we try to let syslog-ng write:
message_1 message_2 message_3 message_4 ... message_n
Hi all, We are seeing exactly the same behaviour Andreas described. Actually it works fine until version 1.5.8, but if we use any version >1.5.8, including patched 1.5.19 and 1.5.20, we get lots of mangled messages. So it's not really the same problem that was fixed in 1.5.20. Any ideas? We'd also love to use the latest version and not have to stick to 1.5.8. Thanks in advance, Carlos Inacio.
I've found the same problem in version 1.5.20: DBD::mysql::db do failed: You have an error in your SQL syntax near 'INSERT INTO logs (host, facility, level, tag, date, time, program, msg) VALUES (' at line 1 at /usr/local/script/insertdb.pl line 35, <FF> line 19. -----Original Message----- From: syslog-ng-admin@lists.balabit.hu [mailto:syslog-ng-admin@lists.balabit.hu] On Behalf Of Carlos Inacio Sent: Friday, September 27, 2002 2:47 PM To: syslog-ng@lists.balabit.hu Subject: Re: [syslog-ng]Urgent: Mangled messages in pipe() destinations in version 1.5.19 On Fri, Aug 02, 2002 at 05:26:25PM +0200, Andreas Schulze wrote:
Hello Balazs,
in version 1.5.19 (and in other versions between >1.5.7 and <=1.5.19, too) we observing obscure message mangling in pipe() destinations.
Imagine the config below and the scenario: syslog-ng --write(2)--> pipe() --read(2)--> application
All four log paths below, writes lines to the pipe '/tmp/pipe'. With 1.5.7 we read from the pipe exactly that, what syslog-ng (using the config below) writes to it.
But with all newer versions (espec. 1.5.19) we read (with the same config):
message_1 message_2 messagmessage_4 !!! ... message_n
if we try to let syslog-ng write:
message_1 message_2 message_3 message_4 ... message_n
Hi all, We are seeing exactly the same behaviour Andreas described. Actually it works fine until version 1.5.8, but if we use any version >1.5.8, including patched 1.5.19 and 1.5.20, we get lots of mangled messages. So it's not really the same problem that was fixed in 1.5.20. Any ideas? We'd also love to use the latest version and not have to stick to 1.5.8. Thanks in advance, Carlos Inacio. _______________________________________________ syslog-ng maillist - syslog-ng@lists.balabit.hu https://lists.balabit.hu/mailman/listinfo/syslog-ng Frequently asked questions at http://www.campin.net/syslog-ng/faq.html
On Fri, Sep 27, 2002 at 02:47:25PM +0200, Carlos Inacio wrote:
On Fri, Aug 02, 2002 at 05:26:25PM +0200, Andreas Schulze wrote: Hi all,
We are seeing exactly the same behaviour Andreas described. Actually it works fine until version 1.5.8, but if we use any version >1.5.8, including patched 1.5.19 and 1.5.20, we get lots of mangled messages. So it's not really the same problem that was fixed in 1.5.20. Any ideas? We'd also love to use the latest version and not have to stick to 1.5.8.
Thanks in advance,
Without being able to reproduce the bug I _need_ more information. I've checked out the difference between 1.5.20 and 1.5.8 at the time I received the original bug report, but saw no reasons that could cause this problem. What I'd need: 1) the least complex config file that shows the problem 2) strace dump of syslog-ng while receiving this message (only the relevant parts are needed, e.g. the place where syslog-ng receives this message) I suspect syslog-ng gets data fragmented in some way, but as I checked the trivial cases I don't know the real cause. Thanks in advance, -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
Balazs Scheidler wrote:
On Fri, Sep 27, 2002 at 02:47:25PM +0200, Carlos Inacio wrote:
We are seeing exactly the same behaviour Andreas described. Actually it works fine until version 1.5.8, but if we use any version >1.5.8, including patched 1.5.19 and 1.5.20, we get lots of mangled messages.
Without being able to reproduce the bug I _need_ more information. I've checked out the difference between 1.5.20 and 1.5.8 at the time I received the original bug report, but saw no reasons that could cause this problem.
What I'd need: 1) the least complex config file that shows the problem 2) strace dump of syslog-ng while receiving this message (only the relevant parts are needed, e.g. the place where syslog-ng receives this message)
Sorry Balazs, I need a little bit time to set up a development environment to trace and debug this problem. This was a bit more difficult, because the buggy behaviour occurs only on heavy loaded log servers. But now, I think, I know what the real problem is. Let's remember. Using the following pipe() destinations: (need more than one dest() for /tmp/pipe, to tag the msgs based on filters())
destination d_a { pipe("/tmp/pipe" template("@tag_a: | $MSG\n")); }; destination d_b { pipe("/tmp/pipe" template("@tag_b: | $MSG\n")); }; destination d_c { pipe("/tmp/pipe" template("@tag_c: | $MSG\n")); }; destination d_d { pipe("/tmp/pipe" template("@tag_d: | $MSG\n")); }; log { source(..); filter(fa); destination(d_a); }; log { source(..); filter(fb); destination(d_b); }; log { source(..); filter(fb); destination(d_c); }; log { source(..); filter(fb); destination(d_d); };
we get mangled messages in /tmp/pipe, if at least one of the log() paths is heavy loaded. This seems to occur in all versions >1.5.8 truss'ing the process gives the view below. (Each message should begin with a tag <@--?LM-->. This is only for easy get the pipe fd's in truss output.) What happens: write(48, " < @ - - I L M - - @ > ".., 4096) = 4096 [-> Try to write 4096 bytes. Success. No problem. (There are more than one message inside this 4KB)] write(48, " c v / % l o s s = 5".., 4096) = 4096 [-> Try to write the next 4 KBytes. Success. No problem? (WARNING: Because we use a byte buffer instead a line buffer, there is NO tailing '\n' in the pipe now!!)] write(48, " c m p d : | i c m p".., 508) Err#11 EAGAIN [-> Try to write the last bytes. Pipe is bussy. Drop. (Remenber, that there is NO tailing '\n' in the pipe now!!)] write(12, " < @ - - S L M - - @ > ".., 247) Err#11 EAGAIN [-> Try to write bytes from the other log path to the same pipe(). Pipe is bussy. Drop. ] [...] write(20, " < @ - - C L M - - @ > ".., 203) = 203 [-> First successfull attempt to write bytes to the pipe, after the pipe becomes ready again. Success? Yes. No! HERE is the Bug. Here we produce a mangled message because we dropped some stuff and the trailing newline before!] I think, you changed the internal buffering from a line based buffer to byte based buffer between 1.5.8 and 1.5.9. In 1.5.7 there isn't that problem. Maybe, line based buffering seems a better idea in this context. If you need better information, I could send you the complex config and a full truss ouput in private. Hope, this coveres the problem. Because a solution becomes more and more important for us, I hope that you can investigate this and maybe we can discuss a solution. Thanks a lot --Andreas [...] write(48, " < @ - - I L M - - @ > ".., 4096) = 4096 write(48, " c v / % l o s s = 5".., 4096) = 4096 write(48, " i c m p d : | i c m".., 1553) Err#11 EAGAIN write(20, " < @ - - C L M - - @ > ".., 203) Err#11 EAGAIN [...] write(48, " < @ - - I L M - - @ > ".., 4096) = 4096 write(48, " c v / % l o s s = 5".., 4096) = 4096 write(48, " c m p d : | i c m p".., 508) Err#11 EAGAIN write(12, " < @ - - S L M - - @ > ".., 247) Err#11 EAGAIN [...] write(20, " < @ - - C L M - - @ > ".., 203) = 203 write(12, " < @ - - S L M - - @ > ".., 161) = 161 write(52, " < @ - - M L M - - @ > ".., 201) = 201 write(20, " < @ - - C L M - - @ > ".., 259) = 259 write(20, " < @ - - C L M - - @ > ".., 242) = 242 write(12, " < @ - - S L M - - @ > ".., 176) = 176 write(20, " < @ - - C L M - - @ > ".., 204) = 204 write(12, " < @ - - S L M - - @ > ".., 135) = 135 write(48, " < @ - - I L M - - @ > ".., 4096) = 4096 write(48, " n o e r r o r s ] <".., 4096) = 4096 write(48, " s ] < - - E O M - - >".., 4096) Err#11 EAGAIN write(48, " 9 . 7 | A L I V E ".., 4096) Err#11 EAGAIN write(48, " 2 / 2 0 0 2 2 2 : 3 9".., 4096) Err#11 EAGAIN write(48, " | i c m p . b o t .".., 4096) Err#11 EAGAIN write(48, " b o t . n e t : 2 7 /".., 4096) Err#11 EAGAIN write(48, " M - - @ > @ i c m p d".., 4096) Err#11 EAGAIN write(48, " @ i c m p d : | i".., 3436) Err#11 EAGAIN write(27, " < @ - - T L M - - @ > ".., 436) Err#11 EAGAIN write(20, " < @ - - C L M - - @ > ".., 194) Err#11 EAGAIN write(12, " < @ - - S L M - - @ > ".., 2682) Err#11 EAGAIN [...] -- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | | sh# cat>$$.c<<EOT | main(l,a,n,d)char**a;{for(d=atoi(a[1])/10*80-atoi(a[2])/5-596;n="@NK\ | ACLCCGZAAQBEAADAFaISADJABBA^SNLGAQABDAXIMBAACTBATAHDBANZcEMMCCCCAAhE\ | IJFAEAAABAfHJETBdFLDAANEfDNBPHdBcBBBEA_AL H E L L O, W O R L D! " | [l++-3];)for(;n-->64;)putchar(!d+++33^l&1);} | EOT | gcc -o$$ $$.c;clear;./$$ 52 8;rm -f $$*
[...]
What happens:
write(48, " < @ - - I L M - - @ > ".., 4096) = 4096 [-> Try to write 4096 bytes. Success. No problem. (There are more than one message inside this 4KB)] write(48, " c v / % l o s s = 5".., 4096) = 4096 [-> Try to write the next 4 KBytes. Success. No problem? (WARNING: Because we use a byte buffer instead a line buffer, there is NO tailing '\n' in the pipe now!!)] write(48, " c m p d : | i c m p".., 508) Err#11 EAGAIN [-> Try to write the last bytes. Pipe is bussy. Drop.
[...]
I think, you changed the internal buffering from a line based buffer to byte based buffer between 1.5.8 and 1.5.9. In 1.5.7 there isn't that problem. Maybe, line based buffering seems a better idea in this context.
Another possibility is to push buffer back into output queue when write returns EAGAIN/EWOULDBLOCK. It has some potential of blocking output to a single destination, but then if destination cannot accept input anymore, it is probably broken anyway. Messages can be dropped on input side then (i.e. if queue is full, simply no new message is queued for this destination). BTW it looks like syslog-ng makes writes in fixed 4096 buffer length. For pipes it is wrong - system guarantees atomic delivery of a single write up to PIPE_BUF; system is free to reorder parts of any single write with larger size. Portable way to query for PIPE_BUF on modern systems is to use (f)pathconf utility. Regards -andrey
On Sat, Dec 28, 2002 at 10:01:07AM +0300, Borzenkov Andrey wrote:
[...]
What happens:
Another possibility is to push buffer back into output queue when write returns EAGAIN/EWOULDBLOCK. It has some potential of blocking output to a single destination, but then if destination cannot accept input anymore, it is probably broken anyway. Messages can be dropped on input side then (i.e. if queue is full, simply no new message is queued for this destination).
This was the indented behaviour and the patch I sent in my previous mail does this.
BTW it looks like syslog-ng makes writes in fixed 4096 buffer length. For pipes it is wrong - system guarantees atomic delivery of a single write up to PIPE_BUF; system is free to reorder parts of any single write with larger size. Portable way to query for PIPE_BUF on modern systems is to use (f)pathconf utility.
I don't understand you here. You mean that chunks of data written are reordered, or if there is multiple write()-s to the same pipe then those may get reordered? I've found this comment by googling though (it is a release notes of a rewritten pipe implementation for Linux): ---- * No single copy for exactly 4096 byte writes, only > PIPE_BUF. Single copy (and thus blocking) such writes could trigger bugs in user space apps that errorneously assume that a pipe write of PIPE_BUF bytes after a successful poll(POLLOUT) doesn't block even if O_NONBLOCK is not set. It's not defined in posix or susv2, but no unix version I tested blocks in such writes. ---- BTW: syslog-ng puts the pipe fd in nonblocking mode, so if the chunk is too large, write() should simply indicate that fewer bytes was written than originally asked to. -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
BTW it looks like syslog-ng makes writes in fixed 4096 buffer length. For pipes it is wrong - system guarantees atomic delivery of a single write up to PIPE_BUF; system is free to reorder parts of any single write with larger size. Portable way to query for PIPE_BUF on modern systems is to use (f)pathconf utility.
I don't understand you here. You mean that chunks of data written are reordered, or if there is multiple write()-s to the same pipe then those may get reordered?
Eh ... sorry, I swear I have seen it somewhere but cannot find it. In those documents I have now PIPE_BUF applies just to cases of several processes writing to the same pipe. So the only case it may cause a problem is when syslog-ng is not the only one writing to pipe. -andrey
Balazs Scheidler wrote:
On Sat, Dec 28, 2002 at 10:01:07AM +0300, Borzenkov Andrey wrote:
Another possibility is to push buffer back into output queue when write returns EAGAIN/EWOULDBLOCK. It has some potential of blocking output to a single destination, but then if destination cannot accept input anymore, it is probably broken anyway. Messages can be dropped on input side then (i.e. if queue is full, simply no new message is queued for this destination).
This was the indented behaviour and the patch I sent in my previous mail does this.
Sounds good. This is the other solution. I'll try the patch out. Thanks a lot for it. But here are two questions for this: - file() destinations have a feature (log_fifo_size()), that allows configuration of output queue. Seems, this's a good feature for pipe() destinations, too? - But, the more important... As you say above, if the output queue is full, syslog-ng drops on the input side. But we must ensure, that _exactly_ whole messages are dropped or queued, regardless of the available queue size in bytes. This is what I meant with line based queuing. We shouldn't forget over all the I/O buffering, that our basic data structure is a newline terminated syslog message.
BTW it looks like syslog-ng makes writes in fixed 4096 buffer length. For pipes it is wrong - system guarantees atomic delivery of a single write up to PIPE_BUF; system is free to reorder parts of any single write with larger size. Portable way to query for PIPE_BUF on modern systems is to use (f)pathconf utility.
Yepp. PIPE_BUF is 4KB on linux, but 5KB on Solaris (See limits(4)). So, to ensure an atomic write(2) on Solaris, you can safely use a 5k buffer.
BTW: syslog-ng puts the pipe fd in nonblocking mode, so if the chunk is too large, write() should simply indicate that fewer bytes was written than originally asked to.
Yes. Its the usual way, use only atomic write(2) with <=PIPE_BUF on nonblocking pipes, to avoid all the stuff that can happen, if only parts of the buffer are written to the fd. -- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | | sh# cat>$$.c<<EOT | main(l,a,n,d)char**a;{for(d=atoi(a[1])/10*80-atoi(a[2])/5-596;n="@NK\ | ACLCCGZAAQBEAADAFaISADJABBA^SNLGAQABDAXIMBAACTBATAHDBANZcEMMCCCCAAhE\ | IJFAEAAABAfHJETBdFLDAANEfDNBPHdBcBBBEA_AL H E L L O, W O R L D! " | [l++-3];)for(;n-->64;)putchar(!d+++33^l&1);} | EOT | gcc -o$$ $$.c;clear;./$$ 52 8;rm -f $$*
On Mon, Dec 30, 2002 at 06:22:36PM +0100, Andreas Schulze wrote:
Balazs Scheidler wrote:
On Sat, Dec 28, 2002 at 10:01:07AM +0300, Borzenkov Andrey wrote:
- file() destinations have a feature (log_fifo_size()), that allows configuration of output queue. Seems, this's a good feature for pipe() destinations, too?
This problem is solved for syslog-ng 2 where all the common parameters are parsed once. It is of course possible to add parameters like this to all drivers but is a bit more difficult in 1.5.x.
- But, the more important... As you say above, if the output queue is full, syslog-ng drops on the input side. But we must ensure, that _exactly_ whole messages are dropped or queued, regardless of the available queue size in bytes. This is what I meant with line based queuing. We shouldn't forget over all the I/O buffering, that our basic data structure is a newline terminated syslog message.
the buffering itself is message based (log_fifo_size specifies the buffer measured in messages not in bytes). The final I/O buffer is used to prevent writing messages in multiple write() calls. Instead a buffer is filled (4kB) and is written as a single chunk.
BTW it looks like syslog-ng makes writes in fixed 4096 buffer length. For pipes it is wrong - system guarantees atomic delivery of a single write up to PIPE_BUF; system is free to reorder parts of any single write with larger size. Portable way to query for PIPE_BUF on modern systems is to use (f)pathconf utility.
Yepp. PIPE_BUF is 4KB on linux, but 5KB on Solaris (See limits(4)). So, to ensure an atomic write(2) on Solaris, you can safely use a 5k buffer.
BTW: syslog-ng puts the pipe fd in nonblocking mode, so if the chunk is too large, write() should simply indicate that fewer bytes was written than originally asked to.
Yes. Its the usual way, use only atomic write(2) with <=PIPE_BUF on nonblocking pipes, to avoid all the stuff that can happen, if only parts of the buffer are written to the fd.
syslog-ng handles the cases when write() is not atomic. So this is a non-issue. The value of 4096 bytes might not be the best but syslog-ng should work regardless the actual value of PIPE_BUF. -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
On Sat, Dec 28, 2002 at 12:05:12AM +0100, Andreas Schulze wrote:
Balazs Scheidler wrote:
On Fri, Sep 27, 2002 at 02:47:25PM +0200, Carlos Inacio wrote:
I think, you changed the internal buffering from a line based buffer to byte based buffer between 1.5.8 and 1.5.9. In 1.5.7 there isn't that problem. Maybe, line based buffering seems a better idea in this context.
If you need better information, I could send you the complex config and a full truss ouput in private.
Hope, this coveres the problem.
Because a solution becomes more and more important for us, I hope that you can investigate this and maybe we can discuss a solution.
Thanks for the detailed report. I think I have found the problem this time. Can you check this patch? Index: pkt_buffer.c =================================================================== RCS file: /var/cvs/syslog-ng/libol/src/pkt_buffer.c,v retrieving revision 1.15 diff -u -r1.15 pkt_buffer.c --- pkt_buffer.c 18 Dec 2002 12:40:28 -0000 1.15 +++ pkt_buffer.c 28 Dec 2002 09:53:00 -0000 @@ -132,7 +132,7 @@ if (self->super.writable) (*self->super.writable) = 1; } - else if (res != 0) { + else { /* this is slow, because of another memory move * but this is run rarely anyway */ struct buffer_node *item; -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
Balazs Scheidler wrote:
On Sat, Dec 28, 2002 at 12:05:12AM +0100, Andreas Schulze wrote:
Balazs Scheidler wrote:
On Fri, Sep 27, 2002 at 02:47:25PM +0200, Carlos Inacio wrote:
I think, you changed the internal buffering from a line based buffer to byte based buffer between 1.5.8 and 1.5.9. In 1.5.7 there isn't that problem. Maybe, line based buffering seems a better idea in this context.
Hope, this coveres the problem.
Thanks for the detailed report. I think I have found the problem this time. Can you check this patch?
Yepp. We try it out as soon as possible. Thanks a lot for the patch.
Index: pkt_buffer.c =================================================================== RCS file: /var/cvs/syslog-ng/libol/src/pkt_buffer.c,v retrieving revision 1.15 diff -u -r1.15 pkt_buffer.c --- pkt_buffer.c 18 Dec 2002 12:40:28 -0000 1.15 +++ pkt_buffer.c 28 Dec 2002 09:53:00 -0000 @@ -132,7 +132,7 @@ if (self->super.writable) (*self->super.writable) = 1; } - else if (res != 0) { + else { /* this is slow, because of another memory move * but this is run rarely anyway */ struct buffer_node *item;
-- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | | sh# cat>$$.c<<EOT | main(l,a,n,d)char**a;{for(d=atoi(a[1])/10*80-atoi(a[2])/5-596;n="@NK\ | ACLCCGZAAQBEAADAFaISADJABBA^SNLGAQABDAXIMBAACTBATAHDBANZcEMMCCCCAAhE\ | IJFAEAAABAfHJETBdFLDAANEfDNBPHdBcBBBEA_AL H E L L O, W O R L D! " | [l++-3];)for(;n-->64;)putchar(!d+++33^l&1);} | EOT | gcc -o$$ $$.c;clear;./$$ 52 8;rm -f $$*
Hello Balazs,
Balazs Scheidler wrote:
I think, you changed the internal buffering from a line based buffer to byte based buffer between 1.5.8 and 1.5.9. In 1.5.7 there isn't that problem. Maybe, line based buffering seems a better idea in this context.
Thanks for the detailed report. I think I have found the problem this time. Can you check this patch?
I checked the patch. Using patched libol-0.3.6 and syslog-ng-1.5.24. It solves the message drops in pipes(). Thanks a lot for this. But it seems, it doesn't solve the mangled messages problem. :( I try to explain it. Look at the following truss output. (Remember, that we use several log path's pointing to the same pipe(), so all fd's (13,18,24,41,54) points to /tmp/pipe e.g. fd 41 is the heavy loaded path and caused the EAGAIN's.) [...] write(41, " < @ - - I L M - - @ > ".., 4096) = 4096 write(41, " r c v / % l o s s = ".., 3562) Err#11 EAGAIN (Can't write to /tmp/pipe. Ok. We are buffered now. Thanks for your patch :) [...] write(41, " r c v / % l o s s = ".., 4096) = 4096 (Here we see, that we are buffered.) write(41, " : | i c m p . b o t".., 4096) = 4096 write(41, " a v g / m a x = 9 .".., 4096) = 4096 (Successfull. But we really NEED a trailing newline. Why? See below.) write(41, " 0 2 / 0 1 / 2 0 0 3 1".., 2923) Err#11 EAGAIN (/tmp/pipe isn't available. Ok. We are buffered. No problem?) write(13, " < @ - - C L M - - @ > ".., 490) Err#11 EAGAIN [...] write(54, " < @ - - T L M - - @ > ".., 721) = 721 (Shit. Here is the problem. We produced a mangled message. Because the last successfull write(2) (to fd 41) used a byte buffer.) write(41, " 0 2 / 0 1 / 2 0 0 3 1".., 4096) = 4096 write(41, " 4 . 7 0 / 5 . 0 3 / 5 .".., 4096) Err#11 EAGAIN write(18, " < @ - - S L M - - @ > ".., 315) Err#11 EAGAIN write(13, " < @ - - C L M - - @ > ".., 490) Err#11 EAGAIN [...] write(41, " 4 . 7 0 / 5 . 0 3 / 5 .".., 4096) = 4096 write(41, " < @ - - I L M - - @ > ".., 4096) = 4096 write(41, " l o s s = 5 / 5 / 0".., 4096) Err#11 EAGAIN write(18, " < @ - - S L M - - @ > ".., 630) Err#11 EAGAIN write(13, " < @ - - C L M - - @ > ".., 490) Err#11 EAGAIN [...] write(54, " < @ - - T L M - - @ > ".., 436) = 436 write(41, " l o s s = 5 / 5 / 0".., 4096) = 4096 (And here is the other problem. We produce a mangled message. Because the write to fd 41 doesn't start at the message boundary.) write(41, " < @ - - I L M - - @ > ".., 4096) Err#11 EAGAIN write(18, " < @ - - S L M - - @ > ".., 630) Err#11 EAGAIN write(13, " < @ - - C L M - - @ > ".., 490) Err#11 EAGAIN [...] ---------- I think its important, that the final chunk to write(2), is oriented on the message boundaries. Means, that the buffer should start with the beginning of a logline and ends with the terminating newline of the same/other/next logline. ---------- I hope, I made the problem more transparent and will be happy, if a patch is easily possible. Maybe there is a better solution. Thanks a lot for your feedback. -- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | | sh# cat>$$.c<<EOT | main(l,a,n,d)char**a;{for(d=atoi(a[1])/10*80-atoi(a[2])/5-596;n="@NK\ | ACLCCGZAAQBEAADAFaISADJABBA^SNLGAQABDAXIMBAACTBATAHDBANZcEMMCCCCAAhE\ | IJFAEAAABAfHJETBdFLDAANEfDNBPHdBcBBBEA_AL H E L L O, W O R L D! " | [l++-3];)for(;n-->64;)putchar(!d+++33^l&1);} | EOT | gcc -o$$ $$.c;clear;./$$ 52 8;rm -f $$*
On Thu, Jan 02, 2003 at 07:11:59PM +0100, Andreas Schulze wrote:
Hello Balazs,
Balazs Scheidler wrote:
I think, you changed the internal buffering from a line based buffer to byte based buffer between 1.5.8 and 1.5.9. In 1.5.7 there isn't that problem. Maybe, line based buffering seems a better idea in this context.
Thanks for the detailed report. I think I have found the problem this time. Can you check this patch?
I checked the patch. Using patched libol-0.3.6 and syslog-ng-1.5.24. It solves the message drops in pipes(). Thanks a lot for this. But it seems, it doesn't solve the mangled messages problem. :(
I try to explain it. Look at the following truss output. (Remember, that we use several log path's pointing to the same pipe(), so all fd's (13,18,24,41,54) points to /tmp/pipe e.g. fd 41 is the heavy loaded path and caused the EAGAIN's.)
Hmm... I see.. You should not point multiple destinations to the same pipe. As each destination has its own buffer. Is it not possible to separate the pipe to a single destination? I'm thinking about the possibility of destination references, would that solve your problem? -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
Balazs Scheidler wrote:
Thanks for the detailed report. I think I have found the problem this time. Can you check this patch?
I try to explain it. Look at the following truss output. (Remember, that we use several log path's pointing to the same pipe(), so all fd's (13,18,24,41,54) points to /tmp/pipe e.g. fd 41 is the heavy loaded path and caused the EAGAIN's.)
Hmm... I see.. You should not point multiple destinations to the same pipe. As each destination has its own buffer. Is it not possible to separate the pipe to a single destination?
Unfortunately no. One of the great features of syslog-ng we need, are the mighty filter capabilities. We use filters, to let syslog-ng classify some types of messages, add a 'class' tag (based on a special filter) to the message and send it to a pipe. Imagine the following example config. I hope it illustrates, what we are doing. destination d_a { pipe("/tmp/pipe" template("@TAG_A: | $MSG\n")); }; destination d_b { pipe("/tmp/pipe" template("@TAG_B: | $MSG\n")); }; destination d_c { pipe("/tmp/pipe" template("@TAG_C: | $MSG\n")); }; destination d_d { pipe("/tmp/pipe" template("@TAG_D: | $MSG\n")); }; log { source(..); filter(fa); destination(d_a); }; log { source(..); filter(fb); destination(d_b); }; log { source(..); filter(fc); destination(d_c); }; log { source(..); filter(fd); destination(d_d); }; We have to do this tagging/filtering via syslog-ng for the following reasons: - syslog-ng does this very fast and excellent - the applications that reads the pipe is commercial software and doesn't have such great filter caps. - a 'middle ware' filter (a special script/program/etc.) isn't fast enough for us, because we are handling millions of messages per hour/day by this way via syslog-ng - and last but not least, this filtering is very easy and handy to configure and to implement using syslog-ng Maybe, you have some ideas, for a better way, to do this.
I'm thinking about the possibility of destination references, would that solve your problem?
Sorry. I don't understand. I'm not sure, that this solves our problem. Can you explain 'destination references' a little bit, please. Thanks a lot for your feedback. -- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | | sh# cat>$$.c<<EOT | main(l,a,n,d)char**a;{for(d=atoi(a[1])/10*80-atoi(a[2])/5-596;n="@NK\ | ACLCCGZAAQBEAADAFaISADJABBA^SNLGAQABDAXIMBAACTBATAHDBANZcEMMCCCCAAhE\ | IJFAEAAABAfHJETBdFLDAANEfDNBPHdBcBBBEA_AL H E L L O, W O R L D! " | [l++-3];)for(;n-->64;)putchar(!d+++33^l&1);} | EOT | gcc -o$$ $$.c;clear;./$$ 52 8;rm -f $$*
On Fri, Jan 03, 2003 at 03:29:38PM +0100, Andreas Schulze wrote:
Balazs Scheidler wrote:
Hmm... I see.. You should not point multiple destinations to the same pipe. As each destination has its own buffer. Is it not possible to separate the pipe to a single destination?
Unfortunately no. One of the great features of syslog-ng we need, are the mighty filter capabilities. We use filters, to let syslog-ng classify some types of messages, add a 'class' tag (based on a special filter) to the message and send it to a pipe. Imagine the following example config. I hope it illustrates, what we are doing.
destination d_a { pipe("/tmp/pipe" template("@TAG_A: | $MSG\n")); }; destination d_b { pipe("/tmp/pipe" template("@TAG_B: | $MSG\n")); }; destination d_c { pipe("/tmp/pipe" template("@TAG_C: | $MSG\n")); }; destination d_d { pipe("/tmp/pipe" template("@TAG_D: | $MSG\n")); }; log { source(..); filter(fa); destination(d_a); }; log { source(..); filter(fb); destination(d_b); }; log { source(..); filter(fc); destination(d_c); }; log { source(..); filter(fd); destination(d_d); }; ...
I'm thinking about the possibility of destination references, would that solve your problem?
Sorry. I don't understand. I'm not sure, that this solves our problem. Can you explain 'destination references' a little bit, please.
looking at your above example, destination references will not be a solution. I meant something like this: destination d_pipe { pipe("/tmp/pipe" template("xxx")); }; destination d_another { destination("d_pipe"); }; so the messages sent to d_another would also go to d_pipe. I will try to think about your problem a bit. ... It is not easy to implement, I'd need to share the destination fd & write buffers between multiple, independent destination drivers... It was not meant to be working the way you used in earlier versions either, the fact it worked was only a coincidence. I would do something with macro expansion instead, it would only need a couple of user changeable variables, like: destination d_pipe { pipe("/tmp/pipe template("$IDSTAG $MSG")); }; log { source(...); filter(...); variable("IDSTAG", "CAT_A"); destination(d_pipe); }; But what happens when multiple destinations match? Are those variables combined, or they are cleared for each log rule, or? my syslog-ng tree makes it possible to match parts of messages and reference those as $1 .. $9 in template expansions. But those variables are cleared after every match(). -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
Balazs Scheidler wrote:
destination d_a { pipe("/tmp/pipe" template("@TAG_A: | $MSG\n")); }; destination d_b { pipe("/tmp/pipe" template("@TAG_B: | $MSG\n")); }; log { source(..); filter(fa); destination(d_a); }; log { source(..); filter(fb); destination(d_b); };
It is not easy to implement, I'd need to share the destination fd & write buffers between multiple, independent destination drivers...
Why to share buffers? For me it seems, that's only necessary to preserve message boundaries in all the final output buffers. So, no buffer handling change is required. Only the content of the buffers need to be adapted. This would solve the direct cause of the problem. And it would increase data integrity, too. Last but not least, it would solve the problem for all other destinations (e.g. AF_LOCAL sockets) But, maybe I'm wrong, because I'm not very familiar with your code.
I would do something with macro expansion instead, it would only need a couple of user changeable variables, like:
destination pipe { pipe("/tmp/pipe" template("$ID_TAG: | $MSG\n")); }; log { .. variable("ID_TAG", "TAG_A"); destination(pipe); }; log { .. variable("ID_TAG", "TAG_B"); destination(pipe); };
But what happens when multiple destinations match? Are those variables combined, or they are cleared for each log rule, or?
Sounds great! This would solve our problem, I think. Thanks! Ok. Combined vars are not a good idea. What should happen in the above example, if both log paths match? I think, the message should logged twice, once with TAG_A and once with TAG_B. If this means 'cleared for each log rule', this's the best idea. Two other (more cosmetically) questions are, what happens in the examples below? Configuration errors? destination pipe { pipe("/tmp/pipe" template("$ID_TAG: | $MSG\n")); }; log { .. variable("ID_TAG", "TAG_A"); destination(pipe); }; log { .. variable("ID_TAG_UNUSED", "TAG_B"); destination(pipe); }; (both log paths matches, but there is a variable, that's never referenced in a destination) and destination pipe { pipe("/tmp/pipe" template("$T_UNDEF: | $MSG\n")); }; log { .. variable("ID_TAG", "TAG_A"); destination(pipe); }; log { .. variable("ID_TAG", "TAG_B"); destination(pipe); }; (there is a var reference, that's never defined in a log path)
my syslog-ng tree makes it possible to match parts of messages and reference those as $1 .. $9 in template expansions. But those variables are cleared after every match().
Sounds like a very nice feature. But it's not usable in our context. We need definable tags. ($1..$n references depends on message content) Thanks a lot for feedback. -- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | http://www.ioccc.org/1990/dds.c
On Fri, Jan 03, 2003 at 06:08:10PM +0100, Balazs Scheidler wrote:
On Fri, Jan 03, 2003 at 03:29:38PM +0100, Andreas Schulze wrote:
Balazs Scheidler wrote: I'm thinking about the possibility of destination references, would that solve your problem?
Sorry. I don't understand. I'm not sure, that this solves our problem. Can you explain 'destination references' a little bit, please.
looking at your above example, destination references will not be a solution. I meant something like this:
destination d_pipe { pipe("/tmp/pipe" template("xxx")); };
destination d_another { destination("d_pipe"); };
so the messages sent to d_another would also go to d_pipe.
I will try to think about your problem a bit. ...
It is not easy to implement, I'd need to share the destination fd & write buffers between multiple, independent destination drivers...
It was not meant to be working the way you used in earlier versions either, the fact it worked was only a coincidence.
Syslog-ng 1.5.26 (libol 0.3.9 to be exact) reverts to message based buffering for pipes, so it should work for you again. -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
Balazs Scheidler wrote:
On Fri, Jan 03, 2003 at 06:08:10PM +0100, Balazs Scheidler wrote:
On Fri, Jan 03, 2003 at 03:29:38PM +0100, Andreas Schulze wrote:
>Balazs Scheidler wrote:
I'm thinking about the possibility of destination references, would that solve your problem?
Sorry. I don't understand. I'm not sure, that this solves our problem. Can you explain 'destination references' a little bit, please.
looking at your above example, destination references will not be a solution. I meant something like this:
destination d_pipe { pipe("/tmp/pipe" template("xxx")); };
destination d_another { destination("d_pipe"); };
so the messages sent to d_another would also go to d_pipe.
I will try to think about your problem a bit. ...
It is not easy to implement, I'd need to share the destination fd & write buffers between multiple, independent destination drivers...
It was not meant to be working the way you used in earlier versions either, the fact it worked was only a coincidence.
Syslog-ng 1.5.26 (libol 0.3.9 to be exact) reverts to message based buffering for pipes, so it should work for you again.
Great. Thanks a lot. We will try it out and give feedback asap. -- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | http://www.ioccc.org/1990/dds.c
Balazs Scheidler wrote:
I'm thinking about the possibility of destination references, would that solve your problem?
Sorry. I don't understand. I'm not sure, that this solves our problem. Can you explain 'destination references' a little bit, please.
looking at your above example, destination references will not be a solution. I meant something like this:
destination d_pipe { pipe("/tmp/pipe" template("xxx")); };
destination d_another { destination("d_pipe"); };
so the messages sent to d_another would also go to d_pipe.
I will try to think about your problem a bit. ...
It is not easy to implement, I'd need to share the destination fd & write buffers between multiple, independent destination drivers...
It was not meant to be working the way you used in earlier versions either, the fact it worked was only a coincidence.
Syslog-ng 1.5.26 (libol 0.3.9 to be exact) reverts to message based buffering for pipes, so it should work for you again.
Great! Thanks a lot. Both (message based buffering and message queueing in case of EAGAIN) works pretty good. We moved it today to our production env. Seems that the problem is solved in a common and good way. Thanks. Is it avaiable in the 1.6.x branch, too? As far as I know 1.6.0 use libol-0.3.9, too. -- Best regards --Andreas Schulze [phone: +49.5246.80.1275, fax: +49.5246.80.2275] | I believe, it was Dennis Ritchie who said something like: | "C is rarely the best language for a given task, | but it's often the second-best". | The implication being that: "[...]" | http://www.ioccc.org/1990/dds.c
participants (6)
-
_/CaT\_
-
Andreas Schulze
-
Andreas Schulze
-
Balazs Scheidler
-
Borzenkov Andrey
-
Carlos Inacio