Logs and journald¶

Exercise logs-and-journald-annex.pdf · PDF

A user at Tramuntana Apps says: "The server went down last night." You were asleep. Nobody saw anything. How do you find out what happened — and at what minute?

You cannot ask the machine what it remembers. But it wrote everything down while it happened. In the last session you killed your heartbeat service with kill -9. Do you know the exact second? You do not. Your VM does.

The machine keeps a diary¶

A log is a list of short lines, each with the time, written by the system while things happen — and never corrected afterwards.

The word comes from the sea. Sailors measured a ship's speed by throwing a wooden log on a rope over the side and counting the knots that ran out. They wrote the result in the log-book, hour after hour. The book kept the name.

Anatomy of a line¶

Oct 05 20:53:39 deb-lab heartbeat.sh[4088]: heartbeat from deb-lab: load 6.30

Syslog and the eight levels of bad news¶

In the early 1980s Eric Allman, at the University of California, Berkeley, was writing the mail server sendmail and needed somewhere to put its messages. He wrote a small helper: syslog. Other programs started using it, and it became the way Unix logs — with no official standard for about twenty years. It was described in RFC 3164 in 2001 and standardised in RFC 5424 in 2009.

Syslog gave every line a severity (also called priority): how bad is it? Those eight levels are still what you filter by today.

The journal: journald¶

The journal is the log-book of a systemd machine, kept by the service systemd-journald.

It collects three things in one place:

flowchart LR
    subgraph SRC ["Who writes"]
        direction TB
        K["<b>Kernel</b><br>hardware, drivers"]
        S["<b>Services</b><br>everything they print<br>(your heartbeat's echo)"]
        P["<b>Programs</b><br>sending to syslog<br>(sudo, logger)"]
    end
    SRC -->|"lines"| J["<b>systemd-journald</b><br>the ship's clerk"]
    J -->|"stores, indexed"| F["<b>/var/log/journal/</b><br>binary files"]
    F -->|"you ask"| Q["<b>journalctl</b><br>the reader"]

The journal is stored in a binary, indexed format, so cat shows rubbish. You do not open it — you ask it, with journalctl.

journalctl basics¶

journalctl opens a pager: arrows and Page Down to move, G (capital) to jump to the end, q to leave.

Who may read the journal?¶

$ journalctl -n 5
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal' can see all messages.

A normal user sees only their own messages. The log of the system can reveal who logged in and what they ran, so it is protected — the permissions of the previous sessions guarding the evidence. From here on, use sudo journalctl.

The options you will use every day¶

Watch the details. A time with a space needs quotes: --since "10 min ago". -u takes the unit name (heartbeat), not the script name (heartbeat.sh). Long options have two dashes: --since, never -since.

Write in the log-book yourself¶

logger sends a line to the journal, as any program would. Open two terminals. In the first, sudo journalctl -f. In the second:

logger -t tramuntana "hello from marta"

The line appears in the first terminal without you touching it:

Oct 05 21:10:36 deb-lab tramuntana[5176]: hello from marta

The -t gave the line its tag, the place where a service would put its name. You can also choose the priority:

logger -p user.err -t tramuntana "disk almost full (test)"
sudo journalctl -t tramuntana -p err

The second command shows the "disk almost full" line, but not the "hello": that one was level 6 (info), and -p err shows only level 3 and worse (0–3).

A method: when, who, how bad¶

A VM that has been on for a week holds tens of thousands of lines. Scrolling through them is not a plan. Three questions cut the pile:

They combine. Here is the line of your kill -9 from the last session, to the second:

$ sudo journalctl -u heartbeat --since yesterday -g "killed|restart"
Oct 05 20:53:50 deb-lab systemd[1]: heartbeat.service: Main process exited, code=killed, status=9/KILL
Oct 05 20:53:50 deb-lab systemd[1]: heartbeat.service: Scheduled restart job, restart counter is at 1.

The exact time; the signal (9, SIGKILL); and who wrote it: systemd[1], not the script — the script was dead, it could not write anything.

Two more hunting tips. If you search with -g and a capital letter, the search becomes case-sensitive — all lower case matches both. And if the event happened before the last reboot, -b (this boot only) will not find it: use --since yesterday.

Who used sudo?¶

Every sudo — failed or successful — is written down. Type a wrong password three times, then ask:

$ sudo journalctl -t sudo --since "5 min ago"
sudo[4484]: pam_unix(sudo:auth): authentication failure; logname=... uid=1000 euid=0 tty=... ruser=marta rhost=  user=marta
sudo[4484]:    marta : 3 incorrect password attempts ; PWD=/home/marta ; USER=root ; COMMAND=/usr/bin/ls /root

Who, from which folder, as which user, and the exact command. That is why only root and the groups adm and systemd-journal may read the journal.

What is still in /var/log¶

Some programs keep their own text files next to the journal. Those you read with less and grep, as in Unit 4:

grep -A1 "Start-Date" /var/log/apt/history.log | tail -4

This shows the last two apt commands, each under its date.

Windows: Event Viewer¶

Windows keeps its diary too. Press Win+R and type eventvwr.msc, then open Windows Logs on the left.

The new idea is the Event ID: every kind of event has a number, so you search for the number instead of for words. Two worth knowing by heart, in the Security log:

In the System log, the source Service Control Manager writes the events about services — starting, stopping, changing the startup type.

In Event Viewer, use Filter Current Log… in the right panel: tick Critical and Error, or type an Event ID. The same from PowerShell — run it as administrator, because the Security log needs it:

Get-WinEvent -LogName System -MaxEvents 5
Get-WinEvent -FilterHashtable @{ LogName='Security'; Id=4624 } -MaxEvents 3

Events come newest first. -FilterHashtable filters while reading, which is much faster than reading everything and piping it to Where-Object.

The Exercise sheet takes you through the whole hunt: your own line, yesterday's kill, a failed sudo, the reboots, the last apt install, and a failed Windows logon found by its number.

Key takeaways¶

• A log is a diary of short timestamped lines: when, which host, who (program and PID), what.
• Severity goes from 0 (emerg, worst) to 7 (debug); -p err means level 3 and worse.
• On Debian 13 the journal (systemd-journald) keeps everything; you ask it with journalctl — and there is no /var/log/syslog.
• Do not scroll: cut the pile with when (--since, -b), who (-u, -t) and how bad (-p), then read the lines above the error.
• logger writes your own line; sudo attempts are logged; only root, adm and systemd-journal can read the whole journal.
• Windows: Event Viewer and Get-WinEvent, with System/Application/Security logs, levels and Event IDs (4624 logon, 4625 failed logon).

Quick check¶

Next: four services of Tramuntana Apps are broken and you only have two commands. Time to put status and logs to work — The case of the failed service.