Building an Incident Timeline from Auth, Web and IDS Logs

An incident report has to answer “what happened, in what order”. The evidence lives in different logs, written by different programs, with different ideas of what a timestamp is. In this lesson one source probes your web server and then guesses its way into your SSH server. You’ll merge the three logs that recorded it into one timeline, and watch the order come out wrong until every timestamp has a timezone. Tested with Docker Engine 29.8.2, Python 3.12.15 (python:3.12-slim), Suricata 8.0.7 (jasonish/suricata:8.0), and the lab images from the earlier lessons in this topic.

One incident, three logs

This reuses the ds-lab network, the sshd-lab, ssh-client and capture-lab images, logins.sh from the auth logs lesson and traffic.sh from the triage lesson. The triage lesson replaced local.rules, so put the .env rule from the Suricata lesson in a file of its own:

# env.rules: the .env rule from the Suricata lesson
alert http any any -> any any (msg:"LAB request for a .env file"; flow:established,to_server; http.uri; content:"/.env"; endswith; classtype:attempted-recon; sid:1000001; rev:2;)

The web server gets one change: its clock is set to Indian Standard Time, UTC+5:30, with a POSIX TZ string. Servers set to local time are common, and this one stands in for all of them.

docker rm -f sshd web tap 2>/dev/null
docker run -d --name sshd --hostname sshd --network ds-lab --ip 172.30.0.10 sshd-lab
docker run -d --name web --network ds-lab --ip 172.30.0.11 -e TZ=IST-5:30 python:3.12-slim python -m http.server 8000
docker run -d --name tap --network container:web -v "$PWD":/work capture-lab tcpdump -i eth0 -U -w /work/incident.pcap port 8000

Then the attack: a web probe followed straight away by SSH guessing.

$ docker run --rm --network ds-lab --ip 172.30.0.20 -v "$PWD":/work -w /work capture-lab sh traffic.sh probe
probe done
$ docker run --rm --network ds-lab --ip 172.30.0.20 -v "$PWD":/work -w /work ssh-client sh logins.sh
alice / password1 -> denied
alice / letmein -> denied
alice / 123456 -> denied
admin / admin -> denied
oracle / oracle -> denied
alice / correct-horse -> ok

Collect the three logs: the web server’s access log (Python’s http.server writes it to stderr, so it’s in docker logs), the SSH server’s auth.log, and Suricata’s eve.json from the capture.

docker stop tap
docker logs web > access.log 2>&1
docker cp sshd:/var/log/auth.log auth.log
rm -rf out && mkdir out
docker run --rm --entrypoint suricata -v "$PWD":/work -w /work jasonish/suricata:8.0 -r incident.pcap -S env.rules -k none -l out

$ cat access.log
172.30.0.20 - - [14/Oct/2026 14:34:48] code 404, message File not found
172.30.0.20 - - [14/Oct/2026 14:34:48] "GET /.env HTTP/1.1" 404 -
172.30.0.20 - - [14/Oct/2026 14:34:48] code 404, message File not found
172.30.0.20 - - [14/Oct/2026 14:34:48] "GET /admin HTTP/1.1" 404 -
172.30.0.20 - - [14/Oct/2026 14:34:48] code 404, message File not found
172.30.0.20 - - [14/Oct/2026 14:34:48] "GET /backup.zip HTTP/1.1" 404 -

Three timestamp styles are now in play. auth.log has 2026-10-14T09:04:52.464054+00:00: full date, microseconds and an offset. eve.json has 2026-10-14T09:04:48.370246+0000: the same, with the offset written without a colon. The access log has 14/Oct/2026 14:34:48: whole seconds and no zone at all. It says 14:34 because that’s the web server’s local time, though it happened at 09:04 UTC.

Reading each source

One parser per log, each yielding (time, source, what), so the timeline code doesn’t care where an event came from.

# sources.py: read each log into (time, source, what happened)
import json, re
from datetime import datetime

def auth(path="auth.log"):
    for line in open(path):
        if re.search(r"Failed password|Accepted", line):
            ts, _, rest = line.split(" ", 2)
            what = rest.split(": ", 1)[1].split(" port ")[0]
            yield datetime.fromisoformat(ts), "ssh", what

ACCESS = re.compile(r'\[(.+?)\] "(\S+ \S+)[^"]*" (\d+)')

def web(path="access.log"):
    for line in open(path):
        if m := ACCESS.search(line):
            when = datetime.strptime(m[1], "%d/%b/%Y %H:%M:%S")
            yield when, "web", f"{m[2]} -> {m[3]}"

def ids(path="out/eve.json"):
    for line in open(path):
        e = json.loads(line)
        if e["event_type"] == "alert":
            yield datetime.fromisoformat(e["timestamp"]), "ids", e["alert"]["signature"]

datetime.fromisoformat reads both offset styles, +00:00 and +0000, since Python 3.11. The access log needs strptime with an explicit format, and the result has no timezone: it’s a naive datetime.

Attempt 1: just sort

# timeline1.py: merge the three logs and sort
from sources import auth, web, ids

events = [*auth(), *web(), *ids()]
for when, source, what in sorted(events):
    print(when, source, what)

$ docker run --rm -v "$PWD":/work -w /work python:3.12-slim python timeline1.py
Traceback (most recent call last):
  File "/work/timeline1.py", line 5, in <module>
    for when, source, what in sorted(events):
                              ^^^^^^^^^^^^^^
TypeError: can't compare offset-naive and offset-aware datetimes

Python refuses to compare a time with a zone against a time without one, because the answer depends on information it doesn’t have. That error is doing you a favour.

Attempt 2: make the error go away

The common fix you’ll find for that error is to strip the zone from everything.

# timeline2.py: drop the timezones so the times compare
from sources import auth, web, ids

events = [(when.replace(tzinfo=None), source, what)
          for when, source, what in [*auth(), *web(), *ids()]]
for when, source, what in sorted(events):
    print(when.strftime("%H:%M:%S"), f"{source:<4}", what)

$ docker run --rm -v "$PWD":/work -w /work python:3.12-slim python timeline2.py
09:04:48 ids  LAB request for a .env file
09:04:52 ssh  Failed password for alice from 172.30.0.20
09:04:55 ssh  Failed password for alice from 172.30.0.20
09:04:58 ssh  Failed password for alice from 172.30.0.20
09:05:00 ssh  Failed password for invalid user admin from 172.30.0.20
09:05:04 ssh  Failed password for invalid user oracle from 172.30.0.20
09:05:05 ssh  Accepted password for alice from 172.30.0.20
14:34:48 web  GET /.env -> 404
14:34:48 web  GET /admin -> 404
14:34:48 web  GET /backup.zip -> 404

No error, and a believable story: an IDS alert, the SSH attack, the login, and then at 14:34 some web requests, five and a half hours later. It’s wrong. The web requests came first; they only look late because their 14:34 is IST and everything else is UTC. Someone reading this timeline would conclude the web probe happened after the break-in, maybe by a different actor, and would miss that the probe was the reconnaissance for it.

replace(tzinfo=None) doesn’t convert anything. It throws the zone away and keeps the digits, so every time is now read as if it were in the same zone, whatever zone it was really in.

Attempt 3: give every time a zone, then convert

The access log doesn’t say what zone it’s in, so you have to find out: from the server’s configuration, or by matching one request against another source, as the IDS alert allows here. Once you know, attach it and convert everything to UTC.

# timeline3.py: give every time a zone, then convert all of them to UTC
from datetime import timedelta, timezone
from sources import auth, web, ids

WEB_TZ = timezone(timedelta(hours=5, minutes=30))  # the web server's clock: TZ=IST-5:30

def utc(when, assumed):
    if when.tzinfo is None:
        when = when.replace(tzinfo=assumed)
    return when.astimezone(timezone.utc)

events = [(utc(w, None), s, x) for w, s, x in [*auth(), *ids()]]
events += [(utc(w, WEB_TZ), s, x) for w, s, x in web()]
for when, source, what in sorted(events):
    print(when.strftime("%H:%M:%S"), f"{source:<4}", what)

$ docker run --rm -v "$PWD":/work -w /work python:3.12-slim python timeline3.py
09:04:48 web  GET /.env -> 404
09:04:48 web  GET /admin -> 404
09:04:48 web  GET /backup.zip -> 404
09:04:48 ids  LAB request for a .env file
09:04:52 ssh  Failed password for alice from 172.30.0.20
09:04:55 ssh  Failed password for alice from 172.30.0.20
09:04:58 ssh  Failed password for alice from 172.30.0.20
09:05:00 ssh  Failed password for invalid user admin from 172.30.0.20
09:05:04 ssh  Failed password for invalid user oracle from 172.30.0.20
09:05:05 ssh  Accepted password for alice from 172.30.0.20

Now the story is right: three probes for sensitive files, the IDS alert for one of them, four seconds of quiet, then password guessing and a login, all from 172.30.0.20. utc() only assumes a zone for times that have none, and only the web source gets an assumption. Times that already carry an offset are converted, never overwritten.

Look closely at the first four lines, though. The IDS alert is for /.env, the first request, yet it sorts after /admin and /backup.zip. The access log only records whole seconds, so all three requests are stamped 09:04:48.000000, while Suricata recorded 09:04:48.370246. Within one second, the order of events from a coarse source and a precise one is unknown. Say so in the report rather than trusting the sort.

The next lesson turns from logs to files: how to examine a suspicious file safely.

Practice

1. Print each event’s time as an offset from the first event, T+ 4.5s, instead of a clock time. How long did the whole incident take?

# p1.py: elapsed time since the first event
from datetime import timedelta, timezone
from sources import auth, web, ids

WEB_TZ = timezone(timedelta(hours=5, minutes=30))

def utc(when, assumed):
    if when.tzinfo is None:
        when = when.replace(tzinfo=assumed)
    return when.astimezone(timezone.utc)

events = [(utc(w, None), s, x) for w, s, x in [*auth(), *ids()]]
events += [(utc(w, WEB_TZ), s, x) for w, s, x in web()]
events.sort()
start = events[0][0]
for when, source, what in events:
    print(f"T+{(when - start).total_seconds():5.1f}s", f"{source:<4}", what)

$ docker run --rm -v "$PWD":/work -w /work python:3.12-slim python p1.py
T+  0.0s web  GET /.env -> 404
T+  0.0s web  GET /admin -> 404
T+  0.0s web  GET /backup.zip -> 404
T+  0.4s ids  LAB request for a .env file
T+  4.5s ssh  Failed password for alice from 172.30.0.20
T+  7.3s ssh  Failed password for alice from 172.30.0.20
T+ 10.4s ssh  Failed password for alice from 172.30.0.20
T+ 12.5s ssh  Failed password for invalid user admin from 172.30.0.20
T+ 16.4s ssh  Failed password for invalid user oracle from 172.30.0.20
T+ 17.9s ssh  Accepted password for alice from 172.30.0.20

2. Classic syslog lines look like Oct 14 08:27:58 sshd sshd-session[11]: .... Parse that timestamp with strptime and print the year and timezone you get.

# p2.py: a classic syslog timestamp has no year and no zone
from datetime import datetime

classic = datetime.strptime("Oct 14 08:27:58", "%b %d %H:%M:%S")
modern = datetime.fromisoformat("2026-10-14T08:27:58.566045+00:00")
print(repr(classic))
print(classic.year, classic.tzinfo)
print(modern.year, modern.tzinfo)

$ docker run --rm -v "$PWD":/work -w /work python:3.12-slim python p2.py
datetime.datetime(1900, 10, 14, 8, 27, 58)
1900 None
2026 UTC

3. Suppose you guess the web server’s zone wrong and use timedelta(hours=5) (UTC+5, Pakistan) instead of UTC+5:30. Where do the web events land?