auth.log entries abnormal date sequence
I was looking over the auth.log on one of my servers (running Xubuntu 14.04 LTS) to see how my brute-force 'friends' were faring and noticed that some entries are appearing out of normal date sequence. Here's a sample of the latest entries that I grepped out of the log:
Code:
Dec 18 10:56:46 serv1 sshd[16577]: Failed password for invalid user test from 5.56.160.101 port 35932 ssh2 There's a thread reporting similar behavior at http://serverfault.com/questions/636...ate-order?lq=1 but no solution there. I can verify that I have only one rsyslogd process running. Any ideas? |
No idea (and checking right now one Rsyslogd PID is running won't work if you -HUP it on logrotate IMHO) but please check:
- are any other service log entries out of whack or only sshd? - do you run a NTP daemon? - if you run atop or any other fine grained SAR, can you see if there has been high CPU or disk I/O during these periods? - is syslog fed via systemd or does Rsyslogd grab directly from /dev/klog? - Do you use a lot of templates, filtering or other potentially resource-hogging stuff in rsyslog.conf? |
- are any other service log entries out of whack or only sshd?
only sshd - do you run a NTP daemon? yes - if you run atop or any other fine grained SAR, can you see if there has been high CPU or disk I/O during these periods? I haven't been running any SAR, but highly doubt that there has been any intensive activity on this machine at these times. It's only ssh (no http or ftp server) and the only successful logins are me and CRON. - is syslog fed via systemd or does Rsyslogd grab directly from /dev/klog? Sorry, I don't know the answer to this, or how to find out. - Do you use a lot of templates, filtering or other potentially resource-hogging stuff in rsyslog.conf? Nothing. rsyslog.conf and 50-default.conf are exactly as provided by default, and RSYSLOGD_OPTIONS (in /etc/default/rsyslog) is null. I can add that each of the out of sequence entries is a duplicate copy of an in-sequence entry but with a timestamp 1 or 2 seconds later than its corresponding in-sequence entry. They all seem to originate during Nov 17 - Dec 6. At first they seemed to be following their own date-sequence order, but then I found a number of exceptions to that. It's possible that there are several (3 or more) overlapping sequences, as if they're popping out of multiple overlapping fifo buffers, but I have no idea what would produce that. |
PS: /var/spool/rsyslog/ is empty.
After checking that, I decided to reboot to see if it would flush out any ssh-related log entries that might be buffered somewhere. After rebooting there were no new entries in auth.log aside from those related to rebooting. So as things stand now the last out of sequence entry is dated Dec 4 and it appears among the Dec 19 log entries. |
Quote:
Quote:
Quote:
Quote:
Quote:
|
Quote:
The learning curve for this is steeper than I anticipated. Apparently system logging isn't as trivial as it seems. Quote:
Code:
# I also noticed in /etc/rsyslog.d/50-default.conf the following: Code:
daemon.*;mail.*;\ Code:
sudo xconsole -file /dev/xconsole I don't think it's really relevant anyway -- I have no reason to expect that any output to a nonexistent pipe will suddenly pop up in a log file 2 weeks later. Quote:
Code:
Dec 4 00:28:31 serv1 sshd[19263]: Failed password for invalid user root from 122.225.109.99 port 50099 ssh2 Code:
Dec 4 00:28:29 serv1 sshd[19263]: Failed password for invalid user root from 122.225.109.99 port 50099 ssh2 Incidentally, the Dec 4 entry which appeared in the log on Dec 19 is the last out of order entry I've seen, so 2-1/2 days have gone by with everything behaving normally. I've been looking at the online documentation for rsyslog and apparently it does use multiple internal message queues, but if I understand it correctly there should only be 1 queue for each action so if writing to /var/log/auth.log is an "action", there should not be 3 or 4 queues for that. Maybe this is just some obscure bug in rsyslog. |
Quote:
Quote:
Code:
]# grep ForwardTo /etc/systemd/journald.conf Quote:
|
I have no /etc/systemd/journald.conf. My logging is pretty bare-bones, limited to what was set up by the standard Xubuntu installation.
I do see Code:
$ModLoad imklog Quote:
I seem to be in over my head here. Or putting it another way there are many things I need to learn that are more urgent than rsyslog. It doesn't appear to be happening anymore and I have no info on what was going on during the time that it was happening, so I don't think I have anything of any use to the list subscribers at this point. But I'll keep an eye on it and if it resumes I'll consider submitting it to the mailing list. Thanks. |
All times are GMT -5. The time now is 01:20 AM. |