[syslog-ng] TCP recv bug in syslog-ng v2.09?
Clayton Dukes
cdukes at gmail.com
Thu Aug 19 21:13:24 CEST 2010
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
> >
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.balabit.hu/pipermail/syslog-ng/attachments/20100819/99249368/attachment-0003.htm
More information about the syslog-ng
mailing list