Discussion:
[syslog-ng] Broken TCP connection
James Pirman
2010-01-05 17:22:36 UTC
Permalink
I am currently having an issue with syslog-ng 3.0.4 where my TCP connection between my client and server is lost throughout the day. By looking at the pcap file from tcpdump I can tell that the TCP connection reset was initiated by the syslog-ng server. The only information that was initially in the log file regarding this disconnection was the following 2 lines:



<45>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733719"] notice Syslog connection closed; fd='9', client='AF_INET(192.168.27.218:46326)', local='AF_INET(192.168.27.198:20514)'



and



<46>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733720"] info Closing log transport fd; fd='9'





In order to get more information, I set the following flags in init.d: "-v -d -t".



This did not give me any more information about the TCP disconnect, however I did notice that a lot of my normal messages were preceeded by the following text:



<47>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733718"] debug Incoming log entry; line=



A normal log message then follows the '=' sign.



A decent percentage of my messages are preceeded by this throughout the day, but just before the disconnect it appears that all of my messages from server-db-01 are preceeded by the debug line. Any ideas as to what could be going on? I have included my config file below if that helps.



Any assistance would be greatly appreciated.

-Jim



@version: 3.0

#Default configuration file for syslog-ng.

#

# For a description of syslog-ng configuration file directives, please read

# the syslog-ng Administrator's guide at:

#

# http://www.balabit.com/dl/html/syslog-ng-admin-guide_en.html/bk01-toc.html

#

options {

keep_hostname(yes);

keep_timestamp(yes);

frac_digits(3);

};

source all {

internal();

syslog(ip("192.168.27.198") port(20514) transport("tcp") log_fetch_limit(100));

};

destination allclientsfile {

file("/data/local/Logs/server-$YEAR-$MONTH-$DAY.log"

flags(syslog-protocol)

flush_timeout(100)

create_dirs(yes)

dir_owner(jpirman)

dir_group(jpirman)

owner(jpirman)

group(jpirman)

template("$PRIORITY $MESSAGE")

);

};

destination msgserver {

udp("127.0.0.1" port(20515)

flush_timeout(100)

template("$ISODATE $PROGRAM $PRIORITY $MESSAGE\n"));

};

log { source(all); destination(allclientsfile); destination(msgserver);};





_________________________________________________________________
Hotmail: Powerful Free email with security by Microsoft.
http://clk.atdmt.com/GBL/go/171222986/direct/01/
James Pirman
2010-01-07 14:42:08 UTC
Permalink
Is there anyone that can help with this? Is there any more information that I need to provide in order for me to get help? I've been dealing with for weeks and am starting to think the only solution is to write my own server.



From: ***@hotmail.com
To: syslog-***@lists.balabit.hu
Date: Tue, 5 Jan 2010 11:22:36 -0600
Subject: [syslog-ng] Broken TCP connection



I am currently having an issue with syslog-ng 3.0.4 where my TCP connection between my client and server is lost throughout the day. By looking at the pcap file from tcpdump I can tell that the TCP connection reset was initiated by the syslog-ng server. The only information that was initially in the log file regarding this disconnection was the following 2 lines:

<45>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733719"] notice Syslog connection closed; fd='9', client='AF_INET(192.168.27.218:46326)', local='AF_INET(192.168.27.198:20514)'

and

<46>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733720"] info Closing log transport fd; fd='9'


In order to get more information, I set the following flags in init.d: "-v -d -t".

This did not give me any more information about the TCP disconnect, however I did notice that a lot of my normal messages were preceeded by the following text:

<47>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733718"] debug Incoming log entry; line=

A normal log message then follows the '=' sign.

A decent percentage of my messages are preceeded by this throughout the day, but just before the disconnect it appears that all of my messages from server-db-01 are preceeded by the debug line. Any ideas as to what could be going on? I have included my config file below if that helps.

Any assistance would be greatly appreciated.
-Jim

@version: 3.0
#Default configuration file for syslog-ng.
#
# For a description of syslog-ng configuration file directives, please read
# the syslog-ng Administrator's guide at:
#
# http://www.balabit.com/dl/html/syslog-ng-admin-guide_en.html/bk01-toc.html
#
options {
keep_hostname(yes);
keep_timestamp(yes);
frac_digits(3);
};
source all {
internal();
syslog(ip("192.168.27.198") port(20514) transport("tcp") log_fetch_limit(100));
};
destination allclientsfile {
file("/data/local/Logs/server-$YEAR-$MONTH-$DAY.log"
flags(syslog-protocol)
flush_timeout(100)
create_dirs(yes)
dir_owner(jpirman)
dir_group(jpirman)
owner(jpirman)
group(jpirman)
template("$PRIORITY $MESSAGE")
);
};
destination msgserver {
udp("127.0.0.1" port(20515)
flush_timeout(100)
template("$ISODATE $PROGRAM $PRIORITY $MESSAGE\n"));
};
log { source(all); destination(allclientsfile); destination(msgserver);};





Hotmail: Powerful Free email with security by Microsoft. Get it now.
_________________________________________________________________
Your E-mail and More On-the-Go. Get Windows Live Hotmail Free.
http://clk.atdmt.com/GBL/go/196390709/direct/01/
Zoltán Pallagi
2010-01-07 16:38:41 UTC
Permalink
Hi,

If I understand you correctly, you have three client/servers, don't you?
client(.218) -> relay server(.198) -> local server on relay server
(127.0.0.1)

and the problem is that sometimes your relay server drops the connection
of client.


James Pirman írta:
> Is there anyone that can help with this? Is there any more
> information that I need to provide in order for me to get help? I've
> been dealing with for weeks and am starting to think the only solution
> is to write my own server.
>
> ------------------------------------------------------------------------
> From: ***@hotmail.com
> To: syslog-***@lists.balabit.hu
> Date: Tue, 5 Jan 2010 11:22:36 -0600
> Subject: [syslog-ng] Broken TCP connection
>
> I am currently having an issue with syslog-ng 3.0.4 where my TCP
> connection between my client and server is lost throughout the day.
> By looking at the pcap file from tcpdump I can tell that the TCP
> connection reset was initiated by the syslog-ng server. The only
> information that was initially in the log file regarding this
> disconnection was the following 2 lines:
>
> <45>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 -
> [meta sequenceId="2733719"] notice Syslog connection closed; fd='9',
> client='AF_INET(192.168.27.218:46326)',
> local='AF_INET(192.168.27.198:20514)'
Can you show me the previous few lines before this log message?
Because if syslog-ng drops the connection usually sends log message
about the reason of this behaviour, like this:

2010-01-07T17:24:48+01:00 syslog-ng err Invalid frame header; header=''
2010-01-07T17:24:48+01:00 syslog-ng notice Syslog connection closed;
fd='10', client='AF_INET(10.100.20.1:33251)',
local='AF_INET(10.30.0.32:20514)'


Your client config can also be useful, the problem may be on client
side. Can you show me the debug log of your client when the connection lost?
>
> and
>
> <46>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 -
> [meta sequenceId="2733720"] info Closing log transport fd; fd='9'
>
>
> In order to get more information, I set the following flags in init.d:
> "-v -d -t".
>
> This did not give me any more information about the TCP disconnect,
> however I did notice that a lot of my normal messages were preceeded
> by the following text:
>
> <47>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 -
> [meta sequenceId="2733718"] debug Incoming log entry; line=
>
> A normal log message then follows the '=' sign.
>
> A decent percentage of my messages are preceeded by this throughout
> the day, but just before the disconnect it appears that all of my
> messages from server-db-01 are preceeded by the debug line. Any ideas
> as to what could be going on? I have included my config file below if
> that helps.
>
> Any assistance would be greatly appreciated.
> -Jim
>
> @version: 3.0
> #Default configuration file for syslog-ng.
> #
> # For a description of syslog-ng configuration file directives, please
> read
> # the syslog-ng Administrator's guide at:
> #
> #
> http://www.balabit.com/dl/html/syslog-ng-admin-guide_en.html/bk01-toc.html
> #
> options {
> keep_hostname(yes);
> keep_timestamp(yes);
> frac_digits(3);
> };
> source all {
> internal();
> syslog(ip("192.168.27.198") port(20514) transport("tcp")
> log_fetch_limit(100));
> };
> destination allclientsfile {
> file("/data/local/Logs/server-$YEAR-$MONTH-$DAY.log"
> flags(syslog-protocol)
> flush_timeout(100)
> create_dirs(yes)
> dir_owner(jpirman)
> dir_group(jpirman)
> owner(jpirman)
> group(jpirman)
> template("$PRIORITY $MESSAGE")
> );
> };
> destination msgserver {
> udp("127.0.0.1" port(20515)
> flush_timeout(100)
> template("$ISODATE $PROGRAM $PRIORITY $MESSAGE\n"));
> };
> log { source(all); destination(allclientsfile); destination(msgserver);};
>
>
>
> ------------------------------------------------------------------------
> Hotmail: Powerful Free email with security by Microsoft. Get it now.
> <http://clk.atdmt.com/GBL/go/171222986/direct/01/>
> ------------------------------------------------------------------------
> Your E-mail and More On-the-Go. Get Windows Live Hotmail Free. Sign up
> now. <http://clk.atdmt.com/GBL/go/196390709/direct/01/>
> ------------------------------------------------------------------------
>
> ______________________________________________________________________________
> 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
>
>


--
pzolee
James Pirman
2010-01-07 16:53:10 UTC
Permalink
Yes, that is correct. The 127.0.0.1 destination is actually my own application.



I just noticed today that the problem seems to be happening when the amount of traffic increases. Right now I am testing with log_fetch_limit increased from 100 to 1000, and I added log_fifo_size globally and set it to 50000. I also decreased my flush timeout from 100 to 10. This appears to be helping and I haven't dropped a connection since. Does this seem like the correct approach?



Thanks,

Jim




Date: Thu, 7 Jan 2010 17:38:41 +0100
From: ***@balabit.hu
To: syslog-***@lists.balabit.hu; ***@hotmail.com
Subject: Re: [syslog-ng] Broken TCP connection

Hi,

If I understand you correctly, you have three client/servers, don't you?
client(.218) -> relay server(.198) -> local server on relay server (127.0.0.1)

and the problem is that sometimes your relay server drops the connection of client.


James Pirman írta:


Is there anyone that can help with this? Is there any more information that I need to provide in order for me to get help? I've been dealing with for weeks and am starting to think the only solution is to write my own server.



From: ***@hotmail.com
To: syslog-***@lists.balabit.hu
Date: Tue, 5 Jan 2010 11:22:36 -0600
Subject: [syslog-ng] Broken TCP connection



I am currently having an issue with syslog-ng 3.0.4 where my TCP connection between my client and server is lost throughout the day. By looking at the pcap file from tcpdump I can tell that the TCP connection reset was initiated by the syslog-ng server. The only information that was initially in the log file regarding this disconnection was the following 2 lines:

<45>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733719"] notice Syslog connection closed; fd='9', client='AF_INET(192.168.27.218:46326)', local='AF_INET(192.168.27.198:20514)'
Can you show me the previous few lines before this log message?
Because if syslog-ng drops the connection usually sends log message about the reason of this behaviour, like this:

2010-01-07T17:24:48+01:00 syslog-ng err Invalid frame header; header=''
2010-01-07T17:24:48+01:00 syslog-ng notice Syslog connection closed; fd='10', client='AF_INET(10.100.20.1:33251)', local='AF_INET(10.30.0.32:20514)'


Your client config can also be useful, the problem may be on client side. Can you show me the debug log of your client when the connection lost?


and

<46>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733720"] info Closing log transport fd; fd='9'


In order to get more information, I set the following flags in init.d: "-v -d -t".

This did not give me any more information about the TCP disconnect, however I did notice that a lot of my normal messages were preceeded by the following text:

<47>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733718"] debug Incoming log entry; line=

A normal log message then follows the '=' sign.

A decent percentage of my messages are preceeded by this throughout the day, but just before the disconnect it appears that all of my messages from server-db-01 are preceeded by the debug line. Any ideas as to what could be going on? I have included my config file below if that helps.

Any assistance would be greatly appreciated.
-Jim

@version: 3.0
#Default configuration file for syslog-ng.
#
# For a description of syslog-ng configuration file directives, please read
# the syslog-ng Administrator's guide at:
#
# http://www.balabit.com/dl/html/syslog-ng-admin-guide_en.html/bk01-toc.html
#
options {
keep_hostname(yes);
keep_timestamp(yes);
frac_digits(3);
};
source all {
internal();
syslog(ip("192.168.27.198") port(20514) transport("tcp") log_fetch_limit(100));
};
destination allclientsfile {
file("/data/local/Logs/server-$YEAR-$MONTH-$DAY.log"
flags(syslog-protocol)
flush_timeout(100)
create_dirs(yes)
dir_owner(jpirman)
dir_group(jpirman)
owner(jpirman)
group(jpirman)
template("$PRIORITY $MESSAGE")
);
};
destination msgserver {
udp("127.0.0.1" port(20515)
flush_timeout(100)
template("$ISODATE $PROGRAM $PRIORITY $MESSAGE\n"));
};
log { source(all); destination(allclientsfile); destination(msgserver);};





Hotmail: Powerful Free email with security by Microsoft. Get it now.


Your E-mail and More On-the-Go. Get Windows Live Hotmail Free. Sign up now.
______________________________________________________________________________
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



--
pzolee

_________________________________________________________________
Your E-mail and More On-the-Go. Get Windows Live Hotmail Free.
http://clk.atdmt.com/GBL/go/196390709/direct/01/
Zoltán Pallagi
2010-01-07 20:11:15 UTC
Permalink
2010.01.07. 17:53 keltezéssel, James Pirman írta:
> Yes, that is correct. The 127.0.0.1 destination is actually my own
> application.
Ok
>
> I just noticed today that the problem seems to be happening when the
> amount of traffic increases. Right now I am testing with
> log_fetch_limit increased from 100 to 1000, and I added log_fifo_size
> globally and set it to 50000. I also decreased my flush timeout from
> 100 to 10. This appears to be helping and I haven't dropped a
> connection since. Does this seem like the correct approach?
I think, this is just a game with numbers but not the real reason for
this behaviour. If you have problem with large traffic, just write the
"flags(flow-control)" field into the right destination of your client
config.
Answer me that I asked of you, please (client config and debug log)
>
> Thanks,
> Jim
>
> ------------------------------------------------------------------------
> Date: Thu, 7 Jan 2010 17:38:41 +0100
> From: ***@balabit.hu
> To: syslog-***@lists.balabit.hu; ***@hotmail.com
> Subject: Re: [syslog-ng] Broken TCP connection
>
> Hi,
>
> If I understand you correctly, you have three client/servers, don't you?
> client(.218) -> relay server(.198) -> local server on relay server
> (127.0.0.1)
>
> and the problem is that sometimes your relay server drops the
> connection of client.
>
>
> James Pirman írta:
>
> Is there anyone that can help with this? Is there any more
> information that I need to provide in order for me to get help?
> I've been dealing with for weeks and am starting to think the only
> solution is to write my own server.
>
> ------------------------------------------------------------------------
> From: ***@hotmail.com <mailto:***@hotmail.com>
> To: syslog-***@lists.balabit.hu <mailto:syslog-***@lists.balabit.hu>
> Date: Tue, 5 Jan 2010 11:22:36 -0600
> Subject: [syslog-ng] Broken TCP connection
>
> I am currently having an issue with syslog-ng 3.0.4 where my TCP
> connection between my client and server is lost throughout the
> day. By looking at the pcap file from tcpdump I can tell that the
> TCP connection reset was initiated by the syslog-ng server. The
> only information that was initially in the log file regarding this
> disconnection was the following 2 lines:
>
> <45>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 -
> [meta sequenceId="2733719"] notice Syslog connection closed;
> fd='9', client='AF_INET(192.168.27.218:46326)',
> local='AF_INET(192.168.27.198:20514)'
>
> Can you show me the previous few lines before this log message?
> Because if syslog-ng drops the connection usually sends log message
> about the reason of this behaviour, like this:
>
> 2010-01-07T17:24:48+01:00 syslog-ng err Invalid frame header; header=''
> 2010-01-07T17:24:48+01:00 syslog-ng notice Syslog connection closed;
> fd='10', client='AF_INET(10.100.20.1:33251)',
> local='AF_INET(10.30.0.32:20514)'
>
>
> Your client config can also be useful, the problem may be on client
> side. Can you show me the debug log of your client when the connection
> lost?
>
>
> and
>
> <46>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 -
> [meta sequenceId="2733720"] info Closing log transport fd; fd='9'
>
>
> In order to get more information, I set the following flags in
> init.d: "-v -d -t".
>
> This did not give me any more information about the TCP
> disconnect, however I did notice that a lot of my normal messages
> were preceeded by the following text:
>
> <47>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 -
> [meta sequenceId="2733718"] debug Incoming log entry; line=
>
> A normal log message then follows the '=' sign.
>
> A decent percentage of my messages are preceeded by this
> throughout the day, but just before the disconnect it appears that
> all of my messages from server-db-01 are preceeded by the debug
> line. Any ideas as to what could be going on? I have included my
> config file below if that helps.
>
> Any assistance would be greatly appreciated.
> -Jim
>
> @version: 3.0
> #Default configuration file for syslog-ng.
> #
> # For a description of syslog-ng configuration file directives,
> please read
> # the syslog-ng Administrator's guide at:
> #
> #
> http://www.balabit.com/dl/html/syslog-ng-admin-guide_en.html/bk01-toc.html
> #
> options {
> keep_hostname(yes);
> keep_timestamp(yes);
> frac_digits(3);
> };
> source all {
> internal();
> syslog(ip("192.168.27.198") port(20514) transport("tcp")
> log_fetch_limit(100));
> };
> destination allclientsfile {
> file("/data/local/Logs/server-$YEAR-$MONTH-$DAY.log"
> flags(syslog-protocol)
> flush_timeout(100)
> create_dirs(yes)
> dir_owner(jpirman)
> dir_group(jpirman)
> owner(jpirman)
> group(jpirman)
> template("$PRIORITY $MESSAGE")
> );
> };
> destination msgserver {
> udp("127.0.0.1" port(20515)
> flush_timeout(100)
> template("$ISODATE $PROGRAM $PRIORITY $MESSAGE\n"));
> };
> log { source(all); destination(allclientsfile);
> destination(msgserver);};
>
>
>
> ------------------------------------------------------------------------
> Hotmail: Powerful Free email with security by Microsoft. Get it
> now. <http://clk.atdmt.com/GBL/go/171222986/direct/01/>
> ------------------------------------------------------------------------
> Your E-mail and More On-the-Go. Get Windows Live Hotmail Free.
> Sign up now. <http://clk.atdmt.com/GBL/go/196390709/direct/01/>
>
> ------------------------------------------------------------------------
>
> ______________________________________________________________________________
> 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
>
>
>
>
>
> --
> pzolee
>
>
> ------------------------------------------------------------------------
> Your E-mail and More On-the-Go. Get Windows Live Hotmail Free. Sign up
> now. <http://clk.atdmt.com/GBL/go/196390709/direct/01/>
>
>
> ______________________________________________________________________________
> 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
>
>


--
pzolee
James Pirman
2010-01-11 20:49:07 UTC
Permalink
pzolee,



The client happens to be a custom application, so I don't have a client config, and flow control doesn't really apply on the client side. I was able to setup a test environment and recreated the problem. The message immediately before the disconnect message is the following:



<47>1 2010-01-11T14:36:40.239-06:00 server-04 syslog-ng 30082 - [meta sequenceId="122761"] debug Destination queue full, dropping message; queue_len='1000', mem_fifo_size='1000'



I am guessing if I don't have flow control on the client side that I need to play with the numbers to ensure that none of the buffers ever get filled up. Is this correct?



Thanks again,

Jim





Date: Thu, 7 Jan 2010 21:11:15 +0100
From: ***@balabit.hu
To: syslog-***@lists.balabit.hu
CC: ***@hotmail.com
Subject: Re: [syslog-ng] Broken TCP connection

2010.01.07. 17:53 keltezéssel, James Pirman írta:


Yes, that is correct. The 127.0.0.1 destination is actually my own application.
Ok


I just noticed today that the problem seems to be happening when the amount of traffic increases. Right now I am testing with log_fetch_limit increased from 100 to 1000, and I added log_fifo_size globally and set it to 50000. I also decreased my flush timeout from 100 to 10. This appears to be helping and I haven't dropped a connection since. Does this seem like the correct approach?
I think, this is just a game with numbers but not the real reason for this behaviour. If you have problem with large traffic, just write the "flags(flow-control)" field into the right destination of your client config.
Answer me that I asked of you, please (client config and debug log)


Thanks,
Jim



Date: Thu, 7 Jan 2010 17:38:41 +0100
From: ***@balabit.hu
To: syslog-***@lists.balabit.hu; ***@hotmail.com
Subject: Re: [syslog-ng] Broken TCP connection

Hi,

If I understand you correctly, you have three client/servers, don't you?
client(.218) -> relay server(.198) -> local server on relay server (127.0.0.1)

and the problem is that sometimes your relay server drops the connection of client.


James Pirman írta:


Is there anyone that can help with this? Is there any more information that I need to provide in order for me to get help? I've been dealing with for weeks and am starting to think the only solution is to write my own server.



From: ***@hotmail.com
To: syslog-***@lists.balabit.hu
Date: Tue, 5 Jan 2010 11:22:36 -0600
Subject: [syslog-ng] Broken TCP connection



I am currently having an issue with syslog-ng 3.0.4 where my TCP connection between my client and server is lost throughout the day. By looking at the pcap file from tcpdump I can tell that the TCP connection reset was initiated by the syslog-ng server. The only information that was initially in the log file regarding this disconnection was the following 2 lines:

<45>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733719"] notice Syslog connection closed; fd='9', client='AF_INET(192.168.27.218:46326)', local='AF_INET(192.168.27.198:20514)'
Can you show me the previous few lines before this log message?
Because if syslog-ng drops the connection usually sends log message about the reason of this behaviour, like this:

2010-01-07T17:24:48+01:00 syslog-ng err Invalid frame header; header=''
2010-01-07T17:24:48+01:00 syslog-ng notice Syslog connection closed; fd='10', client='AF_INET(10.100.20.1:33251)', local='AF_INET(10.30.0.32:20514)'


Your client config can also be useful, the problem may be on client side. Can you show me the debug log of your client when the connection lost?


and

<46>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733720"] info Closing log transport fd; fd='9'


In order to get more information, I set the following flags in init.d: "-v -d -t".

This did not give me any more information about the TCP disconnect, however I did notice that a lot of my normal messages were preceeded by the following text:

<47>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng 29213 - [meta sequenceId="2733718"] debug Incoming log entry; line=

A normal log message then follows the '=' sign.

A decent percentage of my messages are preceeded by this throughout the day, but just before the disconnect it appears that all of my messages from server-db-01 are preceeded by the debug line. Any ideas as to what could be going on? I have included my config file below if that helps.

Any assistance would be greatly appreciated.
-Jim

@version: 3.0
#Default configuration file for syslog-ng.
#
# For a description of syslog-ng configuration file directives, please read
# the syslog-ng Administrator's guide at:
#
# http://www.balabit.com/dl/html/syslog-ng-admin-guide_en.html/bk01-toc.html
#
options {
keep_hostname(yes);
keep_timestamp(yes);
frac_digits(3);
};
source all {
internal();
syslog(ip("192.168.27.198") port(20514) transport("tcp") log_fetch_limit(100));
};
destination allclientsfile {
file("/data/local/Logs/server-$YEAR-$MONTH-$DAY.log"
flags(syslog-protocol)
flush_timeout(100)
create_dirs(yes)
dir_owner(jpirman)
dir_group(jpirman)
owner(jpirman)
group(jpirman)
template("$PRIORITY $MESSAGE")
);
};
destination msgserver {
udp("127.0.0.1" port(20515)
flush_timeout(100)
template("$ISODATE $PROGRAM $PRIORITY $MESSAGE\n"));
};
log { source(all); destination(allclientsfile); destination(msgserver);};





Hotmail: Powerful Free email with security by Microsoft. Get it now.


Your E-mail and More On-the-Go. Get Windows Live Hotmail Free. Sign up now.
______________________________________________________________________________
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



--
pzolee



Your E-mail and More On-the-Go. Get Windows Live Hotmail Free. Sign up now.
______________________________________________________________________________
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




--
pzolee
_________________________________________________________________
Hotmail: Free, trusted and rich email service.
http://clk.atdmt.com/GBL/go/196390708/direct/01/
Zoltán Pallagi
2010-01-12 20:17:34 UTC
Permalink
Hi,

Yes, it is. You need to increase log_fetch_limit() and log_fifo_size()
in this case. Keep your mind the log_fifo_size must be larger than the
log_fetch_limit.
I don't suggest reducing flush_timeout but you should increase both
flush_timeout and flush_lines. Because this message (dropping message)
means your client send messages too fast and the syslog-ng cannot be
able to write them in time.
Back to the original problem, I don't have much idea the reason for
disconnecting. Can you send me the tcpdump file? I suspect the problem
may be here in relation to high traffic.


2010.01.11. 21:49 keltezéssel, James Pirman írta:
> pzolee,
>
> The client happens to be a custom application, so I don't have a
> client config, and flow control doesn't really apply on the client
> side. I was able to setup a test environment and recreated the
> problem. The message immediately before the disconnect message is the
> following:
>
> <47>1 2010-01-11T14:36:40.239-06:00 server-04 syslog-ng 30082 - [meta
> sequenceId="122761"] debug Destination queue full, dropping message;
> queue_len='1000', mem_fifo_size='1000'
>
> I am guessing if I don't have flow control on the client side that I
> need to play with the numbers to ensure that none of the buffers ever
> get filled up. Is this correct?
>
> Thanks again,
> Jim
>
>
> ------------------------------------------------------------------------
> Date: Thu, 7 Jan 2010 21:11:15 +0100
> From: ***@balabit.hu
> To: syslog-***@lists.balabit.hu
> CC: ***@hotmail.com
> Subject: Re: [syslog-ng] Broken TCP connection
>
> 2010.01.07. 17:53 keltezéssel, James Pirman írta:
>
> Yes, that is correct. The 127.0.0.1 destination is actually my
> own application.
>
> Ok
>
>
> I just noticed today that the problem seems to be happening when
> the amount of traffic increases. Right now I am testing with
> log_fetch_limit increased from 100 to 1000, and I added
> log_fifo_size globally and set it to 50000. I also decreased my
> flush timeout from 100 to 10. This appears to be helping and I
> haven't dropped a connection since. Does this seem like the
> correct approach?
>
> I think, this is just a game with numbers but not the real reason for
> this behaviour. If you have problem with large traffic, just write the
> "flags(flow-control)" field into the right destination of your client
> config.
> Answer me that I asked of you, please (client config and debug log)
>
>
> Thanks,
> Jim
>
> ------------------------------------------------------------------------
> Date: Thu, 7 Jan 2010 17:38:41 +0100
> From: ***@balabit.hu <mailto:***@balabit.hu>
> To: syslog-***@lists.balabit.hu
> <mailto:syslog-***@lists.balabit.hu>; ***@hotmail.com
> <mailto:***@hotmail.com>
> Subject: Re: [syslog-ng] Broken TCP connection
>
> Hi,
>
> If I understand you correctly, you have three client/servers,
> don't you?
> client(.218) -> relay server(.198) -> local server on relay server
> (127.0.0.1)
>
> and the problem is that sometimes your relay server drops the
> connection of client.
>
>
> James Pirman írta:
>
> Is there anyone that can help with this? Is there any more
> information that I need to provide in order for me to get
> help? I've been dealing with for weeks and am starting to
> think the only solution is to write my own server.
>
> ------------------------------------------------------------------------
> From: ***@hotmail.com <mailto:***@hotmail.com>
> To: syslog-***@lists.balabit.hu <mailto:syslog-***@lists.balabit.hu>
> Date: Tue, 5 Jan 2010 11:22:36 -0600
> Subject: [syslog-ng] Broken TCP connection
>
> I am currently having an issue with syslog-ng 3.0.4 where my
> TCP connection between my client and server is lost throughout
> the day. By looking at the pcap file from tcpdump I can tell
> that the TCP connection reset was initiated by the syslog-ng
> server. The only information that was initially in the log
> file regarding this disconnection was the following 2 lines:
>
> <45>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng
> 29213 - [meta sequenceId="2733719"] notice Syslog connection
> closed; fd='9', client='AF_INET(192.168.27.218:46326)',
> local='AF_INET(192.168.27.198:20514)'
>
> Can you show me the previous few lines before this log message?
> Because if syslog-ng drops the connection usually sends log
> message about the reason of this behaviour, like this:
>
> 2010-01-07T17:24:48+01:00 syslog-ng err Invalid frame header;
> header=''
> 2010-01-07T17:24:48+01:00 syslog-ng notice Syslog connection
> closed; fd='10', client='AF_INET(10.100.20.1:33251)',
> local='AF_INET(10.30.0.32:20514)'
>
>
> Your client config can also be useful, the problem may be on
> client side. Can you show me the debug log of your client when the
> connection lost?
>
>
> and
>
> <46>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng
> 29213 - [meta sequenceId="2733720"] info Closing log transport
> fd; fd='9'
>
>
> In order to get more information, I set the following flags in
> init.d: "-v -d -t".
>
> This did not give me any more information about the TCP
> disconnect, however I did notice that a lot of my normal
> messages were preceeded by the following text:
>
> <47>1 2010-01-05T10:29:32.323-06:00 server-db-01 syslog-ng
> 29213 - [meta sequenceId="2733718"] debug Incoming log entry;
> line=
>
> A normal log message then follows the '=' sign.
>
> A decent percentage of my messages are preceeded by this
> throughout the day, but just before the disconnect it appears
> that all of my messages from server-db-01 are preceeded by the
> debug line. Any ideas as to what could be going on? I have
> included my config file below if that helps.
>
> Any assistance would be greatly appreciated.
> -Jim
>
> @version: 3.0
> #Default configuration file for syslog-ng.
> #
> # For a description of syslog-ng configuration file
> directives, please read
> # the syslog-ng Administrator's guide at:
> #
> #
> http://www.balabit.com/dl/html/syslog-ng-admin-guide_en.html/bk01-toc.html
> #
> options {
> keep_hostname(yes);
> keep_timestamp(yes);
> frac_digits(3);
> };
> source all {
> internal();
> syslog(ip("192.168.27.198") port(20514) transport("tcp")
> log_fetch_limit(100));
> };
> destination allclientsfile {
> file("/data/local/Logs/server-$YEAR-$MONTH-$DAY.log"
> flags(syslog-protocol)
> flush_timeout(100)
> create_dirs(yes)
> dir_owner(jpirman)
> dir_group(jpirman)
> owner(jpirman)
> group(jpirman)
> template("$PRIORITY $MESSAGE")
> );
> };
> destination msgserver {
> udp("127.0.0.1" port(20515)
> flush_timeout(100)
> template("$ISODATE $PROGRAM $PRIORITY $MESSAGE\n"));
> };
> log { source(all); destination(allclientsfile);
> destination(msgserver);};
>
>
>
> ------------------------------------------------------------------------
> Hotmail: Powerful Free email with security by Microsoft. Get
> it now. <http://clk.atdmt.com/GBL/go/171222986/direct/01/>
> ------------------------------------------------------------------------
> Your E-mail and More On-the-Go. Get Windows Live Hotmail Free.
> Sign up now. <http://clk.atdmt.com/GBL/go/196390709/direct/01/>
>
> ------------------------------------------------------------------------
>
> ______________________________________________________________________________
> 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
>
>
>
>
>
> --
> pzolee
>
>
>
> ------------------------------------------------------------------------
> Your E-mail and More On-the-Go. Get Windows Live Hotmail Free.
> Sign up now. <http://clk.atdmt.com/GBL/go/196390709/direct/01/>
>
>
> ______________________________________________________________________________
> 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
>
>
>
>
>
> --
> pzolee
>
> ------------------------------------------------------------------------
> Hotmail: Free, trusted and rich email service. Get it now.
> <http://clk.atdmt.com/GBL/go/196390708/direct/01/>
>
>
> ______________________________________________________________________________
> 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
>
>


--
pzolee
Balazs Scheidler
2010-01-14 09:12:40 UTC
Permalink
On Mon, 2010-01-11 at 14:49 -0600, James Pirman wrote:
> pzolee,
>
> The client happens to be a custom application, so I don't have a
> client config, and flow control doesn't really apply on the client
> side. I was able to setup a test environment and recreated the
> problem. The message immediately before the disconnect message is the
> following:
>
> <47>1 2010-01-11T14:36:40.239-06:00 server-04 syslog-ng 30082 - [meta
> sequenceId="122761"] debug Destination queue full, dropping message;
> queue_len='1000', mem_fifo_size='1000'
>
> I am guessing if I don't have flow control on the client side that I
> need to play with the numbers to ensure that none of the buffers ever
> get filled up. Is this correct?

That message alone should not cause syslog-ng to initiate a disconnect.
Do you have TLS enabled?

The only reasons syslog-ng disconnects are:
* either some kind of protocol format issue
* or an EOF on the client side

Protocol errors are logged. The exact reasons with messages follow:

msg_error("Error reading frame header",
evt_tag_int("fd", self->super.transport->fd),
evt_tag_errno("error", errno),
NULL);

msg_error("Invalid frame header",
evt_tag_printf("header", "%.*s", (gint) (i - self->buffer_pos), &self->buffer[self->buffer_pos]),
NULL);

msg_error("Incoming frame larger than log_msg_size()",
evt_tag_int("log_msg_size", self->buffer_size - LPFS_FRAME_BUFFER),
evt_tag_int("frame_length", self->frame_len),
NULL);

As I see with the syslog() protocol, EOFs are not logged, only with
the traditional protocol. I've added this log message with this patch
to OSE 3.1, but you should be able to apply it to 3.0 as well.

commit bbc248bc8a577a299036d2ab6898d72f657fc7a0
Author: Balazs Scheidler <***@balabit.hu>
Date: Thu Jan 14 10:11:33 2010 +0100

logproto: added log message about EOF in the new style syslog protocol handler

Are you sure that it wasn't the client which sent a FIN packet in
the first place? Can you show at least the end of tcpdump -rn <pcap file>?

--
Bazsi
James Pirman
2010-01-14 18:00:31 UTC
Permalink
Unfortunately I no longer have the tcpdump since we only keep them for 2 or 3 days. Ever since I increased the parameters the problem has stopped happening. I will have to recreate this again in the test environment to get a new tcpdump. However, because increasing the size stopped the problem, I do not think it is a problem with EOF.




> From: ***@balabit.hu
> To: syslog-***@lists.balabit.hu
> Date: Thu, 14 Jan 2010 10:12:40 +0100
> Subject: Re: [syslog-ng] Broken TCP connection
>
> On Mon, 2010-01-11 at 14:49 -0600, James Pirman wrote:
> > pzolee,
> >
> > The client happens to be a custom application, so I don't have a
> > client config, and flow control doesn't really apply on the client
> > side. I was able to setup a test environment and recreated the
> > problem. The message immediately before the disconnect message is the
> > following:
> >
> > <47>1 2010-01-11T14:36:40.239-06:00 server-04 syslog-ng 30082 - [meta
> > sequenceId="122761"] debug Destination queue full, dropping message;
> > queue_len='1000', mem_fifo_size='1000'
> >
> > I am guessing if I don't have flow control on the client side that I
> > need to play with the numbers to ensure that none of the buffers ever
> > get filled up. Is this correct?
>
> That message alone should not cause syslog-ng to initiate a disconnect.
> Do you have TLS enabled?
>
> The only reasons syslog-ng disconnects are:
> * either some kind of protocol format issue
> * or an EOF on the client side
>
> Protocol errors are logged. The exact reasons with messages follow:
>
> msg_error("Error reading frame header",
> evt_tag_int("fd", self->super.transport->fd),
> evt_tag_errno("error", errno),
> NULL);
>
> msg_error("Invalid frame header",
> evt_tag_printf("header", "%.*s", (gint) (i - self->buffer_pos), &self->buffer[self->buffer_pos]),
> NULL);
>
> msg_error("Incoming frame larger than log_msg_size()",
> evt_tag_int("log_msg_size", self->buffer_size - LPFS_FRAME_BUFFER),
> evt_tag_int("frame_length", self->frame_len),
> NULL);
>
> As I see with the syslog() protocol, EOFs are not logged, only with
> the traditional protocol. I've added this log message with this patch
> to OSE 3.1, but you should be able to apply it to 3.0 as well.
>
> commit bbc248bc8a577a299036d2ab6898d72f657fc7a0
> Author: Balazs Scheidler <***@balabit.hu>
> Date: Thu Jan 14 10:11:33 2010 +0100
>
> logproto: added log message about EOF in the new style syslog protocol handler
>
> Are you sure that it wasn't the client which sent a FIN packet in
> the first place? Can you show at least the end of tcpdump -rn <pcap file>?
>
> --
> 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
>

_________________________________________________________________
Your E-mail and More On-the-Go. Get Windows Live Hotmail Free.
http://clk.atdmt.com/GBL/go/196390709/direct/01/
Loading...