Re: junk at end of syslog packets in 1.5dev19
On Fri, Aug 30, 2013 at 02:43:03PM +0200, William Lallemand wrote: > On Thu, Aug 29, 2013 at 10:50:09PM +0200, Lukas Tribus wrote: > > The behavior also depends on the syslog facility; I used "syslog" in my > > tests. > > > > > > With the current git tree I see the following behavior: > > ntp and local7: syslog ends with \n <-- correct behavior! > > ftp and user: syslog ends with \n + 2 random characters > > kern: syslog ends with \n + 4 random characters > > > > It seems 2a4a44f0f9f caused the initial problem and bfb099c3b3f1 amplified > > it. > > > > > > > > Regards, > > > > Lukas > > Hello Lukas, > > Thanks for your analyze, the bug was indeed caused by the number of digits in > the facility. > > Here's a patch with the real size to send :) Applied, thanks! Willy
RE: junk at end of syslog packets in 1.5dev19
> Hello Lukas, > > Thanks for your analyze, the bug was indeed caused by the number of digits in > the facility. > > Here's a patch with the real size to send :) Thanks, I confirm it fixes the problem. Regards, Lukas
Re: junk at end of syslog packets in 1.5dev19
On Thu, Aug 29, 2013 at 10:50:09PM +0200, Lukas Tribus wrote:
> The behavior also depends on the syslog facility; I used "syslog" in my tests.
>
>
> With the current git tree I see the following behavior:
> ntp and local7: syslog ends with \n <-- correct behavior!
> ftp and user: syslog ends with \n + 2 random characters
> kern: syslog ends with \n + 4 random characters
>
> It seems 2a4a44f0f9f caused the initial problem and bfb099c3b3f1 amplified it.
>
>
>
> Regards,
>
> Lukas
Hello Lukas,
Thanks for your analyze, the bug was indeed caused by the number of digits in
the facility.
Here's a patch with the real size to send :)
--
William Lallemand
>From fcf527a2c629b696e8e2fa2993feb5be90b9ef04 Mon Sep 17 00:00:00 2001
From: William Lallemand
Date: Fri, 30 Aug 2013 14:17:46 +0200
Subject: [PATCH] BUG/MINOR: log: junk at the end of syslog packet
With a facily of 2 or 1 digit, the send size was wrong and bytes with
unknown value were sent.
The size was calculated using the start of the buffer and not the start
of the data which varies with the number of digits of the facility.
This bug was reported by Samuel Stoller and reported by Lukas Tribus.
---
src/log.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/log.c b/src/log.c
index 369dc34..ad9fa73 100644
--- a/src/log.c
+++ b/src/log.c
@@ -847,7 +847,7 @@ void __send_log(struct proxy *p, int level, char *message, size_t size)
} while (fac_level && log_ptr > dataptr);
*log_ptr = '<';
- sent = sendto(*plogfd, log_ptr, size + log_ptr - dataptr,
+ sent = sendto(*plogfd, log_ptr, size - (log_ptr - dataptr),
MSG_DONTWAIT | MSG_NOSIGNAL,
(struct sockaddr *)&logsrv->addr, get_addr_len(&logsrv->addr));
if (sent < 0) {
--
1.8.1.5
RE: junk at end of syslog packets in 1.5dev19
Hi William, (apologies for the high volume in this thread) > haproxy 1.4 and pre 2a4a44f0f9f behavior (expected): > every syslog message ends with \n > > post 2a4a44f0f9f (REORG: log: split send_log function) behavior: > every syslog message ends with \n + 1 random character > > post bfb099c3b3f1 (BUG/MEDIUM: bad length in log_format and __send_log) > behavior: > every syslog message ends with \n + 2 random characters (usually \n, \0 or ") The behavior also depends on the syslog facility; I used "syslog" in my tests. With the current git tree I see the following behavior: ntp and local7: syslog ends with \n <-- correct behavior! ftp and user: syslog ends with \n + 2 random characters kern: syslog ends with \n + 4 random characters It seems 2a4a44f0f9f caused the initial problem and bfb099c3b3f1 amplified it. Regards, Lukas
RE: junk at end of syslog packets in 1.5dev19
Hi William, sorry, there is another commit involved here. This is what I see: haproxy 1.4 and pre 2a4a44f0f9f behavior (expected): every syslog message ends with \n post 2a4a44f0f9f (REORG: log: split send_log function) behavior: every syslog message ends with \n + 1 random character post bfb099c3b3f1 (BUG/MEDIUM: bad length in log_format and __send_log) behavior: every syslog message ends with \n + 2 random characters (usually \n, \0 or ") Regards, Lukas
RE: junk at end of syslog packets in 1.5dev19
Hi William, > I can't reproduce the bug, how did you compile HAProxy? > What is your configuration file? I've trimmed this down to a very basic setup: $ make TARGET=linux26 CPU=native $ ./haproxy -vv HA-Proxy version 1.5-dev19-55 2013/08/13 Copyright 2000-2013 Willy Tarreau Build options : TARGET = linux26 CPU = native CC = gcc CFLAGS = -O2 -march=native -g -fno-strict-aliasing OPTIONS = Default settings : maxconn = 2000, bufsize = 16384, maxrewrite = 8192, maxpollevents = 200 Encrypted password support via crypt(3): yes Built without zlib support (USE_ZLIB not set) Compression algorithms supported : identity Built without OpenSSL support (USE_OPENSSL not set) Built without PCRE support (using libc's regex instead) Built with transparent proxy support using: IP_TRANSPARENT IP_FREEBIND Available polling systems : epoll : pref=300, test result OK poll : pref=200, test result OK select : pref=150, test result OK Total: 3 (3 usable), will use epoll. config: global log 10.0.0.3 syslog debug frontend myfrontend bind :::80 option httplog log global default_backend mybackend backend mybackend mode http server s3 10.0.0.3:80 source 10.0.0.84 Regards, Lukas
Re: junk at end of syslog packets in 1.5dev19
On Thu, Aug 22, 2013 at 10:18:46AM +0200, Lukas Tribus wrote: > > Is this happen randomly or can you pin point this to specifc requests, maybe > > errors/timeouts? How can we reproduce this? > > Nevermind, its easily reproducible (just generate some syslog messages). > > The whole thing seems random: most of the times, the syslog msg ends > with \n\0\0, other times with \n\n\0 or even \n"\n. > > > I've tracked this down to: > Hello, I can't reproduce the bug, how did you compile HAProxy? What is your configuration file? Thanks, -- William Lallemand
RE: junk at end of syslog packets in 1.5dev19
> Is this happen randomly or can you pin point this to specifc requests, maybe > errors/timeouts? How can we reproduce this? Nevermind, its easily reproducible (just generate some syslog messages). The whole thing seems random: most of the times, the syslog msg ends with \n\0\0, other times with \n\n\0 or even \n"\n. I've tracked this down to: 2a4a44f0f9f08d130a9a7211746728c38f670032 is the first bad commit commit 2a4a44f0f9f08d130a9a7211746728c38f670032 Author: William Lallemand Date: Mon Feb 6 16:00:33 2012 +0100 REORG: log: split send_log function Heres a tcpdump output: 10:11:45.854741 IP 10.0.0.55.39079> 10.0.0.3.514: SYSLOG syslog.notice, length: 64 0x: 4500 005c 4000 4011 2658 0a00 0037 E..\..@.@.&X...7 0x0010: 0a00 0003 98a7 0202 0048 1493 3c34 353e .H..<45> 0x0020: 4175 6720 3232 2031 303a 3131 3a34 3520 Aug.22.10:11:45. 0x0030: 6861 7072 6f78 795b 3135 3034 315d 3a20 haproxy[15041]:. 0x0040: 5072 6f78 7920 6d79 6672 6f6e 7465 6e64 Proxy.myfrontend 0x0050: 2073 7461 7274 6564 2e0a .started 10:11:50.113766 IP 10.0.0.55.39079> 10.0.0.3.514: SYSLOG syslog.info, length: 170 0x: 4500 00c6 4000 4011 25ee 0a00 0037 E.@.@.%7 0x0010: 0a00 0003 98a7 0202 00b2 14fd 3c34 363e <46> 0x0020: 4175 6720 3232 2031 303a 3131 3a35 3020 Aug.22.10:11:50. 0x0030: 6861 7072 6f78 795b 3135 3034 315d 3a20 haproxy[15041]:. 0x0040: 3a3a 3a31 302e 302e 302e 333a :::10.0.0.3: 0x0050: 3536 3437 3020 5b32 322f 4175 672f 3230 56470.[22/Aug/20 0x0060: 3133 3a31 303a 3131 3a35 302e 3130 385d 13:10:11:50.108] 0x0070: 206d 7966 726f 6e74 656e 6420 6d79 6261 .myfrontend.myba 0x0080: 636b 656e 642f 7333 2030 2f30 2f30 2f34 ckend/s3.0/0/0/4 0x0090: 2f34 2034 3034 2031 3434 3320 2d20 2d20 /4.404.1443.-.-. 0x00a0: 2d2d 2d2d 2031 2f31 2f30 2f30 2f30 2030 .1/1/0/0/0.0 0x00b0: 2f30 2022 4745 5420 2f20 4854 5450 2f31 /0."GET./.HTTP/1 0x00c0: 2e31 220a .1"... 10:11:53.595881 IP 10.0.0.55.39079> 10.0.0.3.514: SYSLOG syslog.info, length: 171 0x: 4500 00c7 4000 4011 25ed 0a00 0037 E.@.@.%7 0x0010: 0a00 0003 98a7 0202 00b3 14fe 3c34 363e <46> 0x0020: 4175 6720 3232 2031 303a 3131 3a35 3320 Aug.22.10:11:53. 0x0030: 6861 7072 6f78 795b 3135 3034 315d 3a20 haproxy[15041]:. 0x0040: 3a3a 3a31 302e 302e 302e 333a :::10.0.0.3: 0x0050: 3536 3437 3120 5b32 322f 4175 672f 3230 56471.[22/Aug/20 0x0060: 3133 3a31 303a 3131 3a35 332e 3538 315d 13:10:11:53.581] 0x0070: 206d 7966 726f 6e74 656e 6420 6d79 6261 .myfrontend.myba 0x0080: 636b 656e 642f 7333 2039 2f30 2f31 2f34 ckend/s3.9/0/1/4 0x0090: 2f31 3420 3430 3420 3134 3433 202d 202d /14.404.1443.-.- 0x00a0: 202d 2d2d 2d20 312f 312f 302f 312f 3020 ..1/1/0/1/0. 0x00b0: 302f 3020 2247 4554 202f 2048 5454 502f 0/0."GET./.HTTP/ 0x00c0: 312e 3122 0a00 00 1.1"... 10:11:57.830360 IP 10.0.0.55.39079> 10.0.0.3.514: SYSLOG syslog.info, length: 170 0x: 4500 00c6 4000 4011 25ee 0a00 0037 E.@.@.%7 0x0010: 0a00 0003 98a7 0202 00b2 14fd 3c34 363e <46> 0x0020: 4175 6720 3232 2031 303a 3131 3a35 3720 Aug.22.10:11:57. 0x0030: 6861 7072 6f78 795b 3135 3034 315d 3a20 haproxy[15041]:. 0x0040: 3a3a 3a31 302e 302e 302e 333a :::10.0.0.3: 0x0050: 3536 3437 3220 5b32 322f 4175 672f 3230 56472.[22/Aug/20 0x0060: 3133 3a31 303a 3131 3a35 372e 3832 365d 13:10:11:57.826] 0x0070: 206d 7966 726f 6e74 656e 6420 6d79 6261 .myfrontend.myba 0x0080: 636b 656e 642f 7333 2030 2f30 2f30 2f33 ckend/s3.0/0/0/3 0x0090: 2f33 2034 3034 2031 3434 3320 2d20 2d20 /3.404.1443.-.-. 0x00a0: 2d2d 2d2d 2031 2f31 2f30 2f31 2f30 2030 .1/1/0/1/0.0 0x00b0: 2f30 2022 4745 5420 2f20 4854 5450 2f31 /0."GET./.HTTP/1 0x00c0: 2e31 220a 0a00 .1"... 10:12:05.793157 IP 10.0.0.55.39079> 10.0.0.3.514: SYSLOG syslog.info, length: 170 0x: 4500 00c6 4000 4011 25ee 0a00 0037 E.@.@.%7 0x0010: 0a00 0003 98a7 0202 00b2 14fd 3c34 363e <46> 0x0020: 4175 6720 3232 2031 303a 3132 3a30 3520 Aug.22.10:12:05. 0x0030: 6861 7072 6f78 795b 3135 3034 315d 3a20 haproxy[15041]:. 0x0040: 3a3a 3a31 302e 302e 302e 333a :::10.0.0.3: 0x0050: 3536 3437 3320 5b32 322f 4175 672f 3230 56473.[22/Aug/20 0x0060: 3133 3a31 303a 3132 3a30 352e 3738 385d 13:10:12:05.788] 0x0070: 206d 7966 726f 6e74 656e 6420 6d79 6261 .myfrontend.myba 0x0080: 636b 656e 642f 7333 2030 2f3
RE: junk at end of syslog packets in 1.5dev19
Hi Sam! > It appears that the syslog packets generated by 1.5dev19 do not always > end in a newline. They appear to end in a newline, followed by two bytes > of the last syslog buffer. Is this happen randomly or can you pin point this to specifc requests, maybe errors/timeouts? How can we reproduce this? We had a similar report a few days ago, but it doesn't quite match your description. Would you take a look at this: http://www.mail-archive.com/haproxy@formilux.org/msg10851.html Its a patch, but it hasn't been reviewed yet. Regards, Lukas
