Linux - ServerThis forum is for the discussion of Linux Software used in a server related context.
Notices
Welcome to LinuxQuestions.org, a friendly and active Linux Community.
You are currently viewing LQ as a guest. By joining our community you will have the ability to post topics, receive our newsletter, use the advanced search, subscribe to threads and access many other special features. Registration is quick, simple and absolutely free. Join our community today!
Note that registered members see fewer ads, and ContentLink is completely disabled once you log in.
If you have any problems with the registration process or your account login, please contact us. If you need to reset your password, click here.
Having a problem logging in? Please visit this page to clear all LQ-related cookies.
Get a virtual cloud desktop with the Linux distro that you want in less than five minutes with Shells! With over 10 pre-installed distros to choose from, the worry-free installation life is here! Whether you are a digital nomad or just looking for flexibility, Shells can put your Linux machine on the device that you want to use.
Exclusive for LQ members, get up to 45% off per month. Click here for more info.
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
Dec 18 10:56:55 serv1 sshd[16579]: Failed password for invalid user test from 5.56.160.101 port 38287 ssh2
Dec 3 13:27:02 serv1 sshd[17885]: Failed password for invalid user root from 222.186.56.41 port 1709 ssh2
Dec 13 11:54:17 serv1 sshd[31391]: Failed password for invalid user root from 103.41.124.54 port 49460 ssh2
Nov 17 19:00:31 serv1 sshd[11354]: Failed password for invalid user root from 122.225.97.79 port 49199 ssh2
Nov 30 02:37:58 serv1 sshd[11372]: Failed password for invalid user root from 220.177.198.28 port 2655 ssh2
Nov 17 21:20:26 serv1 sshd[11514]: Failed password for invalid user root from 218.2.0.120 port 43516 ssh2
Dec 17 21:14:28 serv1 sshd[13563]: Failed password for invalid user root from 122.225.103.124 port 31382 ssh2
Dec 18 12:30:05 serv1 sshd[14326]: Failed password for invalid user arbab from 120.193.193.151 port 41890 ssh2
Dec 18 13:55:17 serv1 sshd[14370]: Failed password for invalid user bin from 125.65.165.215 port 45085 ssh2
Dec 1 12:30:12 serv1 sshd[14374]: Failed password for invalid user root from 101.64.236.225 port 47438 ssh2
Dec 19 03:08:15 serv1 sshd[16542]: Failed password for invalid user arbab from 67.18.223.130 port 52819 ssh2
Dec 19 03:08:18 serv1 sshd[16544]: Failed password for invalid user admin from 67.18.223.130 port 53548 ssh2
Dec 19 03:08:22 serv1 sshd[16546]: Failed password for invalid user root from 67.18.223.130 port 54041 ssh2
Dec 19 05:40:38 serv1 sshd[16704]: Failed password for invalid user root from 91.83.237.230 port 52341 ssh2
Dec 19 05:40:42 serv1 sshd[16706]: Failed password for invalid user bin from 91.83.237.230 port 52635 ssh2
Dec 19 06:01:44 serv1 sshd[16720]: Failed password for invalid user arbab from 74.208.66.78 port 34089 ssh2
Dec 19 06:01:47 serv1 sshd[16723]: Failed password for invalid user admin from 74.208.66.78 port 34746 ssh2
Dec 19 06:01:53 serv1 sshd[16725]: Failed password for invalid user root from 74.208.66.78 port 35516 ssh2
Dec 19 06:01:55 serv1 sshd[16727]: Failed password for invalid user root from 74.208.66.78 port 37056 ssh2
Dec 19 06:26:49 serv1 sshd[16767]: Failed password for invalid user arbab from 74.52.177.182 port 34797 ssh2
Dec 19 06:26:52 serv1 sshd[16769]: Failed password for invalid user admin from 74.52.177.182 port 38481 ssh2
Dec 19 06:26:54 serv1 sshd[16771]: Failed password for invalid user root from 74.52.177.182 port 39153 ssh2
Dec 19 07:34:49 serv1 sshd[16849]: Failed password for invalid user arbab from 173.12.246.241 port 49958 ssh2
Dec 19 07:34:52 serv1 sshd[16851]: Failed password for invalid user admin from 173.12.246.241 port 50326 ssh2
Dec 19 07:34:55 serv1 sshd[16853]: Failed password for invalid user root from 173.12.246.241 port 50575 ssh2
Dec 19 07:34:58 serv1 sshd[16855]: Failed password for invalid user root from 173.12.246.241 port 50886 ssh2
Nov 19 06:56:38 serv1 sshd[17567]: Failed password for invalid user root from 218.2.0.129 port 26237 ssh2
Dec 19 14:57:47 serv1 sshd[18160]: Failed password for invalid user arbab from 198.74.100.10 port 57285 ssh2
Dec 19 14:57:49 serv1 sshd[18162]: Failed password for invalid user admin from 198.74.100.10 port 57988 ssh2
Dec 19 14:57:53 serv1 sshd[18164]: Failed password for invalid user root from 198.74.100.10 port 58637 ssh2
Dec 19 14:57:55 serv1 sshd[18166]: Failed password for invalid user root from 198.74.100.10 port 59637 ssh2
Dec 19 15:26:44 serv1 sshd[18199]: Failed password for invalid user arbab from 174.79.103.106 port 51173 ssh2
Dec 19 15:26:48 serv1 sshd[18201]: Failed password for invalid user admin from 174.79.103.106 port 52469 ssh2
Dec 19 15:26:51 serv1 sshd[18203]: Failed password for invalid user root from 174.79.103.106 port 53322 ssh2
Dec 19 17:48:46 serv1 sshd[18785]: Failed password for invalid user admin from 64.251.22.13 port 53179 ssh2
Dec 19 17:48:50 serv1 sshd[18787]: Failed password for invalid user test from 64.251.22.13 port 53364 ssh2
Dec 19 17:48:54 serv1 sshd[18789]: Failed password for invalid user root from 64.251.22.13 port 53515 ssh2
Dec 3 20:47:19 serv1 sshd[19074]: Failed password for invalid user root from 222.186.56.41 port 3849 ssh2
Dec 4 00:28:31 serv1 sshd[19263]: Failed password for invalid user root from 122.225.109.99 port 50099 ssh2
Dec 19 21:57:15 serv1 sshd[19332]: Failed password for invalid user arbab from 107.0.105.241 port 34097 ssh2
Dec 19 21:57:23 serv1 sshd[19334]: Failed password for invalid user admin from 107.0.105.241 port 34771 ssh2
Dec 19 21:57:28 serv1 sshd[19336]: Failed password for invalid user root from 107.0.105.241 port 35367 ssh2
I've never noticed anything like this before. The first out of sequence entry seems to be in auth.log.2.gz, where there's a Nov 18 entry in the middle of those from Dec 1, and continues through the rest of that log as well as in auth.log.1 and auth.log. The older logs appear normal. I checked the logs on another machine also running Xubuntu 14.04 LTS and the entries there all seem to be in correct date order.
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.
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.
- 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.
There's a difference between knowing (logging, measuring, auditing) and thinking ;-p
Quote:
Originally Posted by r.stiltskin
- 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.
Check your systemd and syslog configs. Phrased differently: if the machine runs Systemd then Rsyslogd gets fed through Systemd by default.
Quote:
Originally Posted by r.stiltskin
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.
The out of order "duplicates", do the sshd PIDs match?
Quote:
Originally Posted by r.stiltskin
PS: /var/spool/rsyslog/ is empty.
No idea what you're using that for?
Quote:
Originally Posted by r.stiltskin
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.
+1 for trying but please note with Linux rebooting is considered an extreme measure. Most of the time it won't be necessary to "clean things up" that way.
There's a difference between knowing (logging, measuring, auditing) and thinking ;-p
Touché.
The learning curve for this is steeper than I anticipated. Apparently system logging isn't as trivial as it seems.
Quote:
Check your systemd and syslog configs. Phrased differently: if the machine runs Systemd then Rsyslogd gets fed through Systemd by default.
I browsed through /etc/systemd, /run/systemd and /usr/lib/systemd and didn't find anything that seemed relevant, but I don't exactly know what I'm looking for. The only thing that caught my eye in /etc/rsyslog.conf was
Code:
#
# Where to place spool and state files
#
$WorkDirectory /var/spool/rsyslog
which is what led me to look for clues in /var/spool/rsyslog, although as I said last night there's nothing there.
I also noticed in /etc/rsyslog.d/50-default.conf the following:
That pipe /dev/xconsole doesn't exist, and when I try to invoke
Code:
sudo xconsole -file /dev/xconsole
it just tells me "Couldn't open /dec/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:
The out of order "duplicates", do the sshd PIDs match?
Yes. For example the Dec 4 entry that appeared among the Dec 19 entries
Code:
Dec 4 00:28:31 serv1 sshd[19263]: Failed password for invalid user root from 122.225.109.99 port 50099 ssh2
is exactly the same in every respect as the corresponding entry which appeared in the prior log file on Dec 4:
Code:
Dec 4 00:28:29 serv1 sshd[19263]: Failed password for invalid user root from 122.225.109.99 port 50099 ssh2
except that the timestamp is 2 seconds later.
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.
Apparently system logging isn't as trivial as it seems.
No, it never is.
Quote:
Originally Posted by r.stiltskin
I browsed through /etc/systemd, /run/systemd and /usr/lib/systemd and didn't find anything that seemed relevant, but I don't exactly know what I'm looking for.
(*The GRUB kernel command line for ForwardToKMsg is "systemd.journald.forward_to_kmsg" BTW.)
Quote:
Originally Posted by r.stiltskin
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.
These days Rsyslogd comes with all sorts of statistics / debugging. (You haven't seen any "dropping due to" rate limiting messages, right?) Maybe regularly checking said stats may help but I'd definitely consider taking this issue to the http://lists.adiscon.net/mailman/listinfo/rsyslog mailing list.
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
$ModLoad imuxsock
in /etc/rsyslog.conf, but I'm not sure why you mentioned imklog since if I understand correctly, that module takes kernel log messages into rsyslog -- but my "delayed" messages don't come from the kernel log.
Quote:
You haven't seen any "dropping due to" rate limiting messages, right?
No, nothing like that.
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.
LinuxQuestions.org is looking for people interested in writing
Editorials, Articles, Reviews, and more. If you'd like to contribute
content, let us know.
