2

I configured rsyslog to send logs to a central logging server like this:

*.* @@192.168.1.20
$ActionExecOnlyWhenPreviousIsSuspended on
& @@192.168.1.21
& /var/log/failover
$ActionExecOnlyWhenPreviousIsSuspended off

It works well, except when machine is booting. When the virtual machine starts and approximately twenty seconds after the machine starts, no messages are sent to 192.168.1.20 or 192.168.1.21. However, /var/log/failover contains all those “lost” messages.

As a test, I started the machine and entered by hand:

$ logger 1
$ logger 2
$ logger 3
...

The first central logging server contains just:

Nov 28 13:57:40 demo arsene: 10

The second logging server contains no messages from the demo machine.

Finally, var/log/failover on demo machine contains:

Nov 28 13:57:10 demo rsyslogd: [origin software="rsyslogd" swVersion="7.4.4" x-pid="361" x-info="http://www.rsyslog.com"] start
Nov 28 13:57:10 demo rsyslogd: rsyslogd's groupid changed to 104
Nov 28 13:57:10 demo rsyslogd: rsyslogd's userid changed to 101
... # more than a hundred usual messages from the kernel
Nov 28 13:57:20 demo kernel: [   12.127981] random: nonblocking pool is initialized
Nov 28 13:57:21 demo arsene: 1
Nov 28 13:57:22 demo arsene: 2
Nov 28 13:57:23 demo arsene: 3
Nov 28 13:57:25 demo arsene: 4
Nov 28 13:57:27 demo arsene: 5
Nov 28 13:57:28 demo arsene: 6
Nov 28 13:57:30 demo arsene: 7
Nov 28 13:57:32 demo arsene: 8
Nov 28 13:57:37 demo arsene: 9

I encounter this issue for both Ubuntu and Debian virtual machines.

Additional notes:

  1. The network connectivity looks fine. If I try ping 192.168.1.20 and curl google.com during the period where the log messages are not sent to the log server, both ping and curl succeed.

  2. Disabling the firewall of the logging server has no effect.

  3. Running tcpdump shows that nothing is being sent to the log server during the twenty seconds period.

  4. Other Ubuntu machines on the network (which were deployed using a very different approach) report their logs to the logging server fine, including during the boot.

  5. By comparing the faulty machines to the correct ones, I noticed a version mismatch (7 vs. 8) for rsyslogd. Upgrading rsyslogd on faulty machines to version 8.14.0 haven't fixed the issue, but now I see the following message a bit after the log reporting starts working:

    Nov 29 02:18:39 demo rsyslogd-2359: action 'action 11' resumed (module 'builtin:omfwd') [v8.14.0 try http://www.rsyslog.com/e/2359 ]
    
  6. diff shows that /etc/rsyslog.conf and /etc/rsyslog.d/*.conf files are exactly the same between the new faulty machines and the old working ones.

  7. A apt-get update, apt-get upgrade and even apt-get dist-upgrade haven't fixed the problem.

  • tcpdump showed there is icmp traffic to the logging server due to the ping but no udp traffic directed to the logging server, correct? – Mark Plotnick Nov 29 '15 at 3:02
  • @MarkPlotnick: tcpdump showed nothing at all during twenty seconds when running logger commands. Also, there should be normally no UDP traffic: the client is configured to use TCP (two @ in *.* @@192.168.1.20). Note that tcpdump was called like this: sudo tcpdump -n -s 1500 -X port 514. – Arseni Mourzenko Nov 29 '15 at 10:32
  • Sorry, I didn't notice that it was TCP. rsyslog has an actionresumeinterval that is 30 seconds by default. Can you try setting it to a smaller value before any directives that use TCP connections? Depending on your network hardware and things like spanning tree settings, packets may be dropped for a few seconds after an ethernet port is brought up. – Mark Plotnick Nov 29 '15 at 13:50
  • Excellent! By setting $ActionResumeInterval to 1, the first message reported to the central log server during the boot is a kernel message at approximately 2.8 s. Can you please promote your comment to an answer so I could accept it? – Arseni Mourzenko Nov 29 '15 at 14:11
2

As @ThomasDickey said, networking may not be completely started when userland programs start to run. Many enterprise ethernet switches don't accept packets for a number of seconds after an interface comes up, as they try to negotiate spanning tree settings.

rsyslog has an actionresumeinterval setting that is 30 seconds by default. If you set it to a smaller value before any directives that use TCP connections, that will increase the retry rate, and the connections ought to get completed more quickly.

There are also additional options you can set to ensure that early messages which are not sent immediately get delivered as soon as the connection is ready. For instance, you can use the options similar to:

$ActionResumeInterval 5
$ActionQueueType disk
$WorkDirectory /var/spool/rsyslog
$ActionQueueFilename actionRq
$ActionQueueMaxDiskSpace 1m
$ActionQueueSize 4000
$ActionQueueTimeoutEnqueue    0
$ActionResumeRetryCount -1
1

Probably networking hasn't completely started during those 20 seconds. Until that happens, rsyslog has no one to talk to, so it is written locally.

  • It looks like the network is started. I tried to mix logger <digit> with ping 192.168.1.20 and curl google.com: both ping and curl run successfully during those twenty seconds while logging messages are not reported to 192.168.1.20. – Arseni Mourzenko Nov 28 '15 at 15:02

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.