What do you get if you send the loggen data to a simple netcat session with its output redirected to a flat file? Do you see all 55k messages using wc -l? On Thu, Apr 1, 2010 at 6:51 AM, Clayton Dukes <cdukes@gmail.com> wrote:

I should have mentioned that this is logging directly to a file.

destination df_logzilla { file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n") ); };

On Wed, Mar 31, 2010 at 11:47 PM, Clayton Dukes <cdukes@gmail.com> wrote:

...

Hi Folks, I'm trying to run a test to check insert rates. If I run this command:

./loggen -r 5000 -D -I 10 127.0.0.1 514

The output shows: average rate = 5441.60 msg/sec, count=54420, time=10.007, msg size=256, bandwidth=1360.40 kB/sec

But, my stats don't show that many messages received:

syslog-ng[6660]: Log statistics; dropped=\'pipe(/dev/xconsole)=0\', processed=\'center(queued)=24232\', processed=\'center(received)=8077, processed=\'destination(df_logzilla)=8077\'

As you can see, it sent 55k messages, but I only received 8k. Am I doing something wrong?

Here are my options in the syslog-ng config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); log_fifo_size(16384); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); perm(0644); stats_freq(60);

};

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________

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

Nevermind, I found my problem. Flush lines was set to 10, and as I've got about 500 output files open, it was overflowing the input buffer, so it thought it needed to turn on flow-control. Had to bump up log_iw_size. Sent: Thursday, April 01, 2010 9:36:22 AM From: Patrick H. <syslogng@feystorm.net> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] Tests using loggen - not receiving all the packets

I think I'm getting this behavior as well. I use a master syslog-ng process to send filtered packets to another syslog-ng process on the same box over tcp, and its going horridly slow. I tried replacing the syslog-ng child process with netcat, and it the master process is sending really fast. But whenever I start up the child syslog-ng, it starts backing up and the master process starts buffering all the data it cant send. This behavior seems to have started after upgrading to 3.1.0. I'll try downgrading back to 3.0.5 and see if it continues, as well as try to figure out why its performing so bad. I've done an strace, and its definitely having something fishy happen with the socket.

(syslog-ng.516 is the process name of the child process) # strace -p `pidof syslog-ng.516` -i -r -T ... 0.000029 [ 370640d510] write(47, "15364 [3845467040] Apr 1 15:21:"..., 125) = 125 <0.000009> 0.000046 [ 370640dd40] lseek(47, 0, SEEK_END) = 3546874498 <0.000006> 0.000029 [ 370640d510] write(47, "15364 [3845467040] Apr 1 15:21:"..., 186) = 186 <0.000009> 0.000067 [ 3705ccae0f] poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=0}], 4, 0) = 0 (Timeout) <0.000008> 0.000307 [ 3705ccae0f] poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=0}], 4, 0) = 0 (Timeout) <0.000010> 0.000310 [ 3705ccae0f] poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=0}], 4, 0) = 0 (Timeout) <0.000008> 0.000262 [ 3705ccae0f] poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=0}], 4, 4648) = 0 (Timeout) <4.648231> 4.648391 [ 370640dd40] lseek(15, 0, SEEK_END) = 413347569 <0.000009> 0.000041 [ 370640d510] write(15, "Apr 1 15:21:49 gwsinam03 postfi"..., 230) = 230 <0.000015> 0.000074 [ 370640dd40] lseek(15, 0, SEEK_END) = 413347799 <0.000006> 0.000033 [ 370640d510] write(15, "Apr 1 15:21:49 gwsinam03 postfi"..., 68) = 68 <0.000023>

As you can see, its sitting on that poll for 4 seconds before continuing. From lsof, the FDs its polling: syslog-ng 29232 root 3r FIFO 0,6 214383200 pipe syslog-ng 29232 root 5u unix 0xffff81022f7bf680 214383203 /var/lib/syslog-ng/syslog-ng.ctl syslog-ng 29232 root 7u IPv4 214383201 TCP 127.0.0.1:516 (LISTEN) syslog-ng 29232 root 9u IPv4 214383285 TCP 127.0.0.1->127.0.0.1:28061 (ESTABLISHED)

Sent: Thursday, April 01, 2010 7:33:12 AM From: Martin Holste <mcholste@gmail.com> To: cdukes@cdukes.com, Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] Tests using loggen - not receiving all the packets

...

What do you get if you send the loggen data to a simple netcat session with its output redirected to a flat file? Do you see all 55k messages using wc -l?

On Thu, Apr 1, 2010 at 6:51 AM, Clayton Dukes <cdukes@gmail.com <mailto:cdukes@gmail.com>> wrote:

I should have mentioned that this is logging directly to a file.

destination df_logzilla { file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n") ); };

On Wed, Mar 31, 2010 at 11:47 PM, Clayton Dukes <cdukes@gmail.com <mailto:cdukes@gmail.com>> wrote:

Hi Folks, I'm trying to run a test to check insert rates. If I run this command:

./loggen -r 5000 -D -I 10 127.0.0.1 514

The output shows: average rate = 5441.60 msg/sec, count=54420, time=10.007, msg size=256, bandwidth=1360.40 kB/sec

But, my stats don't show that many messages received:

syslog-ng[6660]: Log statistics; dropped=\'pipe(/dev/xconsole)=0\', processed=\'center(queued)=24232\', processed=\'center(received)=8077, processed=\'destination(df_logzilla)=8077\'

As you can see, it sent 55k messages, but I only received 8k. Am I doing something wrong?

Here are my options in the syslog-ng config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); log_fifo_size(16384); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); perm(0644); stats_freq(60);

};

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________

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

I just happened to re-read my original post. Is it purely coincidental that no matter what the message rate was that I sent (5kmps in the first test vs 600mps in the second), the result was a log file of only around 8k messages? On Tue, Apr 13, 2010 at 10:30 PM, Clayton Dukes <cdukes@gmail.com> wrote:

Finally getting a chance to revisit this. I'm still seeing the problem.

If I run loggen like so: /www/svn/loggen -r 600 -D -I 30 127.0.0.1 514 average rate = 607.51 msg/sec, count=18226, time=30.012, msg size=256, bandwidth=151.88 kB/sec

I only get around 8k messages: wc -l /var/log/logzilla/syslog.log 8740 /var/log/logzilla/syslog.log

I've tried bumping up flush_lines and the fifo but neither seemed to make much of a difference.

Here's my config: options {      long_hostnames(off);      log_msg_size(8192);      flush_lines(1); # Note: I've tried this up to 1000      log_fifo_size(35535);      time_reopen(10);      use_dns(yes);      dns_cache(yes);      use_fqdn(yes);      keep_hostname(yes);      chain_hostnames(no); };

destination df_logzilla {   file("/var/log/logzilla/syslog.log"   template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n")   ); };

log {   source(s_all);      destination(df_logzilla); }; On Thu, Apr 1, 2010 at 9:33 AM, Martin Holste <mcholste@gmail.com> wrote:

...

What do you get if you send the loggen data to a simple netcat session with its output redirected to a flat file?  Do you see all 55k messages using wc -l?

On Thu, Apr 1, 2010 at 6:51 AM, Clayton Dukes <cdukes@gmail.com> wrote:

...

I should have mentioned that this is logging directly to a file.

destination df_logzilla {    file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n")    ); };

On Wed, Mar 31, 2010 at 11:47 PM, Clayton Dukes <cdukes@gmail.com> wrote:

...

Hi Folks, I'm trying to run a test to check insert rates. If I run this command:

./loggen -r 5000 -D -I 10 127.0.0.1 514

The output shows: average rate = 5441.60 msg/sec, count=54420, time=10.007, msg size=256, bandwidth=1360.40 kB/sec

But, my stats don't show that many messages received:

syslog-ng[6660]: Log statistics; dropped=\'pipe(/dev/xconsole)=0\', processed=\'center(queued)=24232\', processed=\'center(received)=8077, processed=\'destination(df_logzilla)=8077\'

As you can see, it sent 55k messages, but I only received 8k. Am I doing something wrong?

Here are my options in the syslog-ng config: options {       long_hostnames(off);       log_msg_size(8192);       flush_lines(1);       log_fifo_size(16384);       time_reopen(10);       use_dns(yes);       dns_cache(yes);       use_fqdn(yes);       keep_hostname(yes);       chain_hostnames(no);       perm(0644);      stats_freq(60);

};

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________

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

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________ Clayton Dukes ______________________________________________________________

Hi, I think it's not a syslog-ng problem, the udp buffer of your kernel will be full, and the kernel drops the udp packages (to make sure, you can try to use netcat (netcat -lu -p 514 >> aaa.txt) instead of syslog-ng, I think the logs will be missed in this case too). before running loggen, please check the value of the packet receive errors: root@thor:/var/log# netstat -su Udp: 124383 packets received 3 packets to unknown port received. *82487 packet receive errors* 166196 packets sent RcvbufErrors: 82487 then check it after running. I guess, you will see the missing packets (just check the difference between before and after). so, if I am right, you just have to increase the size of the udp receive buffer and it will work. For example: echo "88888888" > /proc/sys/net/core/rmem_default (or rmem_max) for more details about udp buffering: http://www.29west.com/docs/THPM/udp-buffer-sizing.html Clayton Dukes wrote:

Finally getting a chance to revisit this. I'm still seeing the problem.

If I run loggen like so: /www/svn/loggen -r 600 -D -I 30 127.0.0.1 514 average rate = 607.51 msg/sec, count=18226, time=30.012, msg size=256, bandwidth=151.88 kB/sec

I only get around 8k messages: wc -l /var/log/logzilla/syslog.log 8740 /var/log/logzilla/syslog.log

I've tried bumping up flush_lines and the fifo but neither seemed to make much of a difference.

Here's my config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); # Note: I've tried this up to 1000 log_fifo_size(35535); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); };

destination df_logzilla { file("/var/log/logzilla/syslog.log" template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n") ); };

log { source(s_all); destination(df_logzilla); }; On Thu, Apr 1, 2010 at 9:33 AM, Martin Holste <mcholste@gmail.com> wrote:

...

What do you get if you send the loggen data to a simple netcat session with its output redirected to a flat file? Do you see all 55k messages using wc -l?

On Thu, Apr 1, 2010 at 6:51 AM, Clayton Dukes <cdukes@gmail.com> wrote:

...

I should have mentioned that this is logging directly to a file.

destination df_logzilla { file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n") ); };

On Wed, Mar 31, 2010 at 11:47 PM, Clayton Dukes <cdukes@gmail.com> wrote:

...

Hi Folks, I'm trying to run a test to check insert rates. If I run this command:

./loggen -r 5000 -D -I 10 127.0.0.1 514

The output shows: average rate = 5441.60 msg/sec, count=54420, time=10.007, msg size=256, bandwidth=1360.40 kB/sec

But, my stats don't show that many messages received:

syslog-ng[6660]: Log statistics; dropped=\'pipe(/dev/xconsole)=0\', processed=\'center(queued)=24232\', processed=\'center(received)=8077, processed=\'destination(df_logzilla)=8077\'

As you can see, it sent 55k messages, but I only received 8k. Am I doing something wrong?

Here are my options in the syslog-ng config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); log_fifo_size(16384); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); perm(0644); stats_freq(60);

};

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________

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

-- pzolee

Clayton Dukes wrote:

Excellent link, thanks! That does seem to be the problem, however, if I set the buffer all the way up to 1G using: sysctl -w net.core.rmem_max=1073741824

Then I'm still dropping messages when using a test rate of 6kmps:

# ./loggen -r 6000 -D -I 10 127.0.0.1 514 average rate = 6526.63 msg/sec, count=65272, time=10.008, msg size=256, bandwidth=1631.66 kB/sec

# wc -l /tmp/logs 62933 /tmp/logs

Is there a recommendation on what the buffer should be set to for high insertion rates? My test server has 8G of memory, but I can give it more (up to 24G).

Also, note that this is a VMWare ESXi server - might that have something to do with it?

It's interesting. I tried it with rmem_max=1MB, and worked without dropped messages (my machine is Intel(R) Core(TM)2 CPU 6300 @ 1.86GHz, with ubuntu) root@thor:/opt/syslog-ng/bin# ./loggen -r 6000 -V -D -I 30 127.0.0.1 2222 average rate = 5991.87 msg/sec, count=179757, time=30.001, (last) msg size=256, bandwidth=1497.97 kB/sec root@thor:/var/log# wc -l test.log 179757 test.log root@thor:/var/log# cat /proc/sys/net/core/rmem_default 1048576 But if I set the rmem_max to 1MB, I have also dropped packages, If I set the rmem_default it works... (I don't know why, I am not an udp-kernel magus). Will you try if you set rmem_default instead of rmem_max?

On Wed, Apr 14, 2010 at 6:16 AM, Zoltán Pallagi <pzolee@balabit.hu> wrote:

...

Hi,

I think it's not a syslog-ng problem, the udp buffer of your kernel will be full, and the kernel drops the udp packages (to make sure, you can try to use netcat (netcat -lu -p 514 >> aaa.txt) instead of syslog-ng, I think the logs will be missed in this case too).

before running loggen, please check the value of the packet receive errors: root@thor:/var/log# netstat -su Udp: 124383 packets received 3 packets to unknown port received. 82487 packet receive errors 166196 packets sent RcvbufErrors: 82487

then check it after running. I guess, you will see the missing packets (just check the difference between before and after).

so, if I am right, you just have to increase the size of the udp receive buffer and it will work. For example: echo "88888888" > /proc/sys/net/core/rmem_default (or rmem_max)

for more details about udp buffering: http://www.29west.com/docs/THPM/udp-buffer-sizing.html

Clayton Dukes wrote:

Finally getting a chance to revisit this. I'm still seeing the problem.

If I run loggen like so: /www/svn/loggen -r 600 -D -I 30 127.0.0.1 514 average rate = 607.51 msg/sec, count=18226, time=30.012, msg size=256, bandwidth=151.88 kB/sec

I only get around 8k messages: wc -l /var/log/logzilla/syslog.log 8740 /var/log/logzilla/syslog.log

I've tried bumping up flush_lines and the fifo but neither seemed to make much of a difference.

Here's my config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); # Note: I've tried this up to 1000 log_fifo_size(35535); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); };

destination df_logzilla { file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n") ); };

log { source(s_all); destination(df_logzilla); }; On Thu, Apr 1, 2010 at 9:33 AM, Martin Holste <mcholste@gmail.com> wrote:

What do you get if you send the loggen data to a simple netcat session with its output redirected to a flat file? Do you see all 55k messages using wc -l?

On Thu, Apr 1, 2010 at 6:51 AM, Clayton Dukes <cdukes@gmail.com> wrote:

I should have mentioned that this is logging directly to a file.

destination df_logzilla { file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n") ); };

On Wed, Mar 31, 2010 at 11:47 PM, Clayton Dukes <cdukes@gmail.com> wrote:

Hi Folks, I'm trying to run a test to check insert rates. If I run this command:

./loggen -r 5000 -D -I 10 127.0.0.1 514

The output shows: average rate = 5441.60 msg/sec, count=54420, time=10.007, msg size=256, bandwidth=1360.40 kB/sec

But, my stats don't show that many messages received:

syslog-ng[6660]: Log statistics; dropped=\'pipe(/dev/xconsole)=0\', processed=\'center(queued)=24232\', processed=\'center(received)=8077, processed=\'destination(df_logzilla)=8077\'

As you can see, it sent 55k messages, but I only received 8k. Am I doing something wrong?

Here are my options in the syslog-ng config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); log_fifo_size(16384); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); perm(0644); stats_freq(60);

};

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________

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

-- pzolee

-- pzolee

For anyone searching the Goog and finding this thread later on, I've created an explanation of everything in my Wiki: http://nms.gdd.net/index.php/Install_Guide_for_LogZilla_v3.0#UDP_Buffers Hope it helps! On Wed, Apr 14, 2010 at 12:10 PM, Clayton Dukes <cdukes@gmail.com> wrote:

Yay! That did it. Thanks!

On Wed, Apr 14, 2010 at 11:30 AM, Zoltán Pallagi <pzolee@balabit.hu> wrote:

...

Clayton Dukes wrote:

Excellent link, thanks! That does seem to be the problem, however, if I set the buffer all the way up to 1G using: sysctl -w net.core.rmem_max=1073741824

Then I'm still dropping messages when using a test rate of 6kmps:

# ./loggen -r 6000 -D -I 10 127.0.0.1 514 average rate = 6526.63 msg/sec, count=65272, time=10.008, msg size=256, bandwidth=1631.66 kB/sec

# wc -l /tmp/logs 62933 /tmp/logs

Is there a recommendation on what the buffer should be set to for high insertion rates? My test server has 8G of memory, but I can give it more (up to 24G).

Also, note that this is a VMWare ESXi server - might that have something to do with it?

It's interesting. I tried it with rmem_max=1MB, and worked without dropped messages (my machine is  Intel(R) Core(TM)2 CPU          6300  @ 1.86GHz, with ubuntu)

root@thor:/opt/syslog-ng/bin# ./loggen -r 6000 -V -D -I 30 127.0.0.1 2222 average rate = 5991.87 msg/sec, count=179757, time=30.001, (last) msg size=256, bandwidth=1497.97 kB/sec

root@thor:/var/log# wc -l test.log 179757 test.log

root@thor:/var/log# cat /proc/sys/net/core/rmem_default 1048576

But if I set the rmem_max to 1MB, I have also dropped packages, If I set the rmem_default it works... (I don't know why, I am not an udp-kernel magus). Will you try if you set rmem_default instead of rmem_max?

On Wed, Apr 14, 2010 at 6:16 AM, Zoltán Pallagi <pzolee@balabit.hu> wrote:

Hi,

I think it's not a syslog-ng problem, the udp buffer of your kernel will be full, and the kernel drops the udp packages (to make sure, you can try to use netcat (netcat -lu -p 514 >> aaa.txt) instead of syslog-ng, I think the logs will be missed in this case too).

before running loggen, please check the value of the packet receive errors: root@thor:/var/log# netstat -su Udp:     124383 packets received     3 packets to unknown port received.     82487 packet receive errors     166196 packets sent     RcvbufErrors: 82487

then check it after running. I guess, you will see the missing packets (just check the difference between before and after).

so, if I am right, you just have to increase the size of the udp receive buffer and it will work. For example: echo "88888888" > /proc/sys/net/core/rmem_default (or rmem_max)

for more details about udp buffering: http://www.29west.com/docs/THPM/udp-buffer-sizing.html

Clayton Dukes wrote:

Finally getting a chance to revisit this. I'm still seeing the problem.

If I run loggen like so: /www/svn/loggen -r 600 -D -I 30 127.0.0.1 514 average rate = 607.51 msg/sec, count=18226, time=30.012, msg size=256, bandwidth=151.88 kB/sec

I only get around 8k messages: wc -l /var/log/logzilla/syslog.log 8740 /var/log/logzilla/syslog.log

I've tried bumping up flush_lines and the fifo but neither seemed to make much of a difference.

Here's my config: options {       long_hostnames(off);       log_msg_size(8192);       flush_lines(1); # Note: I've tried this up to 1000       log_fifo_size(35535);       time_reopen(10);       use_dns(yes);       dns_cache(yes);       use_fqdn(yes);       keep_hostname(yes);       chain_hostnames(no); };

destination df_logzilla {    file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n")    ); };

log {    source(s_all);       destination(df_logzilla); }; On Thu, Apr 1, 2010 at 9:33 AM, Martin Holste <mcholste@gmail.com> wrote:

What do you get if you send the loggen data to a simple netcat session with its output redirected to a flat file?  Do you see all 55k messages using wc -l?

On Thu, Apr 1, 2010 at 6:51 AM, Clayton Dukes <cdukes@gmail.com> wrote:

I should have mentioned that this is logging directly to a file.

destination df_logzilla {    file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n")    ); };

On Wed, Mar 31, 2010 at 11:47 PM, Clayton Dukes <cdukes@gmail.com> wrote:

Hi Folks, I'm trying to run a test to check insert rates. If I run this command:

./loggen -r 5000 -D -I 10 127.0.0.1 514

The output shows: average rate = 5441.60 msg/sec, count=54420, time=10.007, msg size=256, bandwidth=1360.40 kB/sec

But, my stats don't show that many messages received:

syslog-ng[6660]: Log statistics; dropped=\'pipe(/dev/xconsole)=0\', processed=\'center(queued)=24232\', processed=\'center(received)=8077, processed=\'destination(df_logzilla)=8077\'

As you can see, it sent 55k messages, but I only received 8k. Am I doing something wrong?

Here are my options in the syslog-ng config: options {       long_hostnames(off);       log_msg_size(8192);       flush_lines(1);       log_fifo_size(16384);       time_reopen(10);       use_dns(yes);       dns_cache(yes);       use_fqdn(yes);       keep_hostname(yes);       chain_hostnames(no);       perm(0644);      stats_freq(60);

};

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________

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

-- pzolee

-- pzolee

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________ Clayton Dukes ______________________________________________________________

2010.04.14. 19:43 keltezéssel, Clayton Dukes írta:

Well...now that the system is getting all the messages, it seems that syslog-ng is still not writing everything.

#/www/svn/lgentest.sh 10000 10 average rate = 10883.79 msg/sec, count=108838, time=10.000, msg size=256, bandwidth=2720.95 kB/sec

# wc -l syslog.log 35179 syslog.log

Here are my options in the syslog-ng config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); log_fifo_size(100000); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); perm(0644); stats_freq(60);

};

Any suggestions?

Did you restart your machine? The changes under /proc are only temporary

On Wed, Apr 14, 2010 at 12:18 PM, Clayton Dukes<cdukes@gmail.com> wrote:

...

For anyone searching the Goog and finding this thread later on, I've created an explanation of everything in my Wiki: http://nms.gdd.net/index.php/Install_Guide_for_LogZilla_v3.0#UDP_Buffers

Hope it helps!

On Wed, Apr 14, 2010 at 12:10 PM, Clayton Dukes<cdukes@gmail.com> wrote:

...

Yay! That did it. Thanks!

On Wed, Apr 14, 2010 at 11:30 AM, Zoltán Pallagi<pzolee@balabit.hu> wrote:

...

Clayton Dukes wrote:

Excellent link, thanks! That does seem to be the problem, however, if I set the buffer all the way up to 1G using: sysctl -w net.core.rmem_max=1073741824

Then I'm still dropping messages when using a test rate of 6kmps:

# ./loggen -r 6000 -D -I 10 127.0.0.1 514 average rate = 6526.63 msg/sec, count=65272, time=10.008, msg size=256, bandwidth=1631.66 kB/sec

# wc -l /tmp/logs 62933 /tmp/logs

Is there a recommendation on what the buffer should be set to for high insertion rates? My test server has 8G of memory, but I can give it more (up to 24G).

Also, note that this is a VMWare ESXi server - might that have something to do with it?

It's interesting. I tried it with rmem_max=1MB, and worked without dropped messages (my machine is Intel(R) Core(TM)2 CPU 6300 @ 1.86GHz, with ubuntu)

root@thor:/opt/syslog-ng/bin# ./loggen -r 6000 -V -D -I 30 127.0.0.1 2222 average rate = 5991.87 msg/sec, count=179757, time=30.001, (last) msg size=256, bandwidth=1497.97 kB/sec

root@thor:/var/log# wc -l test.log 179757 test.log

root@thor:/var/log# cat /proc/sys/net/core/rmem_default 1048576

But if I set the rmem_max to 1MB, I have also dropped packages, If I set the rmem_default it works... (I don't know why, I am not an udp-kernel magus). Will you try if you set rmem_default instead of rmem_max?

On Wed, Apr 14, 2010 at 6:16 AM, Zoltán Pallagi<pzolee@balabit.hu> wrote:

Hi,

I think it's not a syslog-ng problem, the udp buffer of your kernel will be full, and the kernel drops the udp packages (to make sure, you can try to use netcat (netcat -lu -p 514>> aaa.txt) instead of syslog-ng, I think the logs will be missed in this case too).

before running loggen, please check the value of the packet receive errors: root@thor:/var/log# netstat -su Udp: 124383 packets received 3 packets to unknown port received. 82487 packet receive errors 166196 packets sent RcvbufErrors: 82487

then check it after running. I guess, you will see the missing packets (just check the difference between before and after).

so, if I am right, you just have to increase the size of the udp receive buffer and it will work. For example: echo "88888888"> /proc/sys/net/core/rmem_default (or rmem_max)

for more details about udp buffering: http://www.29west.com/docs/THPM/udp-buffer-sizing.html

Clayton Dukes wrote:

Finally getting a chance to revisit this. I'm still seeing the problem.

If I run loggen like so: /www/svn/loggen -r 600 -D -I 30 127.0.0.1 514 average rate = 607.51 msg/sec, count=18226, time=30.012, msg size=256, bandwidth=151.88 kB/sec

I only get around 8k messages: wc -l /var/log/logzilla/syslog.log 8740 /var/log/logzilla/syslog.log

I've tried bumping up flush_lines and the fifo but neither seemed to make much of a difference.

Here's my config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); # Note: I've tried this up to 1000 log_fifo_size(35535); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); };

destination df_logzilla { file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n") ); };

log { source(s_all); destination(df_logzilla); }; On Thu, Apr 1, 2010 at 9:33 AM, Martin Holste<mcholste@gmail.com> wrote:

What do you get if you send the loggen data to a simple netcat session with its output redirected to a flat file? Do you see all 55k messages using wc -l?

On Thu, Apr 1, 2010 at 6:51 AM, Clayton Dukes<cdukes@gmail.com> wrote:

I should have mentioned that this is logging directly to a file.

destination df_logzilla { file("/var/log/logzilla/syslog.log"

template("$HOST\t$FACILITY\t$LEVEL\t$TAG\t$YEAR-$MONTH-$DAY\t$HOUR:$MIN:$SEC\t$PROGRAM\t$MSG\n") ); };

On Wed, Mar 31, 2010 at 11:47 PM, Clayton Dukes<cdukes@gmail.com> wrote:

Hi Folks, I'm trying to run a test to check insert rates. If I run this command:

./loggen -r 5000 -D -I 10 127.0.0.1 514

The output shows: average rate = 5441.60 msg/sec, count=54420, time=10.007, msg size=256, bandwidth=1360.40 kB/sec

But, my stats don't show that many messages received:

syslog-ng[6660]: Log statistics; dropped=\'pipe(/dev/xconsole)=0\', processed=\'center(queued)=24232\', processed=\'center(received)=8077, processed=\'destination(df_logzilla)=8077\'

As you can see, it sent 55k messages, but I only received 8k. Am I doing something wrong?

Here are my options in the syslog-ng config: options { long_hostnames(off); log_msg_size(8192); flush_lines(1); log_fifo_size(16384); time_reopen(10); use_dns(yes); dns_cache(yes); use_fqdn(yes); keep_hostname(yes); chain_hostnames(no); perm(0644); stats_freq(60);

};

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________

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

-- pzolee

-- pzolee

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- ______________________________________________________________

Clayton Dukes ______________________________________________________________

-- pzolee

On Wed, 2010-04-14 at 17:30 +0200, Zoltán Pallagi wrote:

Clayton Dukes wrote:

...

Excellent link, thanks! That does seem to be the problem, however, if I set the buffer all the way up to 1G using: sysctl -w net.core.rmem_max=1073741824

Then I'm still dropping messages when using a test rate of 6kmps:

# ./loggen -r 6000 -D -I 10 127.0.0.1 514 average rate = 6526.63 msg/sec, count=65272, time=10.008, msg size=256, bandwidth=1631.66 kB/sec

# wc -l /tmp/logs 62933 /tmp/logs

Is there a recommendation on what the buffer should be set to for high insertion rates? My test server has 8G of memory, but I can give it more (up to 24G).

Also, note that this is a VMWare ESXi server - might that have something to do with it?

It's interesting. I tried it with rmem_max=1MB, and worked without dropped messages (my machine is Intel(R) Core(TM)2 CPU 6300 @ 1.86GHz, with ubuntu)

root@thor:/opt/syslog-ng/bin# ./loggen -r 6000 -V -D -I 30 127.0.0.1 2222 average rate = 5991.87 msg/sec, count=179757, time=30.001, (last) msg size=256, bandwidth=1497.97 kB/sec

root@thor:/var/log# wc -l test.log 179757 test.log

root@thor:/var/log# cat /proc/sys/net/core/rmem_default 1048576

But if I set the rmem_max to 1MB, I have also dropped packages, If I set the rmem_default it works... (I don't know why, I am not an udp-kernel magus). Will you try if you set rmem_default instead of rmem_max?

quoting socket(7) on Linux rmem_default contains the default setting in bytes of the socket receive buffer. rmem_max contains the maximum socket receive buffer size in bytes which a user may set by using the SO_RCVBUF socket option. syslog-ng allows you to change the socket buffer given rmem_max allows that using the so_rcvbuf() option for the given source. Changing rmem_default at the system scope might be a bit of an overkill, as _all_ udp sockets would get this large socket buffers. And socket buffers are in non-pageable memory, don't forget that. -- Bazsi

On Wed, 2010-04-14 at 13:18 -0700, Evan Rempel wrote:

A little background.

There is a "server" syslog-ng process that accepts messages from the network and sends the messages to a variety of destinations. For this report, I am only interested in one destination that happens to be a pipe.

There is a "slave" syslog-ng process that reads from the pipe that the "server" writes to, and writes to a program destination.

The program reads the standard in, and does "something". All works well.

At some point our application (we know why and don't want to discuss it) application stops reading standard in for a while (1,000,000 lines over an hour). We expect that the memory footprint of syslog-ng "slave" to grow during this time but it does not. Instead, the memory footprint of the syslog-ng "server" grows. When our application starts reading its standard in again, the memory footprint of the syslog "slave" grows very quickly, and all messages reach the destination.

I think that the syslog-ng "slave" get blocked on the program destination in a way that prevents it from reading its source, resulting in the upstream syslog-ng "server" having to buffer all of the messages.

There is no flow control anywhere, and both syslog-ng instances have log_fifo_size(8000000) for all of the destinations.

Anyone have any suggestions?

Hmm, either the slave syslog-ng really blocks (but I don't know any similar bugs right now), or flow control is enabled. There was a bug that caused flow-control to be enabled, if any of the flags was used. Do you have fallback enabled? Can you post the exact versions of syslog-ng you are using? Also, you could confirm if the slave instance really blocks, or it has just stalled one of its sources. You could do that by attaching to the slave process using strace for a little while. 1) first check what fd is being used between master/slave (lsof -p <pid>) 2) then check via strace if that fd is being polled for POLLIN or not If it is not polled, then flow-control is somehow enabled, if syslog-ng is not polling but waiting somewhere, then it might be blocked as you suggest. Anyway, the list of open file descriptors and the strace dump could help in tracking down both cases. -- Bazsi

On Wed, 2010-04-14 at 14:04 -0700, Evan Rempel wrote:

Balazs Scheidler wrote:

...

On Wed, 2010-04-14 at 13:18 -0700, Evan Rempel wrote:

...

A little background.

There is a "server" syslog-ng process that accepts messages from the network and sends the messages to a variety of destinations. For this report, I am only interested in one destination that happens to be a pipe.

There is a "slave" syslog-ng process that reads from the pipe that the "server" writes to, and writes to a program destination.

The program reads the standard in, and does "something". All works well.

At some point our application (we know why and don't want to discuss it) application stops reading standard in for a while (1,000,000 lines over an hour). We expect that the memory footprint of syslog-ng "slave" to grow during this time but it does not. Instead, the memory footprint of the syslog-ng "server" grows. When our application starts reading its standard in again, the memory footprint of the syslog "slave" grows very quickly, and all messages reach the destination.

I think that the syslog-ng "slave" get blocked on the program destination in a way that prevents it from reading its source, resulting in the upstream syslog-ng "server" having to buffer all of the messages.

There is no flow control anywhere, and both syslog-ng instances have log_fifo_size(8000000) for all of the destinations.

Anyone have any suggestions?

Hmm, either the slave syslog-ng really blocks (but I don't know any similar bugs right now), or flow control is enabled.

There was a bug that caused flow-control to be enabled, if any of the flags was used. Do you have fallback enabled?

No, the only flags in the "slave" is no-parse.

...

Can you post the exact versions of syslog-ng you are using?

3.0.5 OSE

...

Also, you could confirm if the slave instance really blocks, or it has just stalled one of its sources. You could do that by attaching to the slave process using strace for a little while.

1) first check what fd is being used between master/slave (lsof -p <pid>) 2) then check via strace if that fd is being polled for POLLIN or not

If it is not polled, then flow-control is somehow enabled, if syslog-ng is not polling but waiting somewhere, then it might be blocked as you suggest.

Anyway, the list of open file descriptors and the strace dump could help in tracking down both cases.

Not to be lazy here, but I am not going to get to this for weeks, really busy at my site right now.

Here is a program that can turn on/off the reading of standard in by using kill -USR1 <PID> kill -USR2 <PID>

--------------- #!/usr/bin/perl

my $read = 0;

$SIG{USR1} = sub { $read = 1 }; $SIG{USR2} = sub { $read = 0 };

while ( not eof(STDIN)) { if ( $read == 1 ) { $line = <STDIN>; print $line; } else { sleep 1; } } ---------------

So hopefully you can reproduce this this really easy at your end.

If I don't hear back, in a few weeks I'll get to this.

I've tried it with 3.1.1, 3.0.6 and finally 3.0.5 and all behaved properly. Memory size grew until it couldn't write to the test program, of course only until the FIFO size filled up. Once I let the program go with a SIGUSR1 it started sending messages, the drop count stayed the same. Flow-control was not enabled. -- Bazsi

OK, I finally got back to this. The lsof of the forground syslog-ng process shows localhost% sudo /usr/sbin/lsof -p 18279 COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME syslog-ng 18279 root cwd DIR 253,6 4096 32793 /usr/local/etc/syslog-ng syslog-ng 18279 root rtd DIR 253,0 1024 2 / syslog-ng 18279 root txt REG 253,6 321731 233449 /usr/local/sbin/syslog-ng syslog-ng 18279 root mem REG 253,0 95464 49455 /lib64/libselinux.so.1 syslog-ng 18279 root mem REG 253,0 247496 49454 /lib64/libsepol.so.1 syslog-ng 18279 root mem REG 253,5 85928 394112 /usr/lib64/libz.so.1.2.3 syslog-ng 18279 root mem REG 253,0 647608 49451 /lib64/libglib-2.0.so.0.1200.3 syslog-ng 18279 root mem REG 253,0 1366176 49458 /lib64/libcrypto.so.0.9.8e syslog-ng 18279 root mem REG 253,5 190976 397026 /usr/lib64/libgssapi_krb5.so.2.2 syslog-ng 18279 root mem REG 253,0 10000 49465 /lib64/libcom_err.so.2.1 syslog-ng 18279 root mem REG 253,5 153464 397024 /usr/lib64/libk5crypto.so.3.1 syslog-ng 18279 root mem REG 253,5 613896 397025 /usr/lib64/libkrb5.so.3.3 syslog-ng 18279 root mem REG 253,5 35728 397023 /usr/lib64/libkrb5support.so.0.1 syslog-ng 18279 root mem REG 253,0 9728 49474 /lib64/libkeyutils-1.2.so syslog-ng 18279 root mem REG 253,0 137256 53855 /lib64/ld-2.5.so syslog-ng 18279 root mem REG 253,5 25464 393467 /usr/lib64/gconv/gconv-modules.cache syslog-ng 18279 root mem REG 253,4 493726 327686 /var/db/nscd/hosts syslog-ng 18279 root mem REG 253,0 50288 49190 /lib64/librt-2.5.so syslog-ng 18279 root mem REG 253,0 111480 49172 /lib64/libnsl-2.5.so syslog-ng 18279 root mem REG 253,6 21478 136301 /usr/local/lib/libevtlog.so.0.0.0 syslog-ng 18279 root mem REG 253,0 306632 49331 /lib64/libssl.so.0.9.8e syslog-ng 18279 root mem REG 253,0 20424 49168 /lib64/libdl-2.5.so syslog-ng 18279 root mem REG 253,0 1712216 49160 /lib64/libc-2.5.so syslog-ng 18279 root mem REG 253,0 142696 49186 /lib64/libpthread-2.5.so syslog-ng 18279 root mem REG 253,0 89800 49188 /lib64/libresolv-2.5.so syslog-ng 18279 root 0u CHR 136,1 3 /dev/pts/1 syslog-ng 18279 root 1u CHR 136,1 3 /dev/pts/1 syslog-ng 18279 root 2u CHR 136,1 3 /dev/pts/1 syslog-ng 18279 root 3u FIFO 253,4 491523 /var/log/syslog.pipes/erempel syslog-ng 18279 root 4u IPv4 121995943 TCP localhost:34513->localhost.localdomain:1514 (ESTABLISHED) syslog-ng 18279 root 5w FIFO 0,6 121995942 pipe syslog-ng 18279 root 6u unix 0xffff81043fd3f100 121995946 /var/syslog-ng.ctl And the strace and configuration file are attached. I'm not an strace expert, but it looks like the source is polled, but once the output can not be written to, the source is not read, even though the poll shows data is available. Thanks for looking at this. Balazs Scheidler wrote:

On Wed, 2010-04-14 at 14:04 -0700, Evan Rempel wrote:

...

Balazs Scheidler wrote:

...

On Wed, 2010-04-14 at 13:18 -0700, Evan Rempel wrote:

...

A little background.

There is a "server" syslog-ng process that accepts messages from the network and sends the messages to a variety of destinations. For this report, I am only interested in one destination that happens to be a pipe.

There is a "slave" syslog-ng process that reads from the pipe that the "server" writes to, and writes to a program destination.

The program reads the standard in, and does "something". All works well.

At some point our application (we know why and don't want to discuss it) application stops reading standard in for a while (1,000,000 lines over an hour). We expect that the memory footprint of syslog-ng "slave" to grow during this time but it does not. Instead, the memory footprint of the syslog-ng "server" grows. When our application starts reading its standard in again, the memory footprint of the syslog "slave" grows very quickly, and all messages reach the destination.

I think that the syslog-ng "slave" get blocked on the program destination in a way that prevents it from reading its source, resulting in the upstream syslog-ng "server" having to buffer all of the messages.

There is no flow control anywhere, and both syslog-ng instances have log_fifo_size(8000000) for all of the destinations.

Anyone have any suggestions? Hmm, either the slave syslog-ng really blocks (but I don't know any similar bugs right now), or flow control is enabled.

There was a bug that caused flow-control to be enabled, if any of the flags was used. Do you have fallback enabled? No, the only flags in the "slave" is no-parse.

...

Can you post the exact versions of syslog-ng you are using? 3.0.5 OSE

...

Also, you could confirm if the slave instance really blocks, or it has just stalled one of its sources. You could do that by attaching to the slave process using strace for a little while.

1) first check what fd is being used between master/slave (lsof -p <pid>) 2) then check via strace if that fd is being polled for POLLIN or not

If it is not polled, then flow-control is somehow enabled, if syslog-ng is not polling but waiting somewhere, then it might be blocked as you suggest.

Anyway, the list of open file descriptors and the strace dump could help in tracking down both cases.

Not to be lazy here, but I am not going to get to this for weeks, really busy at my site right now.

Here is a program that can turn on/off the reading of standard in by using kill -USR1 <PID> kill -USR2 <PID>

--------------- #!/usr/bin/perl

my $read = 0;

$SIG{USR1} = sub { $read = 1 }; $SIG{USR2} = sub { $read = 0 };

while ( not eof(STDIN)) { if ( $read == 1 ) { $line = <STDIN>; print $line; } else { sleep 1; } } ---------------

So hopefully you can reproduce this this really easy at your end.

If I don't hear back, in a few weeks I'll get to this.

I've tried it with 3.1.1, 3.0.6 and finally 3.0.5 and all behaved properly. Memory size grew until it couldn't write to the test program, of course only until the FIFO size filled up.

Once I let the program go with a SIGUSR1 it started sending messages, the drop count stayed the same. Flow-control was not enabled.

-- Evan Rempel erempel@uvic.ca Senior Systems Administrator 250.721.7691 Unix Services, University Systems, University of Victoria @version: 3.0 # # UVic syslog-ng configuration options { log_fifo_size(1000000); use_fqdn(yes); keep_hostname(yes); chain_hostnames(yes); time_reap(60); time_reopen(5); flush_lines(1000); flush_timeout(1000); }; template t_application { template("$MESSAGE\n"); template_escape(no); }; template t_localsyslog { template("<$PRI>$S_ISODATE $HOST erempel: $MSGONLY\n"); template_escape(no); }; source local { pipe("/var/log/syslog.pipes/erempel" flags(no-parse) ); }; source int { internal(); }; destination localsyslog { tcp("localhost" port(1514) localip(wolverine.comp.uvic.ca) template(t_localsyslog) log_fifo_size(5000) ); }; destination erempel { program("/home1l/erempel/read-noread.pl" template(t_application) log_fifo_size(8000000) ); }; log { source(local); destination(erempel); }; log { source(int); destination(localsyslog); };