[syslog-ng] TCP recv bug in syslog-ng v2.09?
Matthew Hall
mhall at mhcomputing.net
Thu Aug 19 21:26:43 CEST 2010
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 at 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 at 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 at gmail.com> <cdukes at gmail.com>
> > > > To: Syslog-ng users' and developers' mailing list
> > > > <syslog-ng at lists.balabit.hu> <syslog-ng at 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 at 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 at 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 at gmail.com> <cdukes at gmail.com>
> > > >>> To: Syslog-ng users' and developers' mailing list
> > > >>> <syslog-ng at lists.balabit.hu> <syslog-ng at 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
> > >
> >
> >
More information about the syslog-ng
mailing list