Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected. *Router config:* logging source-interface Loopback0 logging 172.18.224.150 <tricon:40,-1|172.18.224.150;majoshi@cisco.com> logging host 172.18.224.190 <tricon:40,-1|172.18.224.190;majoshi@cisco.com>transport tcp *syslog-ng config:* source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); }; *debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50<tricon:40,-1|(14.3.23.50;majoshi@cisco.com>:63845)', to='AF_INET(172.18.224.190 <tricon:40,-1|(172.18.224.190;majoshi@cisco.com> :601)' *tcpdump:* 14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94 *Router debug:* *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:19.772<tricon:40,-1|.772;majoshi@cisco.com>: %SYS-5- <tricon:40,-1|-5-;majoshi@cisco.com>CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) <tricon:40,-1|0 (172.18.224.151);majoshi@cisco.com> *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:20.776<tricon:40,-1|.776;majoshi@cisco.com>: Released port 15205 <tricon:40,-1|15205;majoshi@cisco.com> in Transport Port Agent for TCP IP type 1 delay 240000 <tricon:40,-1|240000;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:20.776<tricon:40,-1|.776;majoshi@cisco.com>: TCB 0x850 <tricon:40,-1|850;majoshi@cisco.com>F9754<tricon:40,-1|9754;majoshi@cisco.com>destroyed *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1|83648;majoshi@cisco.com>E60 created *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1|83648;majoshi@cisco.com>E60 setting property TCP_PID (8) 845083 <tricon:40,-1|(8) 845083;majoshi@cisco.com>E4 *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1|83648;majoshi@cisco.com>E60 setting property TCP_NO_DELAY (1) 845083 <tricon:40,-1|(1) 845083;majoshi@cisco.com>E8 *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1|83648;majoshi@cisco.com>E60 setting property TCP keepalive timeout (17) 845084 <tricon:40,-1|(17) 845084;majoshi@cisco.com> A0 *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCP: Random local port generated 63845<tricon:40,-1|63845;majoshi@cisco.com>, network 1 *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1|83648;majoshi@cisco.com>E60 bound to 14.3.23.50.63845<tricon:40,-1|14.3.23.50.63845;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: Reserved port 63845 <tricon:40,-1|63845;majoshi@cisco.com> in Transport Port Agent for TCP IP type 1 *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCP: sending SYN, seq 3300233565 <tricon:40,-1|3300233565;majoshi@cisco.com>, ack 0 *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCP0: Connection to 172.18.224.190<tricon:40,-1|172.18.224.190;majoshi@cisco.com>:601, advertising MSS 536 <tricon:40,-1|536;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.775<tricon:40,-1|.775;majoshi@cisco.com>: TCP0: state was CLOSED -> SYNSENT [63845 - <tricon:40,-1|63845 -;majoshi@cisco.com>> 172.18.224.190(601)<tricon:40,-1|172.18.224.190(601);majoshi@cisco.com> ] *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.779<tricon:40,-1|.779;majoshi@cisco.com>: TCP0: state was SYNSENT -> ESTAB [63845 - <tricon:40,-1|63845 -;majoshi@cisco.com>> 172.18.224.190(601)<tricon:40,-1|172.18.224.190(601);majoshi@cisco.com> ] *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.779<tricon:40,-1|.779;majoshi@cisco.com>: TCP: tcb 83648 <tricon:40,-1|83648;majoshi@cisco.com>E60 connection to 172.18.224.190 <tricon:40,-1|172.18.224.190;majoshi@cisco.com>:601, peer MSS 1460 <tricon:40,-1|1460;majoshi@cisco.com>, MSS is 536<tricon:40,-1|536;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.779<tricon:40,-1|.779;majoshi@cisco.com>: TCB83648 <tricon:40,-1|83648;majoshi@cisco.com>E60 connected to 172.18.224.190.601 <tricon:40,-1|172.18.224.190.601;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1|17 17;majoshi@cisco.com>:34:25.779<tricon:40,-1|.779;majoshi@cisco.com>: %SYS-6- <tricon:40,-1|-6-;majoshi@cisco.com>LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 <tricon:40,-1|172.18.224.190;majoshi@cisco.com> port 601 <tricon:40,-1|601;majoshi@cisco.com> started - reconnection ______________________________________________________________ Clayton Dukes ______________________________________________________________
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry. Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 <tricon:40,-1%7C172.18.224.150;majoshi@cisco.com> logging host 172.18.224.190 <tricon:40,-1%7C172.18.224.190;majoshi@cisco.com> transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50 <tricon:40,-1%7C%2814.3.23.50;majoshi@cisco.com>:63845)', to='AF_INET(172.18.224.190 <tricon:40,-1%7C%28172.18.224.190;majoshi@cisco.com>:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:19.772 <tricon:40,-1%7C.772;majoshi@cisco.com>: %SYS-5- <tricon:40,-1%7C-5-;majoshi@cisco.com>CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) <tricon:40,-1%7C0%20%28172.18.224.151%29;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:20.776 <tricon:40,-1%7C.776;majoshi@cisco.com>: Released port 15205 <tricon:40,-1%7C15205;majoshi@cisco.com> in Transport Port Agent for TCP IP type 1 delay 240000 <tricon:40,-1%7C240000;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:20.776 <tricon:40,-1%7C.776;majoshi@cisco.com>: TCB 0x850 <tricon:40,-1%7C850;majoshi@cisco.com>F9754 <tricon:40,-1%7C9754;majoshi@cisco.com> destroyed *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1%7C83648;majoshi@cisco.com>E60 created *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1%7C83648;majoshi@cisco.com>E60 setting property TCP_PID (8) 845083 <tricon:40,-1%7C%288%29%20845083;majoshi@cisco.com>E4 *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1%7C83648;majoshi@cisco.com>E60 setting property TCP_NO_DELAY (1) 845083 <tricon:40,-1%7C%281%29%20845083;majoshi@cisco.com>E8 *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1%7C83648;majoshi@cisco.com>E60 setting property TCP keepalive timeout (17) 845084 <tricon:40,-1%7C%2817%29%20845084;majoshi@cisco.com>A0 *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCP: Random local port generated 63845 <tricon:40,-1%7C63845;majoshi@cisco.com>, network 1 *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCB83648 <tricon:40,-1%7C83648;majoshi@cisco.com>E60 bound to 14.3.23.50.63845 <tricon:40,-1%7C14.3.23.50.63845;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: Reserved port 63845 <tricon:40,-1%7C63845;majoshi@cisco.com> in Transport Port Agent for TCP IP type 1 *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCP: sending SYN, seq 3300233565 <tricon:40,-1%7C3300233565;majoshi@cisco.com>, ack 0 *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCP0: Connection to 172.18.224.190 <tricon:40,-1%7C172.18.224.190;majoshi@cisco.com>:601, advertising MSS 536 <tricon:40,-1%7C536;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.775 <tricon:40,-1%7C.775;majoshi@cisco.com>: TCP0: state was CLOSED -> SYNSENT [63845 - <tricon:40,-1%7C63845%20-;majoshi@cisco.com>> 172.18.224.190(601) <tricon:40,-1%7C172.18.224.190%28601%29;majoshi@cisco.com>] *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.779 <tricon:40,-1%7C.779;majoshi@cisco.com>: TCP0: state was SYNSENT -> ESTAB [63845 - <tricon:40,-1%7C63845%20-;majoshi@cisco.com>> 172.18.224.190(601) <tricon:40,-1%7C172.18.224.190%28601%29;majoshi@cisco.com>] *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.779 <tricon:40,-1%7C.779;majoshi@cisco.com>: TCP: tcb 83648 <tricon:40,-1%7C83648;majoshi@cisco.com>E60 connection to 172.18.224.190 <tricon:40,-1%7C172.18.224.190;majoshi@cisco.com>:601, peer MSS 1460 <tricon:40,-1%7C1460;majoshi@cisco.com>, MSS is 536 <tricon:40,-1%7C536;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.779 <tricon:40,-1%7C.779;majoshi@cisco.com>: TCB83648 <tricon:40,-1%7C83648;majoshi@cisco.com>E60 connected to 172.18.224.190.601 <tricon:40,-1%7C172.18.224.190.601;majoshi@cisco.com> *Aug 17 17 <tricon:40,-1%7C17%2017;majoshi@cisco.com>:34:25.779 <tricon:40,-1%7C.779;majoshi@cisco.com>: %SYS-6- <tricon:40,-1%7C-6-;majoshi@cisco.com>LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 <tricon:40,-1%7C172.18.224.190;majoshi@cisco.com> port 601 <tricon:40,-1%7C601;majoshi@cisco.com> started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________ ------------------------------------------------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab? ______________________________________________________________ Clayton Dukes ______________________________________________________________ On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET (172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083 E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________
------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Following up on this: Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem. Here's what I can see: UDP: #tcpdump -vvv host 14.3.23.50 -i eth0 tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes 09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134) 14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106 Facility local7 (23), Severity notice (5) Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog] TCP: #tcpdump -vvv host 14.3.23.50 -i eth0 09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146) 14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106 09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40) server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0 So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message? Do I have something misconfigured? ______________________________________________________________ Clayton Dukes ______________________________________________________________ On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET (172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________
------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break. -Patrick Sent: Thursday, August 19, 2010 9:12:36 AM From: Clayton Dukes <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com <mailto:cdukes@gmail.com>> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net <mailto:syslogng@feystorm.net>> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <mailto:cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <mailto:syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET(172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________ ------------------------------------------------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
------------------------------------------------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
bing! (light bulb just went off). I wasn't thinking about the whole established vs. non established connection thing. I couldn't figure out why, if UDP wasn't sending a newline, it wasn't causing the same problem. I wasn't thinking about the fact that the connection was closing, thus ending the stream. Thanks for the help! ______________________________________________________________ Clayton Dukes ______________________________________________________________ On Thu, Aug 19, 2010 at 11:29 AM, <syslogng@feystorm.net> wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
-Patrick
Sent: Thursday, August 19, 2010 9:12:36 AM
From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET(172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________
------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
This understanding is Not quite right. What we are talking about here is the difference between SOCK_STREAM and SOCK_DGRAM socket semantics. In a SOCK_DGRAM each PDU or segment is considered to be a separate atomic message, and each is delivered to the application separately. For a SOCK_DGRAM, a connection just means you have bound the socket to a specific remote address. It does not open and close for each message because it is not connection oriented. In a SOCK_STREAM each PDU or segment is considered to be additional bytes in a continuous flow of data. The application which receives data from a SOCK_STREAM has no way of seeing each PDU or segment individually, because the PDUs or segments are reassembled inside the kernel. There is no standard way of simply receiving each SOCK_STREAM packet separately because there is no relationship between the size of each PDU or segment and the size of the message. The size of the message is defined by the '\n'. This difference is also seen in UDP DNS versus TCP DNS. TCP DNS sends extra fields in the packets to keep track of the message sizes and UDP DNS does not. Matthew. On Thu, Aug 19, 2010 at 11:34:39AM -0400, Clayton Dukes wrote:
bing! (light bulb just went off). I wasn't thinking about the whole established vs. non established connection thing. I couldn't figure out why, if UDP wasn't sending a newline, it wasn't causing the same problem. I wasn't thinking about the fact that the connection was closing, thus ending the stream.
Thanks for the help!
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 11:29 AM, <syslogng@feystorm.net> wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
-Patrick
Sent: Thursday, August 19, 2010 9:12:36 AM
From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET(172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________
------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Matt, Thanks for that very good explanation, it's good ammo for me to approach the developers @ Cisco with :-) ______________________________________________________________ Clayton Dukes ______________________________________________________________ On Thu, Aug 19, 2010 at 1:21 PM, Matthew Hall <mhall@mhcomputing.net> wrote:
This understanding is Not quite right. What we are talking about here is the difference between SOCK_STREAM and SOCK_DGRAM socket semantics.
In a SOCK_DGRAM each PDU or segment is considered to be a separate atomic message, and each is delivered to the application separately. For a SOCK_DGRAM, a connection just means you have bound the socket to a specific remote address. It does not open and close for each message because it is not connection oriented.
In a SOCK_STREAM each PDU or segment is considered to be additional bytes in a continuous flow of data. The application which receives data from a SOCK_STREAM has no way of seeing each PDU or segment individually, because the PDUs or segments are reassembled inside the kernel.
There is no standard way of simply receiving each SOCK_STREAM packet separately because there is no relationship between the size of each PDU or segment and the size of the message. The size of the message is defined by the '\n'.
This difference is also seen in UDP DNS versus TCP DNS. TCP DNS sends extra fields in the packets to keep track of the message sizes and UDP DNS does not.
Matthew.
On Thu, Aug 19, 2010 at 11:34:39AM -0400, Clayton Dukes wrote:
bing! (light bulb just went off). I wasn't thinking about the whole established vs. non established connection thing. I couldn't figure out why, if UDP wasn't sending a newline, it wasn't causing the same problem. I wasn't thinking about the fact that the connection was closing, thus ending the stream.
Thanks for the help!
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 11:29 AM, <syslogng@feystorm.net> wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
-Patrick
Sent: Thursday, August 19, 2010 9:12:36 AM
From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET(172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________
------------------------------
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
------------------------------
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Thanks Clayton, I know how to explain things for networking people because I used to work at HP ProCurve. ;-) I really hope you can get this fixed because I think it will cause me problems at my new job. Matthew. On Thu, Aug 19, 2010 at 03:13:24PM -0400, Clayton Dukes wrote:
Matt, Thanks for that very good explanation, it's good ammo for me to approach the developers @ Cisco with :-)
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 1:21 PM, Matthew Hall <mhall@mhcomputing.net> wrote:
This understanding is Not quite right. What we are talking about here is the difference between SOCK_STREAM and SOCK_DGRAM socket semantics.
In a SOCK_DGRAM each PDU or segment is considered to be a separate atomic message, and each is delivered to the application separately. For a SOCK_DGRAM, a connection just means you have bound the socket to a specific remote address. It does not open and close for each message because it is not connection oriented.
In a SOCK_STREAM each PDU or segment is considered to be additional bytes in a continuous flow of data. The application which receives data from a SOCK_STREAM has no way of seeing each PDU or segment individually, because the PDUs or segments are reassembled inside the kernel.
There is no standard way of simply receiving each SOCK_STREAM packet separately because there is no relationship between the size of each PDU or segment and the size of the message. The size of the message is defined by the '\n'.
This difference is also seen in UDP DNS versus TCP DNS. TCP DNS sends extra fields in the packets to keep track of the message sizes and UDP DNS does not.
Matthew.
On Thu, Aug 19, 2010 at 11:34:39AM -0400, Clayton Dukes wrote:
bing! (light bulb just went off). I wasn't thinking about the whole established vs. non established connection thing. I couldn't figure out why, if UDP wasn't sending a newline, it wasn't causing the same problem. I wasn't thinking about the fact that the connection was closing, thus ending the stream.
Thanks for the help!
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 11:29 AM, <syslogng@feystorm.net> wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
-Patrick
Sent: Thursday, August 19, 2010 9:12:36 AM
From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET(172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________
------------------------------
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
------------------------------
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
lol, thanks :-) I'm actually a bit surprised that nobody has said anything before (like our customers). Maybe they have, but I did a bug search and didn't find anything. I'll have to dig deeper. I know the concept of tcp syslog is still relatively new, so maybe it just hasn't come up yet. I'll still have to see if what they have was done on purpose/by design or if it is, in fact, a bug (or design flaw?). I dunno, hopefully someone smarter than me can answer that, which shouldn't be too hard, heh. ______________________________________________________________ Clayton Dukes ______________________________________________________________ On Thu, Aug 19, 2010 at 3:26 PM, Matthew Hall <mhall@mhcomputing.net> wrote:
Thanks Clayton,
I know how to explain things for networking people because I used to work at HP ProCurve. ;-)
I really hope you can get this fixed because I think it will cause me problems at my new job.
Matthew.
On Thu, Aug 19, 2010 at 03:13:24PM -0400, Clayton Dukes wrote:
Matt, Thanks for that very good explanation, it's good ammo for me to approach the developers @ Cisco with :-)
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 1:21 PM, Matthew Hall <mhall@mhcomputing.net> wrote:
This understanding is Not quite right. What we are talking about here is the difference between SOCK_STREAM and SOCK_DGRAM socket semantics.
In a SOCK_DGRAM each PDU or segment is considered to be a separate atomic message, and each is delivered to the application separately. For a SOCK_DGRAM, a connection just means you have bound the socket to a specific remote address. It does not open and close for each message because it is not connection oriented.
In a SOCK_STREAM each PDU or segment is considered to be additional bytes in a continuous flow of data. The application which receives data from a SOCK_STREAM has no way of seeing each PDU or segment individually, because the PDUs or segments are reassembled inside the kernel.
There is no standard way of simply receiving each SOCK_STREAM packet separately because there is no relationship between the size of each PDU or segment and the size of the message. The size of the message is defined by the '\n'.
This difference is also seen in UDP DNS versus TCP DNS. TCP DNS sends extra fields in the packets to keep track of the message sizes and UDP DNS does not.
Matthew.
On Thu, Aug 19, 2010 at 11:34:39AM -0400, Clayton Dukes wrote:
bing! (light bulb just went off). I wasn't thinking about the whole established vs. non established connection thing. I couldn't figure out why, if UDP wasn't sending a newline, it wasn't causing the same problem. I wasn't thinking about the fact that the connection was closing, thus ending the stream.
Thanks for the help!
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 11:29 AM, <syslogng@feystorm.net> wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
-Patrick
Sent: Thursday, August 19, 2010 9:12:36 AM
From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
> If I recall correctly its because cisco equipment doesnt terminate its > log entries with newlines, so when sending via TCP, syslog-ng thinks the > message is going to be continued in another packet (UDP is assumed to be 1 > packet per log entry). > The only way to fix this is an ugly hack to set the timeout so that when > it doesnt get a reply within a certain time, it assumes the log entry ended. > but if several log entries are sent within the timeout, then they'll all be > mashed together into 1 syslog-ng entry. > > > Sent: Tuesday, August 17, 2010 12:28:28 PM > From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> > To: Syslog-ng users' and developers' mailing list > <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> > Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09? > > Hey guys, > Are there any known bugs for syslog-ng v2.09 that won't allow a cisco > router to send logs over tcp? > I can see a connection established in syslog-ng. > I also see the message come in via tcpdump, but nothing in syslog-ng's > output. > If I change the router from tcp to udp, messages come in as expected. > > *Router config:* > > logging source-interface Loopback0 > logging 172.18.224.150 > logging host 172.18.224.190 transport tcp > > > *syslog-ng config:* > > source s_all { > udp(); > tcp(ip(11.31.130.99) port(8002) max-connections(300)); > tcp(ip(172.18.224.190) port(601) max-connections(300)); > }; > > > *debug output:* > I commented out the line above for the other interface (11.31.130.99), > restarted and this is all I see: > Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', > to='AF_INET(172.18.224.190:601)' > > > *tcpdump:* > > 14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], > proto TCP (6), length 134) > 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win > 4128, length 94 > > > *Router debug:* > > *Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc > on vty0 (172.18.224.151) > *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for > TCP IP type 1 delay 240000 > *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed > *Aug 17 17:34:25.775: TCB83648E60 created > *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 > *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) > 845083E8 > *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout > (17) 845084A0 > *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 > *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 > *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for > TCP IP type 1 > *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 > *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, > advertising MSS 536 > *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> > 172.18.224.190(601)] > *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> > 172.18.224.190(601)] > *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, > peer MSS 1460, MSS is 536 > *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 > *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host > 172.18.224.190 port 601 started - reconnection > > ______________________________________________________________ > > Clayton Dukes > ______________________________________________________________ > > ------------------------------ > >
> Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng > Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng > FAQ: http://www.campin.net/syslog-ng/faq.html > > > >
> Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng > Documentation: > http://www.balabit.com/support/documentation/?product=syslog-ng > FAQ: http://www.campin.net/syslog-ng/faq.html > > >
------------------------------
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
It's a pretty famous problem among the logging daemon maintainers. Many logging daemons are struggling with this issue, and they have come up with various hacks to try to split out the broken messages using timing since they can't always get a '\n'. Fortunately there is a fix available in recent firmware it appears. To append a line feed character at the end of each syslog message over TCP as delimiter, use the logging delimiter tcp command. To turn off the delimiter for Syslog over TCP, use the no form of this command. logging delimiter tcp no logging delimiter tcp By default, the logging delimiter tcp function is enabled. This command was introduced in 12.4(24)T. Usage Guidelines You can use the logging delimiter tcp to append a line feed character at the end of each syslog message over TCP as the delimiter. Since TCP is a stream protocol, the delimiter helps the external TCP syslog listeners to accurately detect the end of each syslog message from the incoming TCP stream. In case the external TCP Syslog listeners do not work well with the delimiter, use the no form of this command to turn it off. On Thu, Aug 19, 2010 at 03:44:12PM -0400, Clayton Dukes wrote:
lol, thanks :-) I'm actually a bit surprised that nobody has said anything before (like our customers). Maybe they have, but I did a bug search and didn't find anything. I'll have to dig deeper.
I know the concept of tcp syslog is still relatively new, so maybe it just hasn't come up yet. I'll still have to see if what they have was done on purpose/by design or if it is, in fact, a bug (or design flaw?). I dunno, hopefully someone smarter than me can answer that, which shouldn't be too hard, heh.
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 3:26 PM, Matthew Hall <mhall@mhcomputing.net> wrote:
Thanks Clayton,
I know how to explain things for networking people because I used to work at HP ProCurve. ;-)
I really hope you can get this fixed because I think it will cause me problems at my new job.
Matthew.
On Thu, Aug 19, 2010 at 03:13:24PM -0400, Clayton Dukes wrote:
Matt, Thanks for that very good explanation, it's good ammo for me to approach the developers @ Cisco with :-)
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 1:21 PM, Matthew Hall <mhall@mhcomputing.net> wrote:
This understanding is Not quite right. What we are talking about here is the difference between SOCK_STREAM and SOCK_DGRAM socket semantics.
In a SOCK_DGRAM each PDU or segment is considered to be a separate atomic message, and each is delivered to the application separately. For a SOCK_DGRAM, a connection just means you have bound the socket to a specific remote address. It does not open and close for each message because it is not connection oriented.
In a SOCK_STREAM each PDU or segment is considered to be additional bytes in a continuous flow of data. The application which receives data from a SOCK_STREAM has no way of seeing each PDU or segment individually, because the PDUs or segments are reassembled inside the kernel.
There is no standard way of simply receiving each SOCK_STREAM packet separately because there is no relationship between the size of each PDU or segment and the size of the message. The size of the message is defined by the '\n'.
This difference is also seen in UDP DNS versus TCP DNS. TCP DNS sends extra fields in the packets to keep track of the message sizes and UDP DNS does not.
Matthew.
On Thu, Aug 19, 2010 at 11:34:39AM -0400, Clayton Dukes wrote:
bing! (light bulb just went off). I wasn't thinking about the whole established vs. non established connection thing. I couldn't figure out why, if UDP wasn't sending a newline, it wasn't causing the same problem. I wasn't thinking about the fact that the connection was closing, thus ending the stream.
Thanks for the help!
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 11:29 AM, <syslogng@feystorm.net> wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
-Patrick
Sent: Thursday, August 19, 2010 9:12:36 AM
From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
> yikes! > seriously? > Guess I'll have to file a bug internally :-) > Can someone else positively verify this? > Or any suggestions on how I can so that we can recreate it in a lab? > > ______________________________________________________________ > > Clayton Dukes > ______________________________________________________________ > > > > On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote: > >> If I recall correctly its because cisco equipment doesnt terminate its >> log entries with newlines, so when sending via TCP, syslog-ng thinks the >> message is going to be continued in another packet (UDP is assumed to be 1 >> packet per log entry). >> The only way to fix this is an ugly hack to set the timeout so that when >> it doesnt get a reply within a certain time, it assumes the log entry ended. >> but if several log entries are sent within the timeout, then they'll all be >> mashed together into 1 syslog-ng entry. >> >> >> Sent: Tuesday, August 17, 2010 12:28:28 PM >> From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> >> To: Syslog-ng users' and developers' mailing list >> <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> >> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09? >> >> Hey guys, >> Are there any known bugs for syslog-ng v2.09 that won't allow a cisco >> router to send logs over tcp? >> I can see a connection established in syslog-ng. >> I also see the message come in via tcpdump, but nothing in syslog-ng's >> output. >> If I change the router from tcp to udp, messages come in as expected. >> >> *Router config:* >> >> logging source-interface Loopback0 >> logging 172.18.224.150 >> logging host 172.18.224.190 transport tcp >> >> >> *syslog-ng config:* >> >> source s_all { >> udp(); >> tcp(ip(11.31.130.99) port(8002) max-connections(300)); >> tcp(ip(172.18.224.190) port(601) max-connections(300)); >> }; >> >> >> *debug output:* >> I commented out the line above for the other interface (11.31.130.99), >> restarted and this is all I see: >> Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', >> to='AF_INET(172.18.224.190:601)' >> >> >> *tcpdump:* >> >> 14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], >> proto TCP (6), length 134) >> 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win >> 4128, length 94 >> >> >> *Router debug:* >> >> *Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc >> on vty0 (172.18.224.151) >> *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for >> TCP IP type 1 delay 240000 >> *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed >> *Aug 17 17:34:25.775: TCB83648E60 created >> *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 >> *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) >> 845083E8 >> *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout >> (17) 845084A0 >> *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 >> *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 >> *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for >> TCP IP type 1 >> *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 >> *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, >> advertising MSS 536 >> *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> >> 172.18.224.190(601)] >> *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> >> 172.18.224.190(601)] >> *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, >> peer MSS 1460, MSS is 536 >> *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 >> *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host >> 172.18.224.190 port 601 started - reconnection >> >> ______________________________________________________________ >> >> Clayton Dukes >> ______________________________________________________________ >> >> ------------------------------ >> >>
>> Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng >> Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng >> FAQ: http://www.campin.net/syslog-ng/faq.html >> >> >> >>
>> Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng >> Documentation: >> http://www.balabit.com/support/documentation/?product=syslog-ng >> FAQ: http://www.campin.net/syslog-ng/faq.html >> >> >> > ------------------------------
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Hi, I'm glad that you found a solution. The only thing that I could think of as a workaround was to try the no-parse flag, but it's good that it wasn't needed. Robert On Thursday, August 19, 2010 17:34 CEST, Clayton Dukes <cdukes@gmail.com> wrote:
bing! (light bulb just went off). I wasn't thinking about the whole established vs. non established connection thing. I couldn't figure out why, if UDP wasn't sending a newline, it wasn't causing the same problem. I wasn't thinking about the fact that the connection was closing, thus ending the stream.
Thanks for the help!
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 11:29 AM, <syslogng@feystorm.net> wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
-Patrick
Sent: Thursday, August 19, 2010 9:12:36 AM
From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET(172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________
------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
------------------------------
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Thanks Robert, I'll start poking on the dev guys on my side and let you know what happens - it will probably take some time as you can probably imagine :-) ______________________________________________________________ Clayton Dukes ______________________________________________________________ 2010/8/19 Fekete Róbert <frobert@balabit.hu>
Hi,
I'm glad that you found a solution. The only thing that I could think of as a workaround was to try the no-parse flag, but it's good that it wasn't needed.
Robert
On Thursday, August 19, 2010 17:34 CEST, Clayton Dukes <cdukes@gmail.com> wrote:
bing! (light bulb just went off). I wasn't thinking about the whole established vs. non established connection thing. I couldn't figure out why, if UDP wasn't sending a newline, it wasn't causing the same problem. I wasn't thinking about the fact that the connection was closing, thus ending the stream.
Thanks for the help!
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Thu, Aug 19, 2010 at 11:29 AM, <syslogng@feystorm.net> wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
-Patrick
Sent: Thursday, August 19, 2010 9:12:36 AM
From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Following up on this:
Interestingly, however, is that when I use tcpdump, I DO see each message coming in via TCP...so now I'm leaning back towards syslog-ng being the problem.
Here's what I can see:
UDP:
#tcpdump -vvv host 14.3.23.50 -i eth0
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:13:31.465239 IP (tos 0xb8, ttl 251, id 1323, offset 0, flags [none], proto UDP (17), length 134)
14.3.23.50.51526 > server.x.com.syslog: SYSLOG, length: 106
Facility local7 (23), Severity notice (5)
Msg: 2975: *Aug 19 12:34:19.465: %SYS-5-CONFIG_I[|syslog]
TCP:
#tcpdump -vvv host 14.3.23.50 -i eth0
09:46:29.902063 IP (tos 0x0, ttl 251, id 12253, offset 0, flags [none], proto TCP (6), length 146)
14.3.23.50.31746 > server.x.com.601: Flags [.], seq 233:339, ack 1, win 4128, length 106
09:46:29.902077 IP (tos 0x0, ttl 64, id 27779, offset 0, flags [DF], proto TCP (6), length 40)
server.x.com.601 > 14.3.23.50.31746: Flags [.], cksum 0xa3bb (correct), seq 1, ack 339, win 5840, length 0
So, it looks like the syslog message does end, but why is syslog-ng buffering and showing multiple TCP-based messages as a single message?
Do I have something misconfigured?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 3:14 PM, Clayton Dukes <cdukes@gmail.com> wrote:
yikes! seriously? Guess I'll have to file a bug internally :-) Can someone else positively verify this? Or any suggestions on how I can so that we can recreate it in a lab?
______________________________________________________________
Clayton Dukes ______________________________________________________________
On Tue, Aug 17, 2010 at 2:52 PM, <syslogng@feystorm.net> wrote:
If I recall correctly its because cisco equipment doesnt terminate its log entries with newlines, so when sending via TCP, syslog-ng thinks the message is going to be continued in another packet (UDP is assumed to be 1 packet per log entry). The only way to fix this is an ugly hack to set the timeout so that when it doesnt get a reply within a certain time, it assumes the log entry ended. but if several log entries are sent within the timeout, then they'll all be mashed together into 1 syslog-ng entry.
Sent: Tuesday, August 17, 2010 12:28:28 PM From: Clayton Dukes <cdukes@gmail.com> <cdukes@gmail.com> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] TCP recv bug in syslog-ng v2.09?
Hey guys, Are there any known bugs for syslog-ng v2.09 that won't allow a cisco router to send logs over tcp? I can see a connection established in syslog-ng. I also see the message come in via tcpdump, but nothing in syslog-ng's output. If I change the router from tcp to udp, messages come in as expected.
*Router config:*
logging source-interface Loopback0 logging 172.18.224.150 logging host 172.18.224.190 transport tcp
*syslog-ng config:*
source s_all { udp(); tcp(ip(11.31.130.99) port(8002) max-connections(300)); tcp(ip(172.18.224.190) port(601) max-connections(300)); };
*debug output:* I commented out the line above for the other interface (11.31.130.99), restarted and this is all I see: Syslog connection accepted; from='AF_INET(14.3.23.50:63845)', to='AF_INET(172.18.224.190:601)'
*tcpdump:*
14:13:46.914566 IP (tos 0x0, ttl 251, id 4303, offset 0, flags [none], proto TCP (6), length 134) 14.3.23.50.63845 > xxx.com.601: Flags [.], seq 230:324, ack 1, win 4128, length 94
*Router debug:*
*Aug 17 17:34:19.772: %SYS-5-CONFIG_I: Configured from console by pnoc on vty0 (172.18.224.151) *Aug 17 17:34:20.776: Released port 15205 in Transport Port Agent for TCP IP type 1 delay 240000 *Aug 17 17:34:20.776: TCB 0x850F9754 destroyed *Aug 17 17:34:25.775: TCB83648E60 created *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_PID (8) 845083E4 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP_NO_DELAY (1) 845083E8 *Aug 17 17:34:25.775: TCB83648E60 setting property TCP keepalive timeout (17) 845084A0 *Aug 17 17:34:25.775: TCP: Random local port generated 63845, network 1 *Aug 17 17:34:25.775: TCB83648E60 bound to 14.3.23.50.63845 *Aug 17 17:34:25.775: Reserved port 63845 in Transport Port Agent for TCP IP type 1 *Aug 17 17:34:25.775: TCP: sending SYN, seq 3300233565, ack 0 *Aug 17 17:34:25.775: TCP0: Connection to 172.18.224.190:601, advertising MSS 536 *Aug 17 17:34:25.775: TCP0: state was CLOSED -> SYNSENT [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP0: state was SYNSENT -> ESTAB [63845 -> 172.18.224.190(601)] *Aug 17 17:34:25.779: TCP: tcb 83648E60 connection to 172.18.224.190:601, peer MSS 1460, MSS is 536 *Aug 17 17:34:25.779: TCB83648E60 connected to 172.18.224.190.601 *Aug 17 17:34:25.779: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 172.18.224.190 port 601 started - reconnection
______________________________________________________________
Clayton Dukes ______________________________________________________________
------------------------------
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
------------------------------
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
On Thu, 2010-08-19 at 09:29 -0600, syslogng@feystorm.net wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
Also, the tcp stack doesn't inform syslog-ng where packets terminate. It only receives a stream of bytes, and potentially two packets can be concatenated or split when receiving. -- Bazsi
Thanks Bazsi, Just as a final follow-up to this, we did end up using 12.4(24)T code and the problem did go away. IOS 12.4(24)T also has the \n delimiter enabled by default when you enable tcp logging. Thanks Matt! ______________________________________________________________ Clayton Dukes ______________________________________________________________ On Thu, Sep 2, 2010 at 11:17 AM, Balazs Scheidler <bazsi@balabit.hu> wrote:
On Thu, 2010-08-19 at 09:29 -0600, syslogng@feystorm.net wrote:
I explained it already :-) When the message comes in over TCP and doesnt end with a newline, syslog-ng assumes the message is going to be continued in another packet. When the cumulative total of all the messages exceeds the max message size it flushes the buffer out and you get all the messages mashed together at once. You can try filing a bug report on bugzilla.balabit.com and request a new flag or something that treats each packet on a tcp source as a separate message, but I'd say the problem is more cisco than syslog-ng since syslog-ng works fine with all other sources except cisco devices :-/ Look at it this way, every thing that sends logs out to tcp expects the receiving syslog daemon to treat a packet without a newline as a message to be continued in a later packet. If syslog-ng changed that default behavior, all these other things that expect the behavior would break.
Also, the tcp stack doesn't inform syslog-ng where packets terminate. It only receives a stream of bytes, and potentially two packets can be concatenated or split when receiving.
-- Bazsi
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.campin.net/syslog-ng/faq.html
On Thu, Sep 02, 2010 at 12:45:23PM -0400, Clayton Dukes wrote:
Just as a final follow-up to this, we did end up using 12.4(24)T code and the problem did go away. IOS 12.4(24)T also has the \n delimiter enabled by default when you enable tcp logging.
Thank $DEITY they fixed that defect! It was annoying everybody who did logging from those boxes. Matthew.
participants (5)
-
Balazs Scheidler
-
Clayton Dukes
-
Fekete Róbert
-
Matthew Hall
-
syslogng＠feystorm.net