Logs, monitoring and troubleshooting

At 08:05 on a Saturday in November, Rosa texted Sam: the shop was showing an error page, and Saturday morning is when the week's biggest orders arrive. Sam was out, so Jordan logged in. Within ten minutes he had found the cause, a disk filled by a single runaway log file, freed space, brought the shop back and set up a rule so that it could not happen again. He could do it because Linux records almost everything that happens in logs, and because he knew where to look and which commands summarize a server's health. This lesson follows that morning, and teaches the logging and monitoring tools behind it.

It covers where Linux keeps its logs, the systemd journal and journalctl, the traditional log files and their priorities, log rotation, the commands that show a server's health at a glance, the basics of continuous monitoring, and a method for troubleshooting that works for problems you have never seen before.

Where logs live

Linux has two logging systems that usually run side by side. The systemd journal collects messages from the kernel, from every service systemd starts and from programs that use the standard logging interface, and stores them in a structured binary format under /var/log/journal. The traditional syslog service, rsyslog on Ubuntu, receives the same messages and writes them to plain text files in /var/log, sorted by kind. Many applications also write their own log files, usually under /var/log in a directory of their own.

Each message has a priority, a number from 0 to 7 inherited from the original syslog design of the 1980s, and a facility, which says what kind of program sent it. Knowing the priorities lets you filter out routine chatter and see only what matters.

The journal and journalctl

The journalctl command reads the journal. On its own it shows every message since records began, oldest first, which is rarely what you want; its options narrow the view by service, time, priority and boot. Members of the adm or systemd-journal groups, and sudo users, can read the whole journal.

> journalctl -u ridgeline-shop -p err --since today
Nov 07 07:58:31 ridge-web gunicorn[1391]: OSError: [Errno 28] No space left on device: '/var/log/ridgeline/shop-debug.log'
Nov 07 07:58:31 ridge-web gunicorn[1391]: [ERROR] Exception in worker process
Nov 07 07:58:32 ridge-web systemd[1]: ridgeline-shop.service: Main process exited, code=exited, status=1/FAILURE
Nov 07 07:58:32 ridge-web systemd[1]: ridgeline-shop.service: Failed with result 'exit-code'.
Nov 07 07:58:37 ridge-web systemd[1]: ridgeline-shop.service: Scheduled restart job, restart counter is at 1.

The first error line names the problem precisely: Errno 28, no space left on device, while writing to a debug log. The following lines show systemd doing its job, restarting the service five seconds after each failure as the unit file asked, but every restart failed for the same reason. Starting with the failing service's errors, rather than reading logs from the top, is what turned a potentially long investigation into a short one.

Following the clue

The error pointed at storage, so the next commands were df and du from lesson 7, followed by a look at the file itself.

> df -h /var/log /srv
Filesystem      Size  Used Avail Use% Mounted on
/dev/vda2        78G   78G     0 100% /
/dev/vdb1        98G   41G   53G  44% /srv
> sudo du -sh /var/log/* 2>/dev/null | sort -h | tail -n 3
412M    /var/log/journal
1.1G    /var/log/nginx
38G     /var/log/ridgeline
> ls -lh /var/log/ridgeline/
-rw-r----- 1 shop adm 38G Nov  7 07:58 shop-debug.log
-rw-r----- 1 shop adm 21M Nov  7 07:58 shop.log

A developer had switched on debug logging while testing a new checkout page on Wednesday and forgotten to switch it off, and nothing was rotating the file. Three days of logging every database query had filled the root file system. Note that /srv, where Ridgeline's data lives, was fine: the problem was on the system disk, because the shop writes its logs to /var/log.

There is a trap here that catches many administrators. If you delete a file that a process still has open, the name disappears but the space is not freed until the process closes the file, because the data is still in use. So rm shop-debug.log would have left the disk full while the shop kept running. Jordan instead emptied the file in place with truncate, which keeps it open but releases the space, and only then turned off debug logging.

> sudo truncate -s 0 /var/log/ridgeline/shop-debug.log
> df -h /
Filesystem      Size  Used Avail Use% Mounted on
/dev/vda2        78G   40G   35G  54% /
> sudo lsof +L1 | head -n 3
COMMAND   PID USER  FD  TYPE DEVICE SIZE/OFF NLINK  NODE NAME
> sudo sed -i 's/^LOG_LEVEL=DEBUG/LOG_LEVEL=INFO/' /etc/ridgeline/shop.env
> sudo systemctl restart ridgeline-shop
> curl -s -o /dev/null -w "%{http_code}\n" https://shop.ridgeline.example/
200

The command lsof +L1 lists open files whose link count is zero, meaning deleted but still open. It came back empty, so no hidden space was being held. The curl command at the end prints only the HTTP status code, and 200 confirmed the shop was back at 08:16, eleven minutes after Rosa's text. Jordan posted a short note to Rosa and Sam: what happened, what he did, and what still needed fixing.

Log rotation

Logs grow forever unless something trims them. On Ubuntu, logrotate runs daily from a systemd timer and handles this for every file it has a rule for: it renames the current log, starts a fresh one, compresses old ones and deletes the oldest. Packages install their own rules in /etc/logrotate.d, which is why nginx's and PostgreSQL's logs never caused trouble. The shop's logs had no rule because nobody had written one. The fix, the real cure rather than the emergency truncate, was a rule of a few lines.

# /etc/logrotate.d/ridgeline
/var/log/ridgeline/*.log {
    daily
    rotate 14
    maxsize 500M
    compress
    delaycompress
    missingok
    notifempty
    copytruncate
    su shop adm
}

Each setting has a purpose. daily and rotate 14 keep two weeks of logs. maxsize 500M rotates a file early if it grows past 500 MB, even mid-day, which would have caught the debug log on Wednesday. compress and delaycompress gzip old logs but leave yesterday's uncompressed for easy reading. copytruncate copies the log and then empties it in place, the same technique as the emergency fix, for applications that keep their log file open. Testing the rule with sudo logrotate --debug /etc/logrotate.d/ridgeline shows what it would do without doing it. The journal has its own limits, set with SystemMaxUse in /etc/systemd/journald.conf.

A server's health at a glance

Beyond logs, a few commands show the current state of a server. Running them in sequence takes under a minute and answers most first questions about a slow or troubled machine.

The load average is the average number of processes running or waiting to run, including those waiting for disk. It should be read against the number of processors: on ridge-web, with two virtual processors, a load of 2 means the processors are fully busy, and a load that stays well above 2 means work is queuing. A high load with low processor use usually means processes are waiting for slow storage. In free's output, Linux uses spare memory as a disk cache, so used memory always looks high; the available column shows how much programs could actually use.

def load_report(uptime_line, cpus):
    loads = uptime_line.split("load average:")[1].split(",")
    one, five, fifteen = (float(x) for x in loads)
    status = "ok"
    if five > cpus:
        status = "overloaded"
    elif five > 0.7 * cpus:
        status = "busy"
    trend = "rising" if one > fifteen * 1.2 else "falling" if one < fifteen * 0.8 else "steady"
    return f"5-min load {five} on {cpus} CPUs: {status}, {trend}"

print(load_report(" 09:20:41 up 3 days,  2:11,  1 user,  load average: 0.02, 0.05, 0.01", 2))
print(load_report(" 08:01:02 up 9 days,  1:03,  2 users,  load average: 3.91, 2.62, 0.88", 2))
print(load_report(" 13:40:10 up 9 days,  6:42,  1 user,  load average: 1.10, 1.52, 1.95", 2))

5-min load 0.05 on 2 CPUs: ok, rising
5-min load 2.62 on 2 CPUs: overloaded, rising
5-min load 1.52 on 2 CPUs: busy, falling

Continuous monitoring and alerting

Jordan found the Saturday problem quickly, but only after customers had already seen the error page. Monitoring turns that around: a program checks the server constantly and alerts someone as soon as a value crosses a threshold, ideally before customers notice. For a small business, a few checks cover most risks: is the shop's home page answering, is any file system's Use figure above 80, are any services failed, is the load or memory unusual, and are backups recent.

Tools range from simple to elaborate. An external uptime service checks the shop's address every minute from the internet and sends a text if it fails, which catches network and DNS problems as well as server ones. On the server, Prometheus with its node exporter collects metrics such as disk, memory and processor use, Grafana draws dashboards from them, and Alertmanager sends alerts; Netdata and Zabbix are popular all-in-one alternatives. Cloud providers offer their own monitoring too. Sam sets Ridgeline up with an external uptime check and a small script, written in lesson 11, that emails Jordan when a disk's Use figure passes 80 or a service fails.

Who did what? Reading auth.log

The authentication log answers questions about access: who logged in, from where, who used sudo and what for, and who tried and failed. On any server reachable from the internet it also shows a constant background of automated attempts to guess SSH passwords. Monday's review of ridge-web's auth.log found thousands of them.

> sudo grep "Failed password" /var/log/auth.log | tail -n 3
Nov  9 03:12:44 ridge-web sshd[20211]: Failed password for root from 192.0.2.201 port 51022 ssh2
Nov  9 03:12:47 ridge-web sshd[20213]: Failed password for invalid user admin from 192.0.2.201 port 51040 ssh2
Nov  9 03:13:02 ridge-web sshd[20220]: Failed password for invalid user oracle from 203.0.113.140 port 40112 ssh2
> sudo grep "sudo:" /var/log/auth.log | grep COMMAND | tail -n 2
Nov  9 09:31:10 ridge-web sudo:   jordan : TTY=pts/0 ; PWD=/home/jordan ; USER=root ; COMMAND=/usr/bin/apt update
Nov  9 09:33:52 ridge-web sudo:   jordan : TTY=pts/0 ; PWD=/home/jordan ; USER=root ; COMMAND=/usr/bin/systemctl restart nginx

The failed attempts are a reason to act, not to panic. With the firewall from lesson 8 only allowing SSH from the office and the roastery, these attempts came from the brief window before ufw was enabled; fail2ban, which bans addresses after repeated failures, and key-only logins in lesson 10 close the door completely. The sudo lines show the audit trail: every privileged command, with the user, directory and full command line. Counting failed attempts by address is a classic first script for a new administrator.

A troubleshooting method

Every problem is different, but a consistent method works for problems you have never met. First, define the symptom precisely: what fails, for whom, since when, and what changed recently. Second, check the obvious, because most outages have dull causes: is the service running, is a disk full, did an update or configuration change happen just before? Third, read the logs for the failing component, errors first, around the time the trouble started. Fourth, form one hypothesis, test it with one change, and observe; changing several things at once leaves you not knowing which one worked. Finally, write down what happened and fix the underlying cause, not just the symptom, so it does not return.

def failed_by_address(log_text):
    counts = {}
    return counts

def serious(lines, worst=3):
    return lines

def load_status(uptime_line, cpus):
    return 'ok'