I have a FreeNAS fileserver at home for backups and whatever. There’s a system job that runs nightly to look at the security logs and alert me if something’s wrong, for instance, if someone attempted to login and used an incorrect password. For as long as this box has been alive, I’d occasionally get emails like this:
bigbox.lan login failures: Nov 6 22:12:14 bigbox sshd[722]: Failed password for root from 192.168.1.50 port 41002 ssh2 -- End of security output --
These are fine, usually, because sometimes I get things wrong. However, I’d occasionally get these even if I know for a fact I haven’t logged in at all. The source address is my desk workstation, and I know I didn’t make the session attempt. This gives me great cause for concern. Grave concern. Has somebody broken into my workstation and is trying to reach out?
So a few weeks ago I set up an iptables rule on my workstation to log the TCP SYN packet of every outbound SSH attempt:
iptables -A OUTPUT -p tcp -m tcp --dport 22 --tcp-flags FIN,SYN,RST,ACK SYN -j LOG --log-prefix "ssh_outbound "
This makes records like this in /var/log/syslog:
Nov 1 23:30:12 workstation kernel: [1473867.997608] ssh_outbound IN= OUT=enp3s0 SRC=192.168.1.50 DST=192.168.1.44 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=20475 DF PROTO=TCP SPT=53594 DPT=22 WINDOW=29200 RES=0x00 SYN URGP=0
So when I got another alert this morning, I grepped my syslog and found absolutely nothing. Is the issue less nefarious than I feared? Is it a misconfiguration somewhere? So what’s going on?
Having had enough, I looked at my FreeNAS security log. It’s about 51KB and contains lots of entries. The entry triggering this morning’s alert is there. But it’s also followed by future dates. Future dates? Ah-hah! The stupid security logging daemon doesn’t store the year in the timestamps, and logwatcher doesn’t know it! This is an alert from last year! So why are old records still hanging around?
FreeNAS has a version of logrotate called newsyslog which gets its config from /etc/newsyslog.conf, which itself has the following entry for auth.log:
# logfilename [owner:group] mode count size when flags [/pid_file] [sig_num] /var/log/auth.log 600 7 100 * JC
Huh. So the asterisk (*) means to not look at time when rotating the log, only the file size. Well, since the file’s not 100KB yet, it will sit until it is. This file is 4 years old! Wacky! So my fix is to change the asterisk to “$M1D0“, meaning monthly, day 1, regardless of size.
Now I only have a few more future alerts to look forward to until December starts and the log is rotated. I think I can live with that and rest a little more peacefully.
Hooray! We did it! We solved Blues Clues!