Reading Logs 1: journalctl, /var/log and logrotate

Version note: The commands in this post were run on a test VM with Ubuntu Server 24.04.5 LTS (systemd 255, rsyslog, logrotate 3.21, Nginx 1.24); the code was built with .NET SDK 10.0.402 and run on the ASP.NET Core 10.0.15 runtime.

Guess First

The API of Bookstore, the online bookstore used as the shared example across this site's series, writes its logs to /var/log/bookstore/api.log. To keep the disk from filling up you added this rule to logrotate: every day rename the file to api.log.1 and create an empty api.log in its place. The next morning you look:

$ sudo ls -l /var/log/bookstore/
total 8
-rw-r----- 1 bookstore bookstore    0 Nov 14 15:48 api.log
-rw-r--r-- 1 root      root      4815 Nov 14 15:48 api.log.1

The application is running and serving requests. Where are the new log lines, and why is api.log 0 bytes? The answer is in the logrotate section.

In the fifth post we handed Bookstore over to systemd and saw that all its output goes to the journal. In this post we learn to read those logs: the filters of journalctl, what is inside a journal entry, where the journal lives on disk and how much space it takes, the classic files in /var/log, and logrotate. Getting answers out of logs with grep, awk and sort is the topic of the next post.

journalctl and Permissions: "No entries" Does Not Always Mean Empty

You log in to the server and the first thing you do is look at Bookstore's log:

$ id
uid=1000(ada) gid=1000(ada) groups=1000(ada),27(sudo)
$ journalctl -u bookstore-api -n 3 --no-pager
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal' can see all messages.
      Pass -q to turn off this notice.
-- No entries --
$ tail -n 2 /var/log/syslog
tail: cannot open '/var/log/syslog' for reading: Permission denied

The service is writing logs, but a regular user only sees entries from their own processes in the journal. -- No entries -- here does not mean "there are no logs" but "there are no logs to show you", and the hint above says so plainly. Instead of typing sudo every time, add the user to the adm group; on Ubuntu this group grants read access both to the journal and to the files in /var/log owned by syslog:adm. Group changes take effect in a new session, so log out of the SSH session and connect again:

$ sudo usermod -aG adm ada
$ id
uid=1000(ada) gid=1000(ada) groups=1000(ada),4(adm),27(sudo)
$ journalctl -u bookstore-api -n 3 --no-pager
Nov 14 15:43:07 bookstore-dev bookstore-api[1430]: Microsoft.AspNetCore.Routing.EndpointMiddleware[0] Executing endpoint 'HTTP: GET /api/books'
Nov 14 15:43:07 bookstore-dev bookstore-api[1430]: Microsoft.AspNetCore.Routing.EndpointMiddleware[1] Executed endpoint 'HTTP: GET /api/books'
Nov 14 15:43:07 bookstore-dev bookstore-api[1430]: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.0 GET http://127.0.0.1/api/books - 200 - application/json;+charset=utf-8 65.6287ms

adm is a read-only group and does not grant sudo; it is the right level for a developer who needs to look at logs but does not administer the server. If you use WSL 2 on Windows, you can try the same commands there: on a current Ubuntu installed with wsl --install, systemd is on by default; otherwise you need to add systemd=true under [boot] in /etc/wsl.conf and restart WSL.

Filters: -u, -f, -p, --since, --grep and -b

For this post we added two endpoints to Bookstore.Api: one writes a Warning when a book is not found, the other an Error when the payment provider times out. The second also puts the X-Request-ID header sent by Nginx into the log; in the seventh post we will follow a request from the Nginx log to the application log with this value.

app.MapGet("/api/books/{isbn}", (string isbn) =>
{
    Book? book = books.FirstOrDefault(b => b.Isbn == isbn);
    if (book is null)
    {
        app.Logger.LogWarning("Book {Isbn} not found", isbn);
        return Results.NotFound();
    }
    return Results.Ok(book);
});

// Order lookup: the payment provider sometimes times out (simulated)
app.MapGet("/api/orders/{id:int}", async (int id, HttpContext context) =>
{
    string requestId = context.Request.Headers["X-Request-ID"].FirstOrDefault() ?? context.TraceIdentifier;
    await Task.Delay(Random.Shared.Next(20, 120));
    if (Random.Shared.Next(100) < 4)
    {
        app.Logger.LogError("Payment provider timeout for order {OrderId}, request {RequestId}", id, requestId);
        return Results.Problem("Payment provider timeout", statusCode: 503);
    }
    return Results.Ok(new { id, status = "Shipped", total = 24.49m });
});

We also put Nginx in front of Bookstore; the site configuration is in the repository at deploy/linux/nginx/bookstore.conf and it writes to its own access and error log files. I sent 120 order requests and looked only at the important lines:

$ for i in $(seq 1 120); do curl -s -o /dev/null -w "%{http_code}\n" http://127.0.0.1/api/orders/$((1000+i)); done | sort | uniq -c
    119 200
      1 503
$ journalctl -u bookstore-api -p warning --since "10 min ago" --no-pager
Nov 14 15:43:30 bookstore-dev bookstore-api[1430]: Bookstore.Api[0] Book 9780000000000 not found
Nov 14 15:44:07 bookstore-dev bookstore-api[1430]: Bookstore.Api[0] Payment provider timeout for order 1088, request 681cdf147ca6bf3d8b9906fcd64b0e3f
$ journalctl -u bookstore-api -p err -o cat --no-pager | tail -n 2
bookstore-api.service: Service has more than one ExecStart= setting, which is only allowed for Type=oneshot services. Refusing.
Bookstore.Api[0] Payment provider timeout for order 1088, request 681cdf147ca6bf3d8b9906fcd64b0e3f

-p (priority) returns the given level and everything more important: -p warning gives Warnings and Errors, -p err only Errors and above. This is the fastest way to find two lines among thousands of informational ones. The first line of the -p err output is not from the application but from systemd: it is left over from the broken drop-in experiment in the fifth post. Because the -u filter also brings the systemd messages about the unit, the answer to "why didn't the service start" shows up in the same command. -o cat drops the date and host columns and shows only the message.

To watch live, use -f (follow). -n 0 waits only for new lines without showing history; from another terminal I requested a book that does not exist:

$ journalctl -u bookstore-api -f -n 0 -o short-iso
2026-11-14T15:45:01+00:00 bookstore-dev bookstore-api[1430]: Microsoft.AspNetCore.Hosting.Diagnostics[1] Request starting HTTP/1.0 GET http://127.0.0.1/api/books/123 - - -
2026-11-14T15:45:01+00:00 bookstore-dev bookstore-api[1430]: Microsoft.AspNetCore.Routing.EndpointMiddleware[0] Executing endpoint 'HTTP: GET /api/books/{isbn}'
2026-11-14T15:45:01+00:00 bookstore-dev bookstore-api[1430]: Bookstore.Api[0] Book 123 not found
2026-11-14T15:45:01+00:00 bookstore-dev bookstore-api[1430]: Microsoft.AspNetCore.Http.Result.NotFoundObjectResult[1] Setting HTTP status code 404.
2026-11-14T15:45:01+00:00 bookstore-dev bookstore-api[1430]: Microsoft.AspNetCore.Routing.EndpointMiddleware[1] Executed endpoint 'HTTP: GET /api/books/{isbn}'
2026-11-14T15:45:01+00:00 bookstore-dev bookstore-api[1430]: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.0 GET http://127.0.0.1/api/books/123 - 404 0 - 58.8711ms

Keeping journalctl -u bookstore-api -f open in one terminal during a deploy shows immediately whether the application comes up and whether the first requests fail. -o short-iso writes the date with the year and the time zone; handy when you put logs from several servers side by side.

Time and boot filters:

$ journalctl --list-boots --no-pager
IDX BOOT ID                          FIRST ENTRY                 LAST ENTRY
 -6 39489c2fcaa34d998572392a615a5b5a Sat 2026-11-14 14:04:18 UTC Sat 2026-11-14 14:33:37 UTC
 -5 b7a826ba3af84beca5d69bb62516e1fc Sat 2026-11-14 14:35:04 UTC Sat 2026-11-14 14:45:09 UTC
 -4 1585691d6a3b473485cfa818d19c7c3a Sat 2026-11-14 14:47:38 UTC Sat 2026-11-14 15:08:40 UTC
 -3 61774f4e01d14ea3910e04590fa0c4ea Sat 2026-11-14 15:09:09 UTC Sat 2026-11-14 15:22:03 UTC
 -2 72c22ea694844292a574072371e29e8d Sat 2026-11-14 15:24:27 UTC Sat 2026-11-14 15:26:52 UTC
 -1 28fb5a9cf9fb4779a1b91e5fa10376ce Sat 2026-11-14 15:27:39 UTC Sat 2026-11-14 15:38:21 UTC
  0 c6bbd2c1c7364e02a4b8f6d43fe19a8f Sat 2026-11-14 15:38:50 UTC Sat 2026-11-14 15:45:01 UTC
$ journalctl -u bookstore-api -b -1 -n 2 --no-pager
Nov 14 15:38:07 bookstore-dev systemd[1]: Stopped bookstore-api.service - Bookstore API (ASP.NET Core on Kestrel).
Nov 14 15:38:07 bookstore-dev systemd[1]: bookstore-api.service: Consumed 13.317s CPU time.
$ journalctl -u bookstore-api --grep "not found" --since today --no-pager
-- Boot 61774f4e01d14ea3910e04590fa0c4ea --
-- Boot 72c22ea694844292a574072371e29e8d --
-- Boot 28fb5a9cf9fb4779a1b91e5fa10376ce --
-- Boot c6bbd2c1c7364e02a4b8f6d43fe19a8f --
Nov 14 15:43:30 bookstore-dev bookstore-api[1430]: Bookstore.Api[0] Book 9780000000000 not found
Nov 14 15:45:01 bookstore-dev bookstore-api[1430]: Bookstore.Api[0] Book 123 not found

-b gives this boot, -b -1 the one before; the question "what happened before last night's reboot" starts with journalctl -b -1 -e (-e jumps to the end). --since and --until take both absolute ("2026-11-14 15:40") and relative ("10 min ago", "-1h", today, yesterday) values. --grep searches the message field with a regex; the -- Boot ... -- lines in the output are not results but separators for each boot in the searched range. Other useful filters: -t bookstore-db-backup (by SYSLOG_IDENTIFIER, the lines of the backup job from the fifth post), -k (kernel only), field matches such as _PID=1430, and -e. The output goes to less; --no-pager is only needed in a script or when piping into another command.

Inside a Journal Entry and .NET's Log Levels

The single line on the screen is really a record made of fields. -o json-pretty shows it; I shortened the long list with --output-fields:

$ journalctl -u bookstore-api -p warning -n 1 -o json-pretty --output-fields=MESSAGE,PRIORITY,SYSLOG_IDENTIFIER,_PID,_UID,_SYSTEMD_UNIT,_TRANSPORT --no-pager
{
    "__REALTIME_TIMESTAMP" : "1794671611747890",
    "PRIORITY" : "4",
    "_PID" : "2985",
    "_TRANSPORT" : "stdout",
    "MESSAGE" : "Bookstore.Api[0] Book 123 not found",
    "SYSLOG_IDENTIFIER" : "bookstore-api",
    "_UID" : "999",
    "_BOOT_ID" : "2f27f34ea7c24b8c835d6db6288c245f",
    "__CURSOR" : "s=687fadfccf6440fab19e618b2799cf33;i=4989;b=2f27f34ea7c24b8c835d6db6288c245f;m=19e9a442;t=6603e8be81e32;x=9ab4ccd4e054ae79",
    "__SEQNUM" : "18825",
    "_SYSTEMD_UNIT" : "bookstore-api.service",
    "__MONOTONIC_TIMESTAMP" : "434742338",
    "__SEQNUM_ID" : "687fadfccf6440fab19e618b2799cf33"
}

Fields starting with an underscore (_PID, _UID, _SYSTEMD_UNIT) are added by journald itself and the process cannot change them; these are the ones you can trust for auditing. _UID 999 is the bookstore service user from the third post. _TRANSPORT=stdout says the line came from the application's standard output. The interesting one is PRIORITY=4: the application wrote plain text, so how did journald know it was a Warning?

The answer is the builder.Services.AddSystemd() line we added in the fifth post. When the application runs under systemd, this line switches the console logger's formatter to the Systemd formatter: each log is written on a single line, without color codes, and the syslog level is prepended to the line as <N>. journald reads this prefix, puts it in the PRIORITY field and strips it from the message. When I redirected the same output to a file instead of the journal, the prefix shows up as is:

$ sudo tail -n 1 /var/log/bookstore/api.log
<6>Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.0 GET http://127.0.0.1/api/books - 200 - application/json;+charset=utf-8 1.3489ms

The mapping is: Critical 2 (crit), Error 3 (err), Warning 4 (warning), Information 6 (info), Debug and Trace 7 (debug). Without AddSystemd every line would be stored as PRIORITY=6 and -p err would never find the application's errors. If you run a .NET application under systemd, this single line makes reading logs much easier.

The Journal on Disk: Persistent or Volatile, and How Much Space?

journald keeps entries either in /var/log/journal (persistent, survives a reboot) or in /run/log/journal (volatile, in RAM, deleted on reboot). Storage= in /etc/systemd/journald.conf decides which:

$ grep -E "^#?(Storage|SystemMaxUse|SystemKeepFree|MaxRetentionSec)=" /etc/systemd/journald.conf
#Storage=auto
#SystemMaxUse=
#SystemKeepFree=
#MaxRetentionSec=
$ journalctl -u systemd-journald -b -o cat --no-pager | grep -i "journal (" | tail -n 2
Runtime Journal (/run/log/journal/7a5216d613204956b9683a4a5dcfa072) is 1.2M, max 9.6M, 8.3M free.
System Journal (/var/log/journal/7a5216d613204956b9683a4a5dcfa072) is 96.2M, max 1.8G, 1.7G free.

The commented-out lines show systemd 255's defaults. auto means persistent if the /var/log/journal directory exists, volatile otherwise. Ubuntu creates this directory at install time, so the journal is persistent here; but on an image without the directory (some minimal images, servers derived from containers) the same setting silently runs volatile. The upper limit also defaults to 10% of the filesystem, at most 4 GB: 1.8G on a 19 GB disk.

I saw what volatile means with an experiment. I made the journal volatile with a drop-in, wrote a line saying the deploy had finished, and restarted the server:

$ printf "[Journal]\nStorage=volatile\n" | sudo tee /etc/systemd/journald.conf.d/10-volatile.conf
[Journal]
Storage=volatile
$ sudo systemctl restart systemd-journald
$ logger -t bookstore-test "deploy 2026-11-14-5 finished"
$ journalctl -t bookstore-test --no-pager
Nov 14 15:45:45 bookstore-dev bookstore-test[2383]: deploy 2026-11-14-5 finished
$ sudo reboot
...
$ journalctl -t bookstore-test --no-pager
-- No entries --
$ journalctl --list-boots --no-pager | tail -n 3
 -2 28fb5a9cf9fb4779a1b91e5fa10376ce Sat 2026-11-14 15:27:39 UTC Sat 2026-11-14 15:38:21 UTC
 -1 c6bbd2c1c7364e02a4b8f6d43fe19a8f Sat 2026-11-14 15:38:50 UTC Sat 2026-11-14 15:45:44 UTC
  0 2f27f34ea7c24b8c835d6db6288c245f Sat 2026-11-14 15:46:36 UTC Sat 2026-11-14 15:47:53 UTC
$ grep bookstore-test /var/log/syslog
2026-11-14T15:45:45.277562+00:00 bookstore-dev bookstore-test: deploy 2026-11-14-5 finished

The previous boot ends at 15:45:44; everything written after that until the reboot, including the deploy line, is gone from the journal. If a server restarted on its own during the night, these are exactly the logs you need most. The line survived only in /var/log/syslog: on Ubuntu, ForwardToSyslog=yes in /usr/lib/systemd/journald.conf.d/syslog.conf also forwards every entry to rsyslog, which writes it to disk. I deleted the drop-in, restarted journald and moved the entries from RAM to disk with sudo journalctl --flush.

For size there are two tools: --vacuum-size and --vacuum-time for a one-off cleanup, and a drop-in for a permanent limit. For the Bookstore server we added deploy/linux/journald/50-bookstore.conf to the repository:

# /etc/systemd/journald.conf.d/50-bookstore.conf
[Journal]
Storage=persistent
SystemMaxUse=500M
SystemKeepFree=2G

$ sudo journalctl --vacuum-size=100M
Vacuuming done, freed 0B of archived journals from /run/log/journal.
Deleted archived journal /var/log/journal/7a5216d613204956b9683a4a5dcfa072/system@0006603d7389d3d6-e916cddc445e49fd.journal~ (8.0M).
Deleted archived journal /var/log/journal/7a5216d613204956b9683a4a5dcfa072/user-1000@0006603d75abe0e1-5ab7215cf91a98d6.journal~ (8.0M).
Deleted archived journal /var/log/journal/7a5216d613204956b9683a4a5dcfa072/system@0006603da0836caa-b4c1690e4e1190e9.journal~ (8.0M).
Vacuuming done, freed 24.0M of archived journals from /var/log/journal/7a5216d613204956b9683a4a5dcfa072.
Vacuuming done, freed 0B of archived journals from /var/log/journal.
$ sudo cp ~/50-bookstore.conf /etc/systemd/journald.conf.d/
$ sudo systemctl restart systemd-journald
$ journalctl -u systemd-journald -n 3 -o cat --no-pager | grep "System Journal"
System Journal (/var/log/journal/7a5216d613204956b9683a4a5dcfa072) is 95.5M, max 500.0M, 404.4M free.

Vacuum only deletes archived files and does not touch the active files being written; that is why I asked for 100 MB but the total only dropped by 24 MB, to 95.5 MB. Writing Storage=persistent explicitly makes journald recreate the directory even if it gets deleted one day. SystemKeepFree=2G makes the journal shrink itself when the disk is close to full.

The Classic Files in /var/log

rsyslog still runs on Ubuntu and writes everything that reaches the journal to plain text files as well. These are the files that older scripts and tools read with grep, tail -f and logrotate:

• /var/log/syslog: almost everything except auth; think of it as a plain text copy of the journal.
• /var/log/auth.log: SSH logins, failed attempts, sudo usage.
• /var/log/kern.log: kernel messages; hardware, disks, the OOM killer, segfaults.
• /var/log/nginx/: the access and error logs Nginx writes itself; these never reach the journal.

From the client in the lab I tried to connect with two users that do not exist and with a wrong password:

$ grep -E "Invalid user|Failed password" /var/log/auth.log | tail -n 4
2026-11-14T15:44:39.376674+00:00 bookstore-dev sshd[1987]: Failed password for invalid user admin from 10.20.30.5 port 37674 ssh2
2026-11-14T15:44:40.100714+00:00 bookstore-dev sshd[1989]: Invalid user oracle from 10.20.30.5 port 37690
2026-11-14T15:44:41.921808+00:00 bookstore-dev sshd[1989]: Failed password for invalid user oracle from 10.20.30.5 port 37690 ssh2
2026-11-14T15:44:45.354925+00:00 bookstore-dev sshd[1991]: Failed password for ada from 10.20.30.5 port 47742 ssh2

On every server open to the internet this file fills up with bots trying names like admin, oracle and root. The same information comes from journalctl -u ssh. Turning off password logins and blocking these attempts is the topic of the eleventh post.

The classic command for the kernel log is dmesg, but on Ubuntu a regular user cannot read it:

$ dmesg -T | tail -n 3
dmesg: read kernel buffer failed: Operation not permitted
$ sysctl kernel.dmesg_restrict
kernel.dmesg_restrict = 1
$ sudo dmesg -T | tail -n 2
[Sat Nov 14 15:53:00 2026] python3[3115]: segfault at 0 ip 0000741d29d8badd sp 00007fffd8219198 error 4 in libc.so.6[741d29c28000+189000] likely on CPU 0 (core 0, socket 0)
[Sat Nov 14 15:53:00 2026] Code: 00 00 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 89 f8 48 89 fa c5 f9 ef c0 25 ff 0f 00 00 3d e0 0f 00 00 0f 87 33 01 00 00 <c5> fd 74 0f c5 fd d7 c1 85 c0 74 57 f3 0f bc c0 c5 f8 77 c3 66 66
$ journalctl -k -b --grep segfault --no-pager
Nov 14 15:52:59 bookstore-dev kernel: python3[3115]: segfault at 0 ip 0000741d29d8badd sp 00007fffd8219198 error 4 in libc.so.6[741d29c28000+189000] likely on CPU 0 (core 0, socket 0)

I produced this line on purpose with a one-line Python command that reads the NULL address. dmesg -T converts the time the kernel has counted since boot into a clock time, and this conversion can drift by a second or so (15:53:00 vs 15:52:59); the time in the journal is more reliable. If you are in the adm group, journalctl -k does not need sudo. This is also where you see the kernel killing a process because memory ran out (the OOM killer); we will examine that with a real case in the tenth post.

Nginx's logs are separate. I stopped Bookstore.Api and sent a request:

$ tail -n 3 /var/log/nginx/bookstore.access.log
127.0.0.1 - - [14/Nov/2026:15:52:22 +0000] "GET /api/books HTTP/1.1" 200 179 "-" "curl/8.5.0"
127.0.0.1 - - [14/Nov/2026:15:52:39 +0000] "GET /api/books/9780547928227 HTTP/1.1" 200 70 "-" "curl/8.5.0"
127.0.0.1 - - [14/Nov/2026:15:52:40 +0000] "GET /api/books HTTP/1.1" 502 166 "-" "curl/8.5.0"
$ tail -n 1 /var/log/nginx/bookstore.error.log
2026/11/14 15:52:40 [error] 714#714: *663 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: _, request: "GET /api/books HTTP/1.1", upstream: "http://127.0.0.1:5000/api/books", host: "127.0.0.1"

The access log only shows the 502; the reason is in the error log: the connection to the upstream (127.0.0.1:5000) was refused, meaning no process is listening behind it. When you get a 502, this is the first line to look at. We will take the access log's columns (IP, time, request, status, bytes, user agent) apart with awk in the seventh post.

logrotate: Rotating Files

The journal manages its own size; plain text files are rotated by logrotate. On Ubuntu 24.04 logrotate is run not by cron but by a systemd timer:

$ systemctl list-timers logrotate.timer --no-pager
NEXT                        LEFT LAST                        PASSED UNIT            ACTIVATES
Sun 2026-11-15 00:00:00 UTC   8h Sat 2026-11-14 14:05:09 UTC      - logrotate.timer logrotate.service

1 timers listed.
Pass --all to see loaded but inactive timers, too.
$ grep -v "^#" /etc/logrotate.conf | grep -v "^$"
weekly
su root adm
rotate 4
create
include /etc/logrotate.d
$ cat /etc/logrotate.d/nginx
/var/log/nginx/*.log {
    daily
    missingok
    rotate 14
    compress
    delaycompress
    notifempty
    create 0640 www-data adm
    sharedscripts
    prerotate
        if [ -d /etc/logrotate.d/httpd-prerotate ]; then \
            run-parts /etc/logrotate.d/httpd-prerotate; \
        fi \
    endscript
    postrotate
        invoke-rc.d nginx rotate >/dev/null 2>&1
    endscript
}

/etc/cron.daily/logrotate is still there, but it exits without doing anything when systemd is running. Nginx's rule line by line: daily every day, rotate 14 keep 14 old files, compress gzip the old ones, delaycompress leave the newest old file (.1) uncompressed for one round, missingok and notifempty do not fail if the file is missing and do not rotate it if it is empty, create 0640 www-data adm create a new file with these permissions in its place. The important part is postrotate: after the file is renamed, Nginx gets the rotate command, which sends SIGUSR1 to the master process, and Nginx closes and reopens its log files. That is also the reason for delaycompress: Nginx may keep writing to .1 until it reopens the file, so it must not be compressed at that moment.

Here is the answer to the guess. For a while I had Bookstore write to a file instead of the journal (with a drop-in on the unit: StandardOutput=append:/var/log/bookstore/api.log) and wrote a rule similar to Nginx's but without postrotate:

$ cat /etc/logrotate.d/bookstore
/var/log/bookstore/*.log {
    daily
    rotate 14
    compress
    delaycompress
    missingok
    notifempty
    create 0640 bookstore bookstore
}
$ sudo logrotate -v -f /etc/logrotate.d/bookstore
...
rotating log /var/log/bookstore/api.log, log->rotateCount is 14
...
creating new /var/log/bookstore/api.log mode = 0640 uid = 999 gid = 988
$ sudo ls -l /var/log/bookstore/
total 8
-rw-r----- 1 bookstore bookstore    0 Nov 14 15:48 api.log
-rw-r--r-- 1 root      root      4815 Nov 14 15:48 api.log.1
$ sudo ls -l /proc/$(systemctl show -p MainPID --value bookstore-api)/fd/1
l-wx------ 1 bookstore bookstore 64 Nov 14 15:48 /proc/1577/fd/1 -> /var/log/bookstore/api.log.1

-f forces a rotation without waiting for the schedule, -v explains what it does (I shortened the output). Renaming does not change the file, only its name. The file descriptor (the number pointing to the open file) held by the process still points to the same file, and that file is now called api.log.1. /proc/<pid>/fd, which we saw in the fourth post, shows this clearly: standard output (fd 1) writes to api.log.1. The new api.log stays empty, and the next night, when api.log.1 is compressed into .2.gz, the application starts writing to a deleted file and the disk space does not come back (we will see that in the tenth post).

There are two solutions. If the application knows how to reopen its log file (like Nginx's SIGUSR1 or rsyslog's HUP), send it a signal in postrotate. .NET has no such signal and a systemctl restart every night means an outage. Then use copytruncate: logrotate copies the file's contents and then truncates the original; the process keeps writing to the same file:

$ sudo logrotate -f /etc/logrotate.d/bookstore
$ sudo ls -l /var/log/bookstore/
total 8
-rw-r--r-- 1 root root 2271 Nov 14 15:50 api.log
-rw-r--r-- 1 root root 2543 Nov 14 15:50 api.log.1
$ sudo ls -l /proc/$(systemctl show -p MainPID --value bookstore-api)/fd/1
l-wx------ 1 bookstore bookstore 64 Nov 14 15:50 /proc/1921/fd/1 -> /var/log/bookstore/api.log
$ sudo grep -c "Request finished" /var/log/bookstore/api.log /var/log/bookstore/api.log.1
/var/log/bookstore/api.log:5
/var/log/bookstore/api.log.1:5

The five requests before the rotation are in .1, the five after it are again in api.log. The price of copytruncate is a small window: lines written between the copy and the truncation can be lost. For it to work properly the file must also have been opened in append mode; systemd's append: and the file sinks of logging libraries open it that way. That is why deploy/linux/logrotate/bookstore in the repository uses copytruncate instead of create. For Bookstore.Api itself, though, we removed the drop-in and went back to the journal: the journal has its own size limit and no rotation problem at all. If you write to a file with a library like Serilog, use its own rolling settings and do not apply logrotate to the same file as well; the two break each other's work.

Production Notes

Measure your log volume. Bookstore.Api had no appsettings.json from the start, and ASP.NET Core wrote four lines at Information level for every request:

$ since=$(date "+%H:%M:%S"); for i in $(seq 1 100); do curl -s -o /dev/null http://127.0.0.1/api/books; done; journalctl -u bookstore-api --since "$since" -o cat | wc -l
400

For an API serving 50 requests per second that is more than 17 million lines a day. We added the setting that the project templates ship with:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning"
    }
  }
}

With the new release the same 100 requests produced 0 lines; the application's own Information logs and all Warnings and Errors remain. The .NET Logging series covers in detail which level should be on in which environment and changing the level live.

The journal and /var/log are for a single server. If you have two servers, looking for an error means grepping in two separate SSH sessions, and when a server is deleted its logs go with it. In production, collect logs in a central place: the .NET Logging series covers structured logs with Serilog and Seq, and the upcoming Observability series covers logs, metrics and traces together with OpenTelemetry. The journal on the server remains the place to look when the central system cannot be reached or the application never came up.

If the disk holding the log directory fills up, it is not only logging that stops; the database and the application on the same disk start failing too. Use SystemMaxUse for the journal, a logrotate rule for files, and journalctl --disk-usage and du -sh /var/log/* to check both. What to do when the disk is full is in the tenth post.

Common Pitfalls

Leaving the journal volatile. As we saw above, the minutes before a reboot are lost. Run journalctl --list-boots on a new server; if you see a single line and the server has restarted before, the journal is not persistent.

Seeing -- No entries -- as a user without permission and assuming there are no logs. Read the hint line, join the adm group or use sudo.

Using create in logrotate while the application writes to the file. The application keeps writing to the old file; either make it reopen the file with postrotate or use copytruncate. Before enabling a new rule, do a dry run with sudo logrotate -d /etc/logrotate.d/bookstore: it prints what it would do without touching any file.

Filling up the log disk. The default limits allow the journal up to 10% of the disk, but a file without a logrotate rule grows without limit. Turning on the application's Debug level while hunting a problem and forgetting to turn it off leads to the same result.

Looking only at the access log. The reason for 502s and 504s is in Nginx's error log and the application's exception is in the journal; do not decide without looking at all three.

A Small Experiment

★☆☆ On your own VM add your user to the adm group, reconnect, and list who logged in today with journalctl -u ssh --since today and the warnings of this boot with -p warning -b.

★★☆ Temporarily remove the builder.Services.AddSystemd() line from Bookstore.Api, deploy it and request a book that does not exist. Does journalctl -u bookstore-api -p warning find that line? Look at the PRIORITY field with -o json-pretty.

★★★ Make the application write to a file with the StandardOutput=append: drop-in, first run logrotate -f with the create rule and check where /proc/<pid>/fd/1 points, then switch to copytruncate and repeat. Send 100 requests per second during the rotation and count whether copytruncate loses any lines.

You now know where the logs are and how to narrow them down. In the next post we get answers out of those lines: chaining small tools with pipes and redirection to find the IPs sending the most requests, the number of 5xx responses per minute and the slowest requests in the Nginx access log.