rsyslog: first logged message is lost when server is down
This document (7008482) is provided subject to the disclaimer at the end of this document.
Environment
SUSE Linux Enterprise Server 11 Service Pack 1
Situation
When the rsyslog server is up, clients will send their log messages to the server.
It can happen that the server doesn't get the 1st message logged after the server went down.
This can be demonstrated with the "logger" command on the client. For instance:
All logger messages will show up, except "1"
When the rsyslog on the client writes the data before it receives the close request from the server and closes the TCP connection, the data is lost. The data was send before the client realized that the server is down and queues up the messages for later re-send.
The following rsyslog messages (from the above example) on the client, show this:
Then if you look at the second "logger 2" syslog you'll see it is not send:
A patch checking if the connection is still alive right before sending resolves the problem.
When the log server goes off-line for a time, clients queue up messages and when the server comes back on-line, the clients send those queued messages to the server.
It can happen that the server doesn't get the 1st message logged after the server went down.
This can be demonstrated with the "logger" command on the client. For instance:
server# service syslog stop
client# logger "1"
client# logger "2"
client# logger "3"
server# service syslog start
All logger messages will show up, except "1"
When the rsyslog on the client writes the data before it receives the close request from the server and closes the TCP connection, the data is lost. The data was send before the client realized that the server is down and queues up the messages for later re-send.
The following rsyslog messages (from the above example) on the client, show this:
2721.516104810:main queue:Reg/w0: result of expression evaluation: 0As you can see although syslog was stopped, the message (all 38 bytes) is send over TCP.
2721.516126880:main queue:Reg/w0: Called action, logging to builtin-file (/var/log/messages)
2721.517325156:action 1 queue:Reg/w0: action 1 queue: entering rate limiter
2721.517364182:action 1 queue:Reg/w0: action 1 queue: entry deleted, state 0, size now 0 entries
2721.517399692:action 1 queue:Reg/w0: 10.10.10.70:514/tcp
2721.517948684:action 1 queue:Reg/w0: TCP sent 38 bytes, requested 38
Then if you look at the second "logger 2" syslog you'll see it is not send:
The window for this to happen is really short but in an environment where you need reliability, lost messages need to be avoided.
2723.245788686:action 1 queue:Reg/w0: action 1 queue: entry deleted, state 0, size now 0 entries
2723.245906306:action 1 queue:Reg/w0: 10.10.10.70:514/tcp
2723.245949832:action 1 queue:Reg/w0: TCP sent -1 bytes, requested 38
2723.245966140:action 1 queue:Reg/w0: message not (tcp)send2723.246514947:main queue:Reg/w0: main queue: entering rate limiter
A patch checking if the connection is still alive right before sending resolves the problem.
Resolution
The rsyslog update to rsyslog-3.18.3-7.22.1 released June 2011 includes the solution to resolve this problem. Please install the recommended update.
Disclaimer
This Support Knowledgebase provides a valuable tool for SUSE customers and parties interested in our products and solutions to acquire information, ideas and learn from one another. Materials are provided for informational, personal or non-commercial use within your organization and are presented "AS IS" WITHOUT WARRANTY OF ANY KIND.
- Document ID:7008482
- Creation Date: 28-Apr-2011
- Modified Date:03-Mar-2020
-
- SUSE Linux Enterprise Server
For questions or concerns with the SUSE Knowledgebase please contact: tidfeedback[at]suse.com
