Reading Logs 2: Getting Answers from Logs with Pipes, Redirection, grep, awk, sed, sort and uniq

Version note: The commands in this post were run on a test VM with Ubuntu Server 24.04.5 LTS (bash 5.2, grep 3.11, gawk 5.2, sed 4.9, coreutils 9.4, jq 1.7, Nginx 1.24); Bookstore.Api was built with .NET SDK 10.0.402 and run on the ASP.NET Core 10.0.15 runtime.

Guess First

You want to find the IP sending the most requests to the server of Bookstore, the online bookstore used as the shared example across this site's series, and you type this:

awk '{print $1}' /var/log/nginx/bookstore.access.log | uniq -c | sort -rn | head -n 1

The command prints an IP and a number without any error. Is that number the total request count of that IP? We will see the answer with a small example in the Common Pitfalls section.

In the previous post we saw where the logs are and how to narrow them down with journalctl. In this post we get answers out of logs: the basics of redirection and pipes, then four questions on a real Nginx access log, answered by chaining grep, awk, cut, sed, sort, uniq and wc. Turning these commands into a script and dealing with exit status and pipefail is the job of the Bash Scripting series; here we use them interactively on the command line.

stdin, stdout, stderr and Redirection

Every process starts with three streams: stdin (input) as number 0, stdout (normal output) as number 1 and stderr (error messages) as number 2. Since both outputs go to the terminal by default, you usually only see the difference when you redirect output to a file:

$ ls -d /opt/bookstore /opt/catalog
ls: cannot access '/opt/catalog': No such file or directory
/opt/bookstore
$ ls -d /opt/bookstore /opt/catalog > out.txt
ls: cannot access '/opt/catalog': No such file or directory
$ cat out.txt
/opt/bookstore
$ ls -d /opt/bookstore /opt/catalog > out.txt 2>&1; cat out.txt
ls: cannot access '/opt/catalog': No such file or directory
/opt/bookstore
$ ls -d /opt/bookstore /opt/catalog 2>&1 > out.txt
ls: cannot access '/opt/catalog': No such file or directory
$ ls -d /opt/catalog 2>/dev/null; echo "exit=$?"
exit=2

> writes only stdout to the file; the error still shows on the terminal. 2>&1 means "connect stderr to wherever stdout points right now", and it is read from left to right. That is why order matters: in > out.txt 2>&1 stdout goes to the file first and stderr follows it; in 2>&1 > out.txt stderr is connected to the terminal while stdout is still there, and the error never reaches the file. 2>/dev/null throws the error away entirely; the exit code ($?) is still 2, so the error is hidden, not gone. > overwrites the file, >> appends to it:

$ echo "deploy 2026-11-14-6" > notes.txt; echo "deploy 2026-11-14-7" >> notes.txt; cat notes.txt
deploy 2026-11-14-6
deploy 2026-11-14-7

In production, redirecting a command's output to the wrong file with > empties that file instantly; for a config file or a log, use >> when in doubt or take a copy first.

Pipes and Small Tools

| (pipe) connects the stdout of the command on the left to the stdin of the one on the right. That is also the idea behind Unix tools: each tool does one job well, reads plain text, writes plain text, and you answer the question by chaining them. Almost every chain in this post uses the same skeleton: extract a field (awk, cut), filter (grep), sort (sort), count (uniq -c, wc -l), take the first few (head). If you want to both see an intermediate result on screen and save it to a file, use tee:

$ awk '{print $1}' /var/log/nginx/bookstore.access.log | sort | uniq -c | sort -rn | tee top-ips.txt | head -n 3
   1482 198.51.100.23
    533 203.0.113.8
    492 192.0.2.44
$ wc -l top-ips.txt
13 top-ips.txt

tee writes its input to the file and also passes it on to the next command: the screen shows the first three lines, the file has all 13 IPs. Handy for sharing what you found with the team during an incident.

The Fields of the Access Log

In the previous post Nginx wrote Bookstore's log in the default combined format. For the question "which request is the slowest" we need the request time, and for "where is this request's application log" we need a request ID. We added our own format to the site configuration (in the repository at deploy/linux/nginx/bookstore.conf):

# /etc/nginx/sites-available/bookstore
log_format bookstore '$remote_addr - $remote_user [$time_local] "$request" '
                     '$status $body_bytes_sent "$http_referer" "$http_user_agent" '
                     '$request_time $upstream_response_time $request_id';

server {
    listen 80 default_server;
    server_name _;

    # The load balancer in front of us sends the real client IP
    set_real_ip_from 10.20.30.0/24;
    real_ip_header X-Forwarded-For;

    access_log /var/log/nginx/bookstore.access.log bookstore;
    error_log /var/log/nginx/bookstore.error.log;

    location / {
        proxy_pass http://127.0.0.1:5000;
        proxy_set_header Host $host;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Proto $scheme;
        proxy_set_header X-Request-ID $request_id;
    }
}

The format is the same as combined with three fields added at the end: $request_time (the time from Nginx receiving the request to sending the last byte of the response, in seconds), $upstream_response_time (Bookstore.Api's response time) and $request_id (a random ID Nginx generates for each request; we also send the same value to the application in the X-Request-ID header). The set_real_ip_from lines write the real client IP that the load balancer in front sends in X-Forwarded-For into $remote_addr; why and when that is safe is covered in the Forwarded Headers post of the Web Servers and Hosting series. In the lab I simulated the load balancer with about 5,800 requests from the client machine, using IPs reserved for documentation (198.51.100.x, 203.0.113.x, 192.0.2.x); all outputs below come from that traffic.

$ head -n 2 bookstore.access.log
198.51.100.23 - - [14/Nov/2026:16:00:23 +0000] "GET /api/books/9780141439518 HTTP/1.1" 404 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:145.0) Gecko/20100101 Firefox/145.0" 0.064 0.064 891c7f5d4c5bb4c3c589541f2a307dc4
192.0.2.44 - - [14/Nov/2026:16:00:23 +0000] "GET /api/books/9780141439518 HTTP/1.1" 404 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0 Safari/537.36" 0.052 0.052 493b0ea0859a0fe3d0a0e895dadb4b5c
$ awk '{print $1, $9, $(NF-2)}' bookstore.access.log | head -n 3
198.51.100.23 404 0.064
192.0.2.44 404 0.052
203.0.113.57 200 0.140

awk splits a line on whitespace and gives you the pieces as $1, $2 and so on. In this format $1 is the IP, $4 is [14/Nov/2026:16:00:23, $7 the path, $9 the status and $10 the bytes. Because the user agent contains spaces, the field numbers after it change from line to line; that is why we count from the end: NF is the number of fields, $NF the last field (the request ID), $(NF-2) the third from the end ($request_time). To take a quoted field as a whole, cut is easier; splitting on the " character, the sixth piece is the user agent:

$ cut -d'"' -f6 bookstore.access.log | sort | uniq -c | sort -rn
   1686 bookstore-web/22.2
   1651 Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0 Safari/537.36
   1624 Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:145.0) Gecko/20100101 Firefox/145.0
    239 python-requests/2.32.3

Scenario 1: Who Sends How Many Requests?

$ awk '{print $1}' bookstore.access.log | sort | uniq -c | sort -rn | head
   1482 198.51.100.23
    533 203.0.113.8
    492 192.0.2.44
    486 203.0.113.5
    266 198.51.100.7
    252 203.0.113.57
    251 198.51.100.66
    248 192.0.2.201
    247 203.0.113.150
    239 192.0.2.99
$ awk '{print $9}' bookstore.access.log | sort | uniq -c | sort -rn
   4289 200
    774 404
     71 502
     66 503

The chain works like this: awk extracts the IPs, sort brings identical IPs next to each other, uniq -c counts consecutive identical lines, sort -rn sorts numerically (-n) from largest to smallest (-r), and head gives the first 10. One IP sends more than a quarter of all traffic. The 404s also stand out; to see which addresses that IP got 404s for, I used the part of awk that can take a condition:

$ awk '$1 == "198.51.100.23" && $9 == 404 {print $7}' bookstore.access.log | sort | uniq -c
     90 /api/books/9780000000000
     84 /api/books/9780141439518
$ grep -E "wp-login|\.env|phpmyadmin|\.git" bookstore.access.log | awk '{print $1, $9, $7}' | sort | uniq -c
     48 192.0.2.99 404 /.env
     63 192.0.2.99 404 /.git/config
     61 192.0.2.99 404 /phpmyadmin/
     63 192.0.2.99 404 /wp-login.php
      2 192.0.2.99 502 /.env
      1 192.0.2.99 502 /phpmyadmin/
      1 192.0.2.99 502 /wp-login.php

In awk, a condition written before the braces (such as $9 == 404) makes the action inside them run only on lines that match it. The first result shows a client repeatedly asking for two ISBNs that are not in the catalog; probably a caching bug or an old link. The second is a familiar picture: a bot looking for hidden files such as .env and .git/config. grep -E turns on extended regex, and | means "or"; since a dot in a regex means "any character", we escaped it as \.. Blocking such an IP is the topic of the eleventh post.

Scenario 2: 5xx per Minute and the Window of an Incident

The status breakdown has 71 502s. When did they happen?

$ awk '$9 ~ /^5/ {print substr($4, 14, 5), $9}' bookstore.access.log | sort | uniq -c
     24 16:00 503
      7 16:01 503
     35 16:04 503
     71 16:05 502

$9 ~ /^5/ selects statuses starting with 5. substr($4, 14, 5) takes five characters from the 14th character of the [14/Nov/2026:16:05:07 field, i.e. the hour and minute. The table separates two different problems: the 503s are few and spread out over the day (the payment provider timeouts we added in the previous post), while the 502s are packed into a single minute. To look closer at that minute, use sed's range selection:

$ sed -n "/:16:05:00 /,/:16:05:30 /p" /var/log/nginx/bookstore.access.log | awk "{print \$9}" | sort | uniq -c
    102 200
     22 404
     71 502
$ grep -o "connect() failed ([^)]*)" bookstore.error.log | sort | uniq -c
     71 connect() failed (111: Connection refused)

sed -n turns off the default output and p prints only the selected lines; /A/,/B/ selects everything from the first line containing A to the first line containing B. It also works with line numbers, as in sed -n '100,120p'. All 502s are between 16:05:00 and 16:05:30, and all 71 lines in the error log are the same: the connection to the upstream was refused, so nothing was listening behind it. grep -o prints only the matching part instead of the whole line; useful for counting different kinds of errors. Looking at the same window in the journal shows the reason:

$ journalctl -u bookstore-api --since 16:04 --until 16:06 -o short-iso --no-pager | grep -E "Stopped|started"
2026-11-14T16:05:07+00:00 bookstore-dev bookstore-api[3992]: Bookstore.Api[0] Stopped cleanly
2026-11-14T16:05:07+00:00 bookstore-dev systemd[1]: Stopped bookstore-api.service - Bookstore API (ASP.NET Core on Kestrel).
2026-11-14T16:05:54+00:00 bookstore-dev bookstore-api[4181]: Microsoft.Hosting.Lifetime[0] Application started. Hosting environment: Production; Content root path: /opt/bookstore/releases/2026-11-14-6
2026-11-14T16:05:54+00:00 bookstore-dev bookstore-api[4181]: Bookstore.Api[0] Bookstore.Api started, PID 4181

The service was stopped at 16:05:07 and started again 47 seconds later; the 502s fall exactly in that window. In the previous post we found a 502 by hand; this time we found it with numbers and a time range.

Scenario 3: The Slowest Requests

$ awk '{print $(NF-2), $9, $7}' bookstore.access.log | sort -rn | head -n 20
3.052 200 /api/reports/sales?seconds=3
3.034 200 /api/reports/sales?seconds=3
3.016 200 /api/reports/sales?seconds=3
...
$ grep -v "/reports/" /var/log/nginx/bookstore.access.log | awk '{print $(NF-2), $9, $7}' | sort -rn | head -n 5
2.026 200 /api/books
2.010 200 /api/books/9780141439587
1.999 200 /api/books/9780141439587
1.980 200 /api/books
0.381 503 /api/orders/2596

All of the top 20 are the report endpoint that is slow on purpose, which is expected. grep -v drops matching lines; with the reports removed, the interesting part shows up: /api/books, which normally takes a few milliseconds, took two seconds. Their timestamps show these were the first requests right after the application restarted: in .NET the first requests are slow because of JIT compilation and startup work. For an average per endpoint instead of individual lines, use awk's arrays:

$ awk '{u=$7; sub(/\?.*/, "", u); gsub(/[0-9]{4,}/, "{id}", u); n[u]++; t[u]+=$(NF-2)} END {for (k in n) printf "%-24s %6d %8.3f\n", k, n[k], t[k]/n[k]}' bookstore.access.log | sort -k2,2rn
/api/books                 1773    0.007
/api/orders/{id}           1709    0.076
/api/books/{id}            1326    0.008
/api/reports/sales          103    1.921
/wp-login.php                64    0.004
/.git/config                 63    0.005
/phpmyadmin/                 62    0.006
/.env                        50    0.004
/health                      50    0.006

For each line we put the path in u, remove the query string with sub, and turn numbers of four or more digits into {id} with gsub so that each ISBN and order number does not get its own row. n[u] accumulates the request count and t[u] the total time; the END block runs once when the file ends and prints the average. sort -k2,2rn sorts on the second column, numerically and in reverse. Orders are ten times slower than books because the application simulates a 20–120 ms delay while waiting for the payment provider. This table is a very rough version of what an APM tool does; on a single server, with nothing installed, in a minute.

Scenario 4: Following a Request, Compressed Logs and jq

A customer says they got an error on the order page. We find the 503 in the Nginx log and move to the application log with the request ID at the end:

$ grep "\" 503 " /var/log/nginx/bookstore.access.log | tail -n 1
203.0.113.5 - - [14/Nov/2026:16:04:59 +0000] "GET /api/orders/4520 HTTP/1.1" 503 151 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:145.0) Gecko/20100101 Firefox/145.0" 0.092 0.092 72acdb39420755c1047bf42ca7a3898d
$ journalctl -u bookstore-api -b --grep 72acdb39420755c1047bf42ca7a3898d -o short-iso --no-pager
2026-11-14T16:04:59+00:00 bookstore-dev bookstore-api[3992]: Bookstore.Api[0] Payment provider timeout for order 4520, request 72acdb39420755c1047bf42ca7a3898d

The two logs are linked by the same ID: Nginx tells who, when and how long; the application tells why. The quotes and spaces in grep "\" 503 " matter: had we searched for just 503, we would also have matched a 503 inside an order number or a duration. Carrying this ID across several services and queues is covered in the correlation ID post of the .NET Logging series and in the post on finding causes in logs in the Debugging and Problem Solving series.

For the old files that logrotate has rotated and compressed, there are versions that work without unpacking them: zgrep, zcat, zless.

$ zgrep -c " 503 " bookstore.access.log.2.gz
5
$ zcat bookstore.access.log.2.gz | awk '{print $9}' | sort | uniq -c | sort -rn
    254 200
     41 404
      5 503

The application log lives in the journal, so it has no plain text file, but the journal can output JSON, and the right tool for JSON is jq:

$ journalctl -u bookstore-api -p err --since "-30min" -o json --no-pager | jq -r '[.__REALTIME_TIMESTAMP, .PRIORITY, .MESSAGE] | @tsv' | tail -n 3
1794672294728805    3    Bookstore.Api[0] Payment provider timeout for order 3171, request a1447812bfcbcc5d1eb57dac8576cb48
1794672295231002    3    Bookstore.Api[0] Payment provider timeout for order 2308, request ae43270bdafca2663f17b2212b0a231b
1794672299199455    3    Bookstore.Api[0] Payment provider timeout for order 4520, request 72acdb39420755c1047bf42ca7a3898d
$ journalctl -u bookstore-api -p err --since "-30min" -o json --no-pager | jq -r '.MESSAGE' | grep -oE "order [0-9]+" | wc -l
73

-o json writes each entry as a single-line JSON object; jq picks the fields you want, @tsv turns them into a tab-separated line, and the result goes back into a grep/awk chain. The same approach works if your application writes its logs as JSON. jq itself is covered in detail in the Terminal and Command Line series.

Production Notes

On a large file, narrow first and process second. On an access log of several GB, sort uses both memory and disk (it writes temporary files to /tmp). First get down to the relevant time range with grep or sed -n, then sort. Running a heavy chain on a live server with low priority via nice (fourth post) keeps you from touching the application's CPU.

Reading logs on the server is for a quick first look. If you ask the same question every week (5xx per minute, slowest endpoint), the answer belongs on a dashboard and in an alert; the upcoming Observability series covers this with metrics. These chains are the tools you have left when there is no central system or it is not enough.

Logs contain personal data: IP addresses, user agents, sometimes an e-mail in a query string. If you copy a file to your own machine for analysis, mask it first; sed -E is enough for that:

$ sed -E "s/^([0-9]+\.[0-9]+)\.[0-9]+\.[0-9]+/\1.x.x/" /var/log/nginx/bookstore.access.log | head -n 2 | cut -c1-80
198.51.x.x - - [14/Nov/2026:16:00:23 +0000] "GET /api/books/9780141439518 HTTP/1
192.0.x.x - - [14/Nov/2026:16:00:23 +0000] "GET /api/books/9780141439518 HTTP/1.

s/old/new/ substitutes, -E enables extended regex, \1 is the first group captured in parentheses. Privacy-compliant logging is covered in the sensitive data post of the .NET Logging series.

Common Pitfalls

Using uniq on unsorted input. The answer to the guess: uniq only merges identical lines that are next to each other.

$ printf "203.0.113.5\n198.51.100.23\n203.0.113.5\n" | uniq -c
      1 203.0.113.5
      1 198.51.100.23
      1 203.0.113.5
$ printf "203.0.113.5\n198.51.100.23\n203.0.113.5\n" | sort | uniq -c
      1 198.51.100.23
      2 203.0.113.5

In a real log the same IP is split into thousands of pieces and sort -rn | head -n 1 gives you only the longest unbroken run; since the command does not fail, you do not notice the wrong number. Rule: always sort before uniq.

Forgetting regex escapes. Searching for an IP looks harmless:

$ grep -c "203.0.113.5" bookstore.access.log
738
$ grep -c "^203\.0\.113\.5 " bookstore.access.log
486
$ grep -c "/api/reports/sales?seconds=1" bookstore.access.log
38
$ grep -cE "/api/reports/sales?seconds=1" bookstore.access.log
0

The first command also counted 203.0.113.57, because a dot is any character and there is no boundary at the end. The right way is to escape the dots and anchor to the start of the line (^) and the trailing space; if you are searching for fixed text, grep -F turns regex off completely. The second pair is sneakier: in a basic regex ? is a literal character, with -E it means "the previous character is optional", and the same expression finds 0 instead of 38.

Forgetting that sorting depends on the locale:

$ printf "bookstore\nBookstore\nAPI\napi\n" | LC_ALL=en_US.UTF-8 sort
api
API
bookstore
Bookstore
$ printf "bookstore\nBookstore\nAPI\napi\n" | LC_ALL=C sort
API
Bookstore
api
bookstore

Same input, two results. en_US.UTF-8 uses dictionary order, C byte order. This server comes with C.UTF-8, but if the locale differs on your own machine or another server, sorting two files with sort and comparing them with comm or join silently gives wrong results. In scripts and comparisons write LC_ALL=C; it is both consistent and faster.

Writing cat file | grep. It works, but adds an unnecessary process and pipe; grep expression file does the same job and also knows the file name (with -c on several files it gives a count per file). On large files, putting grep at the start of the chain sends fewer lines to every command after it.

Assuming field numbers are fixed. After fields that contain spaces, such as the user agent, $12 and $13 change from line to line. Count from the end ($NF, $(NF-2)) or use cut -d'"' for quoted fields. When you change the log format, check these chains too.

A Small Experiment

★☆☆ Get the status breakdown of the Nginx access log on your own server and find the top 10 paths returning 404 with awk '$9 == 404 {print $7}' | sort | uniq -c | sort -rn | head.

★★☆ Print the number of requests per hour and the 5xx ratio in the same hour with a single awk command (hint: two arrays, division in END). Save the result to a file as well with tee.

★★★ Bookstore's log_format already has $upstream_response_time. Find the requests where the difference from $request_time is greater than 0.1 seconds: does that difference point to a slow client or a slow application? Slow down a request with curl --limit-rate 1k and verify your own answer.

The logs gave us IPs, ports and upstream errors; the next question is "is this port really open, and who is listening". In the next post we move on to network commands: diagnosing "why can't I reach it" layer by layer with ip, ss, curl, dig and nc.