An off-cadence post in the spirit of the season. I have been keeping a separate notebook all year of log entries that, on first reading, made me nearly drop my coffee. Some turned out to be benign. Some turned out to be real. Each one taught me something about reading logs that no methodology document quite captures.
In rough chronological order.
March: the trailing dot
Mar 14 03:42:11 mail postfix/smtpd[14322]: connect from unknown[203.0.113.45]
Mar 14 03:42:11 mail postfix/smtpd[14322]: NOQUEUE: reject: RCPT from unknown[203.0.113.45]: 554 Relay access denied
Mar 14 03:42:11 mail postfix/smtpd[14322]: ... [thousands more in two minutes]The pattern: thousands of connection attempts from a single IP in two minutes, all trying to relay through my mail server. All being correctly rejected, but the rate was unusual.
The initial worry: the rejections were correct, but a successful relay attack would not have been visible from this excerpt. Was something getting through?
The investigation: I cross-referenced the rejection log against the actual mail-out queue and the outbound traffic graphs. No mail was relaying from this source. The attempts were a brute-force test of my relay configuration; none succeeded.
The lesson: rate of attempts is alarming even when the response is correct. The thousands of rejections suggested an attacker was probing seriously, which meant they probably had a list of addresses they were trying. I added the source range to the firewall drop list and the noise stopped.
April: the user who never logs in
Apr 02 14:31:07 webserver sshd[8421]: Accepted publickey for backup from 192.168.1.5 port 41207 ssh2The pattern: a successful SSH login. Single line. Looked entirely normal.
The initial worry: I did not have a user named backup on this host. There was no key in /etc/ssh/authorized_keys for any user named backup. So how was the login accepted?
The investigation, panicked: I logged in immediately and checked everything. getent passwd backup returned a real entry. /etc/passwd showed backup:x:34:34:Backup System User:/var/backups:/bin/sh. The user existed. It was a system account that came with Debian and that I had never noticed. There was an authorised key — in /var/backups/.ssh/authorized_keys. Where had it come from?
The answer, embarrassingly: I had set up an automated rsync backup three months earlier and added the key myself. I had forgotten. The login was my own backup script running on schedule from another host I owned.
The lesson: not everything that looks suspicious is. But also: a backup user on a public-facing host is the kind of thing an attacker would create to be inconspicuous. The fact that my own setup looked like that is a sign that I should have used a less-common username for the backup automation. Renamed it.
May: the very fast scan
May 18 02:04:01 fw kernel: DROP TCP 203.0.113.99:31337 -> 192.0.2.50:21
May 18 02:04:01 fw kernel: DROP TCP 203.0.113.99:31337 -> 192.0.2.50:23
May 18 02:04:01 fw kernel: DROP TCP 203.0.113.99:31337 -> 192.0.2.50:25
May 18 02:04:01 fw kernel: DROP TCP 203.0.113.99:31337 -> 192.0.2.50:53
May 18 02:04:01 fw kernel: DROP TCP 203.0.113.99:31337 -> 192.0.2.50:80
... (many more)The pattern: a port scan. Nothing surprising about that. What was unusual was the speed — twenty ports per second from a single source.
The initial worry: scans are usually slower because scanners try to evade detection. Twenty per second was either a careless scanner or someone who did not care if they were detected. Both are interesting. The deeper worry was whether something had succeeded before I noticed; the timestamps gave me 90 seconds to investigate.
The investigation: I extracted the scan footprint, confirmed it matched nmap's default fast scan, and confirmed every probe had been dropped at the firewall. None of my services had seen the connection attempts. The attacker's source was a compromised home cable modem; I emailed the ISP's abuse address.
The lesson: speed is itself diagnostic. Fast scans usually mean the attacker does not care. Slow scans usually mean the attacker is trying to evade detection. The same set of probes, at different rates, has different threat implications.
July: the daemon that wasn't
Jul 12 19:23:14 hostb kernel: BIND[14921] killed by signal 11, core dumpedThe pattern: the BIND daemon had segfaulted. One line in the kernel log.
The initial worry: a BIND segfault on an internet-facing host was, in mid-1999, exactly the symptom of an attempted exploit of a memory-corruption bug. If the exploit had succeeded, I would have an attacker shell. If it had failed, the daemon had crashed but the host was still mine.
The investigation, urgent: I jumped to the host, checked process listings, looked for anything not on the expected list. Nothing unusual. Read the core dump. The crash was in a code path I recognised from the recent advisory — the NXT record handling that had been patched in 8.2.2-P5.
But I had patched. I had verified. So why the crash?
The answer: the running daemon was the old unpatched binary. I had updated the source on disk and rebuilt it, but I had not restarted named after the build. The new binary was sitting on disk; the old buggy one was still in memory.
The attacker had attempted the exploit. The exploit had triggered the crash but had not succeeded in code execution, probably because of some incidental detail of the host's memory layout. I was lucky. The lesson, which I subsequently wrote up at length, is that "patched" is not a single state.
September: the slow shell session
Sep 22 03:14:08 hostc sshd[3421]: Accepted publickey for me from 192.0.2.10 port 38492 ssh2
Sep 22 03:14:11 hostc sshd[3421]: pam_unix(sshd:session): session opened for user me by (uid=0)
Sep 22 03:14:14 hostc audit: user me ran: w
Sep 22 03:14:21 hostc audit: user me ran: ls /root
Sep 22 03:14:38 hostc audit: user me ran: ls /var/log
Sep 22 03:14:52 hostc audit: user me ran: cat /etc/shadow
Sep 22 03:14:58 hostc audit: user me ran: history
Sep 22 03:14:59 hostc audit: user me ran: exitThe pattern: a shell session as my own user, at 3am, doing things that did not match what I would do.
The initial worry: this looked like an attacker who had recovered or guessed my SSH key. The commands were all read-only — ls, cat /etc/shadow, history — and short. They were the commands an attacker would run to assess what they had access to before doing anything irreversible.
The investigation: I jumped to a different terminal, logged in, and disabled my own account. I rotated my SSH key. Then I read more carefully.
The answer turned out to be that I had logged in, from a hotel room I had not used in months, where my laptop had got an old IP that overlapped with the address range I had just listed in the audit log. The session was indeed mine. I had logged in to check on the server while sleepless on a work trip and forgot.
The rotation of my SSH key, in retrospect, was the right thing to do anyway — better to rotate keys based on a false alarm than not to rotate them when the alarm is real.
The lesson: the content of activity matters more than the timing. 3am is not the witching hour; it is, for a working professional, just a time when sometimes things happen. Aleph One, in his various Bugtraq posts, has said as much: it is the action profile, not the clock, that distinguishes attacker activity.
A small reflection on the season
The entries above are scary because of the ambiguity. Each one had me, briefly, in a state of "this might be a real incident". Some were. Most were not. The investigation work in each case was the part that distinguishes useful operational vigilance from paranoid noise.
What I have learned over the year is that the felt fear is not a reliable signal. The first instinct is often wrong. The discipline is to look further: pull more context, cross-reference other sources, check the surrounding minutes of log activity, ask whether the alarming reading is the simplest explanation.
Most of the time, the simplest explanation is benign. Sometimes it is not. The discipline of distinguishing the cases, in my experience, only develops with practice — and a small amount of being wrong about each kind, which is its own teacher.
Have a safe night. Watch your logs.