verifyfirst

Logs and stdout

You read the output and it looked normal.

What it captures

What the program chose to say about itself, in the branches that say anything.

What it cannot see

Known failures · 15

NS-011 observedmisattributed-victim

The OOM killer names the fattest process, not the one that leaked

reads as
A long-running session dies mid-task. The log records that session being killed. Conclusion drawn: that session was the problem.
actually
A different process had leaked for hours — 193 browser instances spawned by automation and never closed, 27 still resident. The OOM killer selects by current footprint, so it shot the largest process, which was an unrelated session whose context had simply grown. The leak and the casualty were different processes.
blind because
The log faithfully records the victim. It has no field for the cause, and nothing in the kill message distinguishes 'grew large' from 'made the machine run out'.
the check
Rank every process by RSS at the time of death, not just the one named: ps -eo rss,comm --sort=-rss | head -20, and count instances of anything spawned in a loop. A single fat process is a victim; a hundred medium ones are the cause.
cost of missing
The innocent session is blamed and 'fixed'. The leak keeps running and takes another process later.
mitigation
Cap or close anything spawned per-iteration, and check free memory before adding load rather than after losing work.
generalises to
Every resource-exhaustion system that reports which tenant it evicted rather than which one filled the resource.
NS-028 documentedhandle-outlives-the-path

A rotated log leaves the daemon writing to a file that no longer has a name

reads as
app.log exists, is zero bytes, and gains no lines. Conclusion drawn: the service is idle, or has stopped working.
actually
logrotate renamed or removed the file the process had open. The process still holds the old inode and keeps appending to it. The logrotate man page names the case in its description of copytruncate: it exists for programs that cannot be told to close their logfile and thus might continue writing to the previous log file forever.
blind because
Reading a log means resolving a path. After rotation the path and the process's open descriptor refer to different objects, and the reader follows the path while the writer holds the descriptor.
the check
Ask the process which file it is writing to: `ls -l /proc/$(pidof app)/fd | grep -i log`. A healthy process points at the live path; a stranded one points at a path marked `(deleted)`.
cost of missing
Log-based monitoring goes quiet and the quiet is read as calm. Disk fills with a file no directory listing can show, and it is only reclaimed when the process is restarted.
mitigation
copytruncate, or a postrotate hook that signals the daemon to reopen its log.
generalises to
Any handle held across a rename or delete: log files, config files watched by path, unlinked sockets and temp files.
source
man7.org
NS-029 documentedfiltered-not-absent

Python discards records below WARNING when no logging is configured

reads as
A script instrumented with logger.info() at every step produces no output at all. Conclusion drawn: the code path never ran.
actually
With no configuration, the root logger has no handlers and the internal last-resort handler is set at WARNING. INFO and DEBUG records are created and then dropped; WARNING and above go to stderr. The code ran, and said so, into nothing.
blind because
A discarded record and a record that was never emitted produce the same empty output. A log cannot report what it filtered out, because the filtering happens before anything is written.
the check
`logging.getLogger(__name__).isEnabledFor(logging.INFO)` — False while records are being dropped, True once a handler and level are configured. Observed on 3.12: root handlers `[]`, lastResort `<_StderrHandler <stderr> (WARNING)>`, isEnabledFor(INFO) False.
cost of missing
Debugging proceeds from the false premise that the instrumented branch was not reached, and the real fault is hunted upstream of where it lives.
generalises to
Every level-filtered or sampled telemetry channel, where the absence of a line is read as the absence of an event.
source
docs.python.org
NS-031 documentedunflushed-buffer

A killed process loses the output it produced but never flushed

reads as
A worker is killed and its log ends several steps before the operation under investigation. Conclusion drawn: execution never reached that step.
actually
Standard output is block-buffered whenever it does not refer to a terminal, so lines accumulate in a user-space buffer of a few kilobytes until it fills or the process exits cleanly. SIGKILL cannot be caught, blocked or handled, so no flush happens. The steps ran, announced themselves, and the announcements died in the buffer.
blind because
A log records what was flushed, not what was written. A line that was never produced and a line that was produced into a buffer and then discarded are the same absence.
the check
Re-run with buffering removed and kill it the same way: `PYTHONUNBUFFERED=1 prog > out.log` (or `stdbuf -oL` for a C program). Observed on 3.12: a script printing two lines and then sleeping, SIGKILLed two seconds in, left out.log at 0 bytes; the identical run under PYTHONUNBUFFERED=1 left both lines. Output that appears only when unbuffered was being produced all along.
cost of missing
The investigation moves upstream of the last logged line, which is not where the process was. The fault lives inside the region the log appears to prove was never entered.
mitigation
Anything whose log will be read after an abnormal death should be unbuffered at the point of writing; adding it at the point of reading is too late.
generalises to
Every buffered channel inspected after an abrupt stop: stdio, log shippers with in-memory queues, metrics flushed on a timer, traces batched before export.
source
docs.python.org
NS-032 documentedrate-limited-not-absent

journald discards every message past the burst and files the notice elsewhere

reads as
`journalctl -u worker` covers the whole run and contains no error and no completion line. Conclusion drawn: the worker raised no error, and the absent completion line is the anomaly worth chasing.
actually
If more messages than RateLimitBurst are logged by a service inside RateLimitIntervalSec, all further messages within the interval are dropped until the interval is over. The default is 10000 messages in 30s, multiplied by a factor derived from the free disk space available to the journal. Everything the service says after the burst is exhausted is discarded, including the line that mattered.
blind because
The stored records are contiguous and well-formed; the log simply stops and later resumes. A message about the number of dropped messages is generated, but by journald under its own identity, so a query filtered to the unit does not show it — and a reader outside the systemd-journal and adm groups cannot see it at all.
the check
Count what the producer emitted against what the journal stored. Observed on this host: a transient unit emitting 120,001 numbered lines in 2.1s stored 37,499 of them — line 1 through line 37,499 and then nothing at all, with the final line absent and no suppression notice visible under `journalctl --user -u NAME`.
cost of missing
A verbose service is treated as a well-instrumented one, and its silence during the interesting minute is read as calm rather than as the direct consequence of its own verbosity.
mitigation
LogRateLimitIntervalSec= and LogRateLimitBurst= can be raised per unit, but a service logging at that rate needs to log less rather than louder.
generalises to
Every sampled or throttled telemetry path: metrics agents, trace sampling, syslog rate limits, ingestion quotas in hosted log services.
source
man7.org
NS-033 documentedconfiguration-silently-declined

basicConfig does nothing once anything has already touched the root logger

reads as
`logging.basicConfig(level=logging.DEBUG)` runs at the top of main() and the program still emits only warnings. Conclusion drawn: the instrumented branches are not being reached, or the level argument is wrong.
actually
The function does nothing if the root logger already has handlers configured, unless force is set to True. One earlier call to logging.warning(), one imported library that logs during import, or one framework that configures logging first, installs a handler; every later basicConfig call is then a no-op and the root level stays at WARNING.
blind because
The call raises nothing and returns nothing to inspect, and the handler that is present is a working handler emitting real lines. The output is a correct log at the wrong level, which is far more convincing than no log at all.
the check
Interrogate the configuration rather than the output: `python3 -c 'import logging; logging.warning("x"); logging.basicConfig(level=logging.DEBUG); print(logging.root.handlers, logging.root.level, logging.getLogger().isEnabledFor(logging.INFO))'`. Observed on 3.12: handlers `[<StreamHandler <stderr> (NOTSET)>]`, level 30, isEnabledFor(INFO) False; with `force=True` the INFO record appears and isEnabledFor(INFO) is True.
cost of missing
Missing lines are attributed to unreached code, and the debugging effort goes into the application instead of into the two lines of logging setup that declined to apply.
generalises to
Every initialiser that is idempotent by doing nothing: first-wins registries, singleton bootstrappers, setup functions that check for prior state and return quietly.
source
docs.python.org
NS-034 documentedinstrument-fails-silently

A malformed log call discards its own record and returns normally

reads as
app.log holds the lines either side of a payment and no line for the payment itself. Conclusion drawn: that branch did not execute.
actually
The argument count did not match the format string. Interpolation happens inside the handler rather than at the call site, so the exception is raised during emit() and routed to Handler.handleError. The call returns normally, the program continues, the exit status is 0, and the record is gone. Where logging.raiseExceptions has been set to False — 'this is what is mostly wanted for a logging system' — nothing is written anywhere.
blind because
The line is missing for a reason internal to the logging subsystem, and the logging subsystem is the instrument being read. Its own failures are the one class of event it is built not to report through itself.
the check
Look on the other stream, which is where the default handler puts its own failures: `python3 app.py 2>&1 >/dev/null | grep -c '^--- Logging error ---'` — non-zero when records were formatted and thrown away, zero when the branch genuinely did not run. Observed on 3.12: `log.info('charged %s for %s', 'user-1')` produced a TypeError traceback on stderr, exit status 0, and an app.log containing only the following line; with `logging.raiseExceptions = False` stderr was 0 bytes and the log was identical.
cost of missing
The audit trail has a hole exactly where an operation is hardest to reconstruct, and the hole is read as evidence the operation did not happen.
mitigation
Route stderr to the same destination as the log, so the logging subsystem's own failures land beside the records they replaced.
generalises to
Every subsystem asked to report on itself: monitoring agents that cannot alert on their own death, error trackers that drop malformed events, audit logs that fail open.
source
docs.python.org
NS-035 documentedreordered-by-buffering

Combined stdout and stderr arrive in an order that never happened

reads as
`prog > run.log 2>&1` yields three failure lines followed by three start lines. Conclusion drawn: the failures preceded the work, so something failed before the steps began.
actually
Standard output is fully buffered when it does not refer to an interactive device; standard error is not. Redirected to a file, stdout accumulates and is written in one block at exit while every stderr line goes straight through. The order in the merged file is an artefact of buffering policy, not a record of time.
blind because
A log is read as a sequence and a sequence is read as causality. The merged file records neither the originating stream nor the moment of emission, so the interleaving is the only ordering evidence available and it is precisely the part that was destroyed.
the check
Re-run with stdout unbuffered and compare the two files. Observed on 3.12: a program alternating a stdout line and a stderr line three times produced all three stderr lines before all three stdout lines under `> combined.log 2>&1`, and strictly alternating lines under `PYTHONUNBUFFERED=1`. `stdbuf -oL` did not change it, because the interpreter manages its own buffers rather than libc's.
cost of missing
A cause is assigned to the wrong step, and the fix is applied to whatever the reordering happened to place first.
mitigation
Timestamp at the point of emission, so ordering does not depend on arrival, and keep the two streams separate when their relative order carries meaning.
generalises to
Any merge of independently buffered sources into one ordered view: multi-process logs, distributed traces without synchronised clocks, tail -f across several files.
source
man7.org
NS-066 documentedstreams-split-by-redirection-order

Redirection order decides whether the log can contain errors at all

reads as
The service runs as `app 2>&1 > app.log` and app.log holds a clean sequence of startup lines with no errors. Conclusion drawn: the run was clean.
actually
Redirections are processed left to right. The bash manual gives this exact pair: `ls > dirlist 2>&1` sends both streams to the file, while `ls 2>&1 > dirlist` 'directs only the standard output to file dirlist, because the standard error was duplicated from the standard output before the standard output was redirected to dirlist'. Standard error went wherever standard output pointed beforehand, usually a terminal that no longer exists or a parent's discarded output.
blind because
The log is genuine, complete and correctly ordered for the stream it captured. Nothing in it can indicate that a second stream existed and went elsewhere, so a log with no errors and a log that cannot contain errors are the same file.
the check
Ask the running process where its descriptors point: `readlink /proc/$$/fd/1 /proc/$$/fd/2` from inside the redirected command. Observed on bash 5.2.21: under `./probe.sh 2>&1 > out1.log`, fd 1 pointed at out1.log while fd 2 pointed at the parent's output; under `./probe.sh > out2.log 2>&1` both pointed at out2.log. A script emitting one error line produced `grep -c ERROR` of 0 in the first case and 1 in the second.
cost of missing
Every diagnostic the program emits is discarded by the same arrangement that produces the record used to declare it healthy, and alerting built on that log's contents can never fire.
generalises to
Any capture configured to watch one channel while the interesting events use another: stderr against stdout, structured logs against panics, application logs against the supervisor's.
source
gnu.org
NS-067 documentedseverity-assigned-by-the-transport

A service's stdout is recorded at info priority whatever the line says

reads as
`journalctl -u app -p err` prints '-- No entries --'. Conclusion drawn: the service has logged no errors.
actually
systemd assigns the priority, not the text. SyslogLevel= is 'the default syslog log level to use when logging to the logging system or the kernel log buffer', it 'only applies to log messages written to stdout or stderr', and it 'Defaults to info'. Unless a line carries an explicit angle-bracket level prefix, every line the process prints is stored at priority 6, including the ones whose text reads ERROR.
blind because
The filter and the store agree. Priority is metadata attached at ingestion, so a severity filter reports the transport's opinion rather than the application's.
the check
Look at the priority distribution instead of the filtered view: `journalctl -u UNIT -o json | jq -r .PRIORITY | sort | uniq -c`. Observed on a unit logging 43,061 records over three weeks: every one at PRIORITY 6 (informational), while a plain-text search of the same range found 14 lines containing 'error'. `journalctl -u UNIT -p err` reported '-- No entries --' throughout.
cost of missing
Severity-based alerting and triage are silently disabled for every service that logs to stdout without prefixes, which is most of them, and the absence of high-priority records is read as the absence of high-priority events.
mitigation
Emit the angle-bracket level prefix from the application, or set SyslogLevel= on the unit; SyslogLevelPrefix= controls whether such prefixes are honoured.
generalises to
Every field assigned by a collector rather than by the source: levels inferred by a log shipper, statuses rewritten by a proxy, timestamps stamped at ingestion.
source
freedesktop.org
NS-068 documentedevidence-discarded-at-reboot

A journal with no persistent directory discards its evidence at reboot

reads as
After a crash and a restart, `journalctl -u app --since '2 days ago'` returns nothing. Conclusion drawn: the service logged nothing before it died, so the failure was abrupt.
actually
journald's Storage= defaults to auto, and 'auto behaves like persistent if the /var/log/journal directory exists, and volatile otherwise (the existence of the directory controls the storage mode)'. Under volatile storage the journal lives below /run and does not survive a reboot. The pre-crash records existed, and the restart performed to recover deleted them.
blind because
An empty query result has one shape. 'Nothing was logged', 'nothing matched the filter' and 'the storage that held it no longer exists' all render as no output and a zero exit.
the check
Establish whether history survives before drawing conclusions from its absence: `ls -d /var/log/journal 2>/dev/null; journalctl --list-boots`. Observed on this host: /var/log/journal exists and holds 566 MB, and --list-boots lists two boots reaching back five weeks, so an empty result here is a fact about the service. On a host without that directory the same commands print nothing and a single boot, and no empty result carries information.
cost of missing
The post-mortem proceeds from the premise that the process died silently, and the reboot performed to restore service is the act that destroyed the evidence for any other explanation.
mitigation
Create /var/log/journal and restart systemd-journald, or set Storage=persistent explicitly, before the next incident rather than after it.
generalises to
Every store whose retention is shorter than the investigation: ring buffers, in-memory metrics, container logs removed with the container, tmpfs working directories.
source
freedesktop.org
NS-069 observedself-reported-identity

Traffic classified by user-agent counts what clients claim to be

reads as
An access log shows 57% of requests from browsers. Conclusion drawn: most visitors are people, and the site is reaching a human audience.
actually
The User-Agent header is set by the client and asserted, never verified. A single scanner sending a stock Windows Chrome string produced a large share of that bucket; its requests were for /contact, /about-us, /pricing, /team and /support — pages this site has never had. Real browsers and anything imitating one are indistinguishable by header alone.
blind because
The field being counted is supplied by the party being measured. Every row is internally consistent and none of them is evidence.
the check
Group requests by client address and compare what each one asked for against what exists. A client whose requests are mostly 404s for pages the site has never published is enumerating, whatever it calls itself. Corroborate with an independent signal the client does not control, such as whether it also fetched the page's own subresources.
cost of missing
Audience is misread in the direction that flatters. Content decisions get made for readers who were never there, and genuine machine traffic is filed as human.
mitigation
Treat the user-agent as one weak signal among several. Behaviour — which paths, in what order, with which subresources — is set by the client too, but it is far more expensive to fake convincingly.
generalises to
Any metric derived from a field the measured party supplies: referrers, self-reported versions, declared content types, client-side analytics events.
NS-088 documentedinterleaved-past-the-atomic-limit

Records longer than a pipe's atomic limit are spliced into one another

reads as
`grep 'request_id=abc123' app.log` returns nothing, and the file around that period is full of well-formed lines. Conclusion drawn: that request never reached this service.
actually
pipe(7): POSIX.1 says that writes of less than PIPE_BUF bytes must be atomic, the output data being written to the pipe as a contiguous sequence, while writes of more than PIPE_BUF bytes may be nonatomic, and the kernel may interleave the data with data written by other processes. On Linux PIPE_BUF is 4096 bytes. Several workers writing to one pipe, which is what a container's stdout, a `tee` and most log shippers are, produce records cut open with another worker's record inserted into the gap. The result still ends in a newline, so it is still a line.
blind because
A log reader sees lines, and a spliced line is a line: it has a beginning, an end and plausible contents. The pattern that would have matched now straddles a boundary that did not exist when the record was written, and the line count is unchanged.
the check
Validate each line against the format the writer emits and count the failures, rather than counting lines. Observed on Linux 6.8 with four writers into one pipe behind a deliberately slow reader: at 4090-byte records, 800 lines and 0 malformed; at 5000-byte records, 800 lines and 21 malformed; at 20000-byte records, 800 lines and 195 malformed, one of which opened with `BEGIN-B-0010` and contained an entire `BEGIN-A-0000 ... END-A-0000` record inside it. The line count was 800 in every run.
cost of missing
Requests appear never to have happened, error rates read low, and the records that would contradict both are present in the file in a form no query will match.
mitigation
Keep each record under PIPE_BUF, or give each writer its own descriptor opened O_APPEND onto a regular file, where appends do not interleave regardless of size.
generalises to
Any shared append-only channel with an atomicity limit: pipes, datagram sockets, unlocked file writes, records assembled from several write calls.
source
man7.org
NS-089 documentedwindow-in-a-different-time-frame

A log search returns nothing because the window and the timestamps are in different zones

reads as
`journalctl -u app --since '2026-08-24 00:20:00'` prints `-- No entries --` for a window that covers the incident. Conclusion drawn: the service logged nothing then, so it was not running or was never reached.
actually
journalctl interprets --since and --until in the local time zone, and systemd.time(7) states that on display systemd will format timestamps in the local timezone. When the window is copied from a source in another zone, a UTC dashboard, a cloud console, an API response or a colleague on another continent, the query addresses a moment hours away from the one intended. The entries exist and sit outside the range.
blind because
An empty result set has one shape. Nothing separates 'no entries in this window' from 'the window was somewhere else', and the timestamps that would reveal the offset are precisely the ones the filter excluded.
the check
Ask for the entries in an unambiguous frame and see whether they exist at all before filtering: `journalctl -u app -n 5 --utc -o short-iso`. Observed on this box (Etc/UTC) against a single `logger -t vftz` entry: plain `journalctl -t vftz` displayed it as `Aug 24 00:24:27`, while `TZ=America/New_York journalctl -t vftz` displayed the same entry as `Aug 23 20:24:27`, a different calendar day. Passing a window taken from the UTC clock while TZ was America/New_York returned `-- No entries --` for a record written seconds earlier.
cost of missing
The investigation concludes the service was silent during the incident and moves upstream, while the evidence sits in the same file a few hours away.
mitigation
Pin both ends of every correlation to one frame: query with --utc and read with -o short-iso, or attach an explicit offset to every timestamp that crosses a system boundary.
generalises to
Every filter expressed in units the store does not share: time zones, seconds against milliseconds, inclusive against exclusive bounds, severities named differently by the writer and the query.
source
freedesktop.org
NS-090 observedcrawled-is-not-indexed

Crawler hits in an access log are not evidence that a page is indexed

reads as
The access log shows repeated fetches from Googlebot, Bingbot and other declared crawlers, and the sitemap was accepted. Conclusion drawn: the pages are in the index and the site is discoverable.
actually
Crawling, indexing and ranking are three separate stages. A crawler fetching a URL records only that it was retrieved; the page may then be excluded, deduplicated against similar content, or held in a queue for days. A site can be fetched hundreds of times and return no results for a search of its own exact title.
blind because
The access log is written by the origin and can only record requests that reached it. It has no field for what the requester did afterwards, and no stage of indexing produces a request back to the server.
the check
Query the index itself rather than reading the log: search for an exact phrase unique to the page, in quotes, and separately run a `site:` query for the domain. Both return nothing while the page is merely crawled. For a property you control, the index-coverage report in Google Search Console or Bing Webmaster Tools states the stage per URL.
cost of missing
Distribution work is reported as finished on the strength of crawler traffic, and the weeks in which the pages are fetched but unfindable pass unnoticed. Effort moves on to new content while nothing published so far can be reached by search.
mitigation
Treat submission and crawling as inputs, not outcomes. The observable outcome is a result page containing your URL.
generalises to
Any pipeline whose early stages report back to you and whose later stages do not: submitted-versus-accepted, queued-versus-delivered, uploaded-versus-published, deployed-versus-serving.

Plain text: /log-output.txt · all instruments