[syslog-ng] TCP recv bug in syslog-ng v2.09?

Thu Aug 19 22:07:54 CEST 2010

Yeah, now the only problem is all the ancient boxes with no new 12 
series code or outdated SMARTNet agreements. But those are a problem 
regardless of this issue!

On Thu, Aug 19, 2010 at 04:05:11PM -0400, Clayton Dukes wrote:
> Aha!
> Thanks for pointing me to my own company's documentation! hehe.
> So, it does appear as though they have provided a fix in later versions of
> the code.
> That is probably about the best we can ask for, and in my case, it's not a
> terrible option since we're running this on IP SLA shadow routers which can
> easily be upgraded.
> 
> A HUGE thank you!
> 
> ______________________________________________________________
> 
> Clayton Dukes
> ______________________________________________________________
> 
> 
> On Thu, Aug 19, 2010 at 3:50 PM, Matthew Hall <mhall at mhcomputing.net> wrote:
> 
> > 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 at 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 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
> > > > > > >
> > > > > >
> > > > > >
> > > >
> >