Even worse case
<6>1 2011-12-31T12:04:05.036812+08:00 squid6 kernel - - imklog 5.8.6,
log source = /proc/kmsg started.
...several SYN flooding entries in the same second...
*** glibc detected *** /sbin/rsyslogd: free(): invalid next size
(fast): 0x00007fafb8000e00 ***
*** glibc detected *** /sbin/rsyslogd: malloc(): memory corruption:
0x00007fafb8000e20 ***
And possibly hours later the host was not responsive to ssh
connection requests, and even TTY login attempts failed...
Interestingly the debug log in another file continues a little beyond:
Debug line with all properties:
FROMHOST: 'squid6', fromhost-ip: '127.0.0.1', HOSTNAME: 'squid6', PRI: 47,
syslogtag 'rsyslogd-pstats:', programname: 'rsyslogd-pstats',
APP-NAME: 'rsyslogd-pstats', PROCID: '', MSGID: '-',
TIMESTAMP: 'Dec 31 12:24:05', STRUCTURED-DATA: '-',
msg: 'main Q[DA]: size=0 enqueued=0 full=0 maxqsize=0 '
escaped msg: 'main Q[DA]: size=0 enqueued=0 full=0 maxqsize=0 '
inputname: impstats rawmsg: 'main Q[DA]: size=0 enqueued=0 full=0 maxqsize=0 '
Debug line with all properties:
FROMHOST: 'squid6', fromhost-ip: '127.0.0.1', HOSTNAME: 'squid6', PRI: 47,
syslogtag 'rsyslogd-pstats:', programname: 'rsyslogd-pstats',
APP-NAME: 'rsyslogd-pstats', PROCID: '', MSGID: '-',
TIMESTAMP: 'Dec 31 12:24:05', STRUCTURED-DATA: '-',
msg: 'main Q: size=4 enqueued=30 full=0 maxqsize=5 '
escaped msg: 'main Q: size=4 enqueued=30 full=0 maxqsize=5 '
inputname: impstats rawmsg: 'main Q: size=4 enqueued=30 full=0 maxqsize=5 '
Fortunately the squid service on that host was not badly affected. So
I did graceful failover and reboot the host, everything became OK.
Although there was no direct timestamp associated, I guess the problem
occured soon after rsyslogd started. I also spotted several corrupted
messages on other hosts when rsyslogd started. They are same version:
# rsyslogd -v
rsyslogd 5.8.6, compiled with:
FEATURE_REGEXP: Yes
FEATURE_LARGEFILE: No
GSSAPI Kerberos 5 support: Yes
FEATURE_DEBUG (debug build, slow code): No
32bit Atomic operations supported: Yes
64bit Atomic operations supported: Yes
Runtime Instrumentation (slow code): No
Thanks,
Kaiwang
2011/12/31 Kaiwang Chen <[email protected]>:
> Also spotted corrupted messages from imuxsock:
>
> Debug line with all properties:
> FROMHOST: 'squid9', fromhost-ip: '127.0.0.1', HOSTNAME: 'squid9', PRI: 47,
> syslogtag 'rsyslogd-pstats:', programname: '<88>+?<99>2
> <88>+?<99>rssyslogd-pstats', APP-NAME: '', PROCID: '', MSGID: '-',
> TIMESTAMP: 'Dec 30 21:46:14', STRUCTURED-DATA: '-',
> msg: 'imuxsock: submitted=429 ratelimit.discarded=0
> ratelimit.numratelimiters=213 '
> escaped msg: 'imuxsock: submitted=429 ratelimit.discarded=0
> ratelimit.numratelimiters=213 '
> inputname: impstats rawmsg: 'imuxsock: submitted=429
> ratelimit.discarded=0 ratelimit.numratelimiters=213 '
>
>
> Thanks,
> Kaiwang
>
> 2011/12/27 Kaiwang Chen <[email protected]>:
>> 2011/12/25 <[email protected]>:
>>> On Fri, 23 Dec 2011, Kaiwang Chen wrote:
>>>
>>>> Hi all,
>>>>
>>>> I found rsyslogd occasionally produced corrupted log entries like
>>>>
>>>> <6>1 2011-12-23T23:03:18.089938+08:00 db1 <D0>#001 D^kernel - -
>>>> device eth0 entered promiscuous mode
>>>>
>>>> I believe that problem appeared in earlier versions including 5.8.2.
>>>> Looks like corruption never occur before hostname field. Is it a
>>>> reported bug? Any clue?
>>>
>>>
>>> the question is if this problem is in the raw message being sent to you, or
>>> is it something added by the rsyslog processing.
>>>
>>> I would suggest adding something along the following line.
>>>
>>> :rawmesg, :contains, "#001" /var/log/badmessages:RSYSLOG_DEBUG
>>>
>>> this will look for any messages with the hex 01 character in them and spit
>>> out all the info that you can use about the message in to the file
>>> /var/log/badmessages
>>>
>>> run this for a little while and look to see what the raw message that is
>>> being received over the wire looks like. If it's bad, then you need to look
>>> at the sender. If the raw message looks sane, but rsyslog isn't handling it
>>> right, then we can troubleshoot from there.
>>
>> Looks like it's related to tcp transmission. On the original server
>> that get input from unix socket, it is OK; while on the centeral log
>> server, the raw message is already corrupted.
>>
>> ===== on central log server
>> <30>1 2011-12-27T14:06:56+08:00 gw71 snmpd 24254 - - Connection from
>> UDP: [172.25.0.230]:53547
>> <30>1 2011-12-27T14:06:56+08:00 gw71 snmpd 24254 - - Received SNMP
>> packet(s) from UDP: [172.25.0.230]:53547
>> <30>1 2011-12-27T14:06:56+08:00 gw71 snmpd 2#032#025<D5>1 - -
>> Connection from UDP: [172.25.0.230]:53547
>>
>> Debug line with all properties:
>> FROMHOST: '172.25.0.71', fromhost-ip: '172.25.0.71', HOSTNAME: 'gw71', PRI:
>> 30,
>> syslogtag 'snmpd[24254]', programname: 'snmpd', APP-NAME: 'snmpd',
>> PROCID: '24254', MSGID: '-',
>> TIMESTAMP: 'Dec 27 14:06:56', STRUCTURED-DATA: '-',
>> msg: ' Connection from UDP: [172.25.0.230]:53547'
>> escaped msg: ' Connection from UDP: [172.25.0.230]:53547'
>> inputname: imptcp rawmsg: '<30>1 2011-12-27T14:06:56+08:00 gw71 snmpd
>> 24254 - - Connection from UDP: [172.25.0.230]:53547'
>>
>> Debug line with all properties:
>> FROMHOST: '172.25.0.71', fromhost-ip: '172.25.0.71', HOSTNAME: 'gw71', PRI:
>> 30,
>> syslogtag 'snmpd[24254]', programname: 'snmpd', APP-NAME: 'snmpd',
>> PROCID: '24254', MSGID: '-',
>> TIMESTAMP: 'Dec 27 14:06:56', STRUCTURED-DATA: '-',
>> msg: ' Received SNMP packet(s) from UDP: [172.25.0.230]:53547'
>> escaped msg: ' Received SNMP packet(s) from UDP: [172.25.0.230]:53547'
>> inputname: imptcp rawmsg: '<30>1 2011-12-27T14:06:56+08:00 gw71 snmpd
>> 24254 - - Received SNMP packet(s) from UDP: [172.25.0.230]:53547'
>>
>> Debug line with all properties:
>> FROMHOST: '172.25.0.71', fromhost-ip: '172.25.0.71', HOSTNAME: 'gw71', PRI:
>> 30,
>> syslogtag 'snmpd[2#032#025<D5>1]', programname: 'snmpd', APP-NAME:
>> 'snmpd', PROCID: '2#032#025<D5>1', MSGID: '-',
>> TIMESTAMP: 'Dec 27 14:06:56', STRUCTURED-DATA: '-',
>> msg: ' Connection from UDP: [172.25.0.230]:53547'
>> escaped msg: ' Connection from UDP: [172.25.0.230]:53547'
>> inputname: imptcp rawmsg: '<30>1 2011-12-27T14:06:56+08:00 gw71 snmpd
>> 2#032#025<D5>1 - - Connection from UDP: [172.25.0.230]:53547'
>>
>> ===== on the orginal host (*.* @@(o)172.25.0.230:514)
>> <30>1 2011-12-27T14:06:56+08:00 gw71 snmpd 24254 - - Connection from
>> UDP: [172.25.0.230]:53547
>> <30>1 2011-12-27T14:06:56+08:00 gw71 snmpd 24254 - - Received SNMP
>> packet(s) from UDP: [172.25.0.230]:53547
>> <30>1 2011-12-27T14:06:56+08:00 gw71 snmpd 24254 - - Connection from
>> UDP: [172.25.0.230]:53547
>>
>> Debug line with all properties:
>> FROMHOST: 'gw71', fromhost-ip: '127.0.0.1', HOSTNAME: 'gw71', PRI: 30,
>> syslogtag 'snmpd[24254]:', programname: 'snmpd', APP-NAME: 'snmpd',
>> PROCID: '24254', MSGID: '-',
>> TIMESTAMP: 'Dec 27 14:06:56', STRUCTURED-DATA: '-',
>> msg: ' Connection from UDP: [172.25.0.230]:53547'
>> escaped msg: ' Connection from UDP: [172.25.0.230]:53547'
>> inputname: imuxsock rawmsg: '<30>Dec 27 14:06:56 snmpd[24254]:
>> Connection from UDP: [172.25.0.230]:53547'
>>
>> Debug line with all properties:
>> FROMHOST: 'gw71', fromhost-ip: '127.0.0.1', HOSTNAME: 'gw71', PRI: 30,
>> syslogtag 'snmpd[24254]:', programname: 'snmpd', APP-NAME: 'snmpd',
>> PROCID: '24254', MSGID: '-',
>> TIMESTAMP: 'Dec 27 14:06:56', STRUCTURED-DATA: '-',
>> msg: ' Received SNMP packet(s) from UDP: [172.25.0.230]:53547'
>> escaped msg: ' Received SNMP packet(s) from UDP: [172.25.0.230]:53547'
>> inputname: imuxsock rawmsg: '<30>Dec 27 14:06:56 snmpd[24254]:
>> Received SNMP packet(s) from UDP: [172.25.0.230]:53547'
>>
>> Debug line with all properties:
>> FROMHOST: 'gw71', fromhost-ip: '127.0.0.1', HOSTNAME: 'gw71', PRI: 30,
>> syslogtag 'snmpd[24254]:', programname: 'snmpd', APP-NAME: 'snmpd',
>> PROCID: '24254', MSGID: '-',
>> TIMESTAMP: 'Dec 27 14:06:56', STRUCTURED-DATA: '-',
>> msg: ' Connection from UDP: [172.25.0.230]:53547'
>> escaped msg: ' Connection from UDP: [172.25.0.230]:53547'
>> inputname: imuxsock rawmsg: '<30>Dec 27 14:06:56 snmpd[24254]:
>> Connection from UDP: [172.25.0.230]:53547'
>>
>>
>> Thanks,
>> Kaiwang
>>>
>>> David Lang
>>>
>>> > rsyslogd 5.8.6, compiled with:
>>>>
>>>> FEATURE_REGEXP: Yes
>>>> FEATURE_LARGEFILE: No
>>>> GSSAPI Kerberos 5 support: Yes
>>>> FEATURE_DEBUG (debug build, slow code): No
>>>> 32bit Atomic operations supported: Yes
>>>> 64bit Atomic operations supported: Yes
>>>> Runtime Instrumentation (slow code): No
>>>>
>>>> /etc/rsyslog.conf
>>>> $ActionFileDefaultTemplate RSYSLOG_SyslogProtocol23Format
>>>> $ActionForwardDefaultTemplate RSYSLOG_SyslogProtocol23Format
>>>>
>>>> $ModLoad imklog
>>>> $ModLoad imuxsock
>>>> $ModLoad impstats
>>>>
>>>> $SystemLogSocketIgnoreMsgTimestamp off
>>>> $SystemLogUsePIDFromSystem on
>>>>
>>>> $PStatInterval 600
>>>> $PStatSeverity 7
>>>>
>>>> $WorkDirectory /var/spool/rsyslog
>>>>
>>>> $MainMsgQueueSaveOnShutdown on
>>>> $MainMsgQueueFileName mq
>>>> $MainMsgQueueMaxFileSize 5m
>>>>
>>>> $ActionQueueType LinkedList
>>>> $ActionQueueSaveOnShutdown on
>>>> $ActionQueueFileName dbq
>>>> $ActionQueueMaxFileSize 10m
>>>> $ActionResumeRetryCount -1
>>>> *.* @@(o)10.2.3.4
>>>>
>>>>
>>>> # Log all kernel messages to the console.
>>>> # Logging much else clutters up the screen.
>>>> #kern.* /dev/console
>>>>
>>>> # Log anything (except mail) of level info or higher.
>>>> # Don't log private authentication messages!
>>>> *.info;mail.none;authpriv.none;cron.none /var/log/messages
>>>>
>>>> # The authpriv file has restricted access.
>>>> authpriv.* /var/log/secure
>>>>
>>>> # Log all the mail messages in one place.
>>>> mail.* -/var/log/maillog
>>>>
>>>>
>>>> # Log cron stuff
>>>> cron.* /var/log/cron
>>>>
>>>> # Everybody gets emergency messages
>>>> *.emerg *
>>>>
>>>> # Save news errors of level crit and higher in a special file.
>>>> uucp,news.crit /var/log/spooler
>>>>
>>>> # Save boot messages also to boot.log
>>>> local7.* /var/log/boot.log
>>>>
>>>>
>>>> Thanks,
>>>> Kaiwang
>>>> _______________________________________________
>>>> rsyslog mailing list
>>>> http://lists.adiscon.net/mailman/listinfo/rsyslog
>>>> http://www.rsyslog.com/professional-services/
>>>>
>>> _______________________________________________
>>> rsyslog mailing list
>>> http://lists.adiscon.net/mailman/listinfo/rsyslog
>>> http://www.rsyslog.com/professional-services/
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
