Python Observability

Logging from Cron and Batch Jobs

A scheduled job has a failure mode no service has: it can simply not happen, producing no output, no error and no evidence of any kind. Everything else about logging a job follows from working around that, and from the related fact that a job's records are read weeks later by somebody reconstructing what happened rather than live by somebody watching. This page covers the configuration, the run identifier, the bracket records and the absence alert. It is a task article under telemetry from serverless and batch Python, part of the Python telemetry pipelines and delivery section.

Four outcomes, and what each leaves behind Four outcomes of a scheduled job are compared by the records each produces. A successful run produces a start record and an end record with a success outcome and its counts, which is the easy case. A run that fails with an exception produces a start record, an error record with the traceback, and an end record with a failed outcome, which is also easy because the error is searchable. A run that is killed — out of memory, a node eviction, a timeout enforced by the scheduler — produces a start record and nothing else, so it is identifiable only as a start with no matching end. A run that never began produces nothing whatsoever: no start, no error, no trace, no metric. The conclusion drawn is that the third and fourth cases cannot be detected by searching for failures, and each needs its own check: unmatched starts for the third, and an expectation-based absence alert for the fourth. what each outcome leaves in the log succeeded start end · ok · counts easy failed start error + traceback end · failed searchable killed start nothing — no end record was ever written find unmatched starts never ran no records of any kind, in any signal only an expectation finds it searching for failures finds two of the four outcomes the other two are an unmatched start record and an absence, and each needs its own check
Half a job's failure modes leave no failure record. The start record and the absence alert are what cover them.

Prerequisites

pip install "python-json-logger>=2.0.7,<4.0.0"

# under a traditional crontab, redirect where something collects it
*/15 * * * * /usr/bin/python3 /opt/jobs/reconcile.py >> /var/log/app/reconcile.jsonl 2>&1

Implementation

Step 1 — Configure logging as the very first thing. A job that configures logging after importing its dependencies loses any record of a failure during those imports, which is a real and annoying category — a missing package, a bad configuration file, a database driver that cannot load. Putting the configuration at the top of the entry point, before anything else, means even that failure produces a parseable record.

#!/usr/bin/env python3
# reconcile.py
import logging
import os
import sys
import time
import uuid

from pythonjsonlogger import jsonlogger

RUN_ID = os.environ.get("RUN_ID") or uuid.uuid4().hex
JOB = os.environ.get("JOB_NAME", "nightly-reconciliation")


class RunContextFilter(logging.Filter):
    """Stamp every record with the job and run, without touching call sites."""

    def filter(self, record: logging.LogRecord) -> bool:
        record.job = JOB
        record.run_id = RUN_ID
        return True


handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(jsonlogger.JsonFormatter(
    "%(asctime)s %(levelname)s %(name)s %(message)s %(job)s %(run_id)s"))
handler.addFilter(RunContextFilter())
logging.basicConfig(level=logging.INFO, handlers=[handler], force=True)

log = logging.getLogger("reconcile")

Step 2 — Bracket the run with a start and an end record. The pair is what makes an incomplete run findable. A job killed by the scheduler, evicted from a node or terminated for memory produces a start with no end, and that unmatched start is the only evidence it ever ran. Searching for failures will never find it, because it did not fail — it stopped.

def main() -> int:
    started = time.monotonic()
    log.info("job started", extra={"phase": "start"})
    try:
        rows = load_rows()
        cleaned, rejected = transform(rows)
        written = write(cleaned)
    except Exception:
        log.exception("job failed", extra={
            "phase": "end", "outcome": "failed",
            "duration_s": round(time.monotonic() - started, 3)})
        return 1

    log.info("job finished", extra={
        "phase": "end",
        "outcome": "partial" if rejected else "ok",
        "rows_read": len(rows),
        "rows_written": written,
        "rows_rejected": len(rejected),
        "duration_s": round(time.monotonic() - started, 3),
    })
    return 0

Expected Output: two records per run, each carrying the run identifier that links them.

{"asctime": "2026-09-18T02:00:01.104Z", "levelname": "INFO", "message": "job started", "job": "nightly-reconciliation", "run_id": "0d41f2a8c9b74e1f", "phase": "start"}
{"asctime": "2026-09-18T02:00:42.312Z", "levelname": "INFO", "message": "job finished", "job": "nightly-reconciliation", "run_id": "0d41f2a8c9b74e1f", "phase": "end", "outcome": "partial", "rows_read": 100000, "rows_written": 99842, "rows_rejected": 158, "duration_s": 41.208}

Step 3 — Record the exit code separately from the exception. A Python process can exit non-zero without raising anything the interpreter saw: a call to sys.exit, a signal, a segmentation fault in a native extension. Capturing the exit status in the wrapper that launched the job, and logging it there, covers the cases the application cannot.

#!/bin/sh
# run-job.sh — the wrapper that records what Python could not
RUN_ID=$(cat /proc/sys/kernel/random/uuid)
export RUN_ID JOB_NAME=nightly-reconciliation

python3 /opt/jobs/reconcile.py
STATUS=$?

printf '{"job":"%s","run_id":"%s","phase":"exit","exit_code":%d}\n' \
  "$JOB_NAME" "$RUN_ID" "$STATUS"
exit $STATUS

Step 4 — Keep the record count proportional to the run, not to the data. A job processing a hundred thousand rows should produce a handful of records. The instinct to log each item is strong, particularly during development, and it produces a volume that dominates a fleet's log bill for data nobody reads. Log the phases, the counts and the exceptional items; the rest belongs in the job's own output.

Step 5 — Alert on the absence of a completion record. This is the check nothing else covers. It needs an expectation — this job should complete at least once every ninety minutes — and it must be based on completion rather than start, since a job that starts and hangs is indistinguishable from a healthy one otherwise.

# nothing has completed for this job in longer than its schedule allows
time() - max by (job) (job_last_completion_timestamp_seconds{job="nightly-reconciliation"}) > 5400

Step 6 — Make overlapping runs distinguishable. A job whose runtime occasionally exceeds its interval will have two instances running at once, and without a run identifier their records interleave into something that cannot be read. The identifier makes each run's output recoverable; a lock that prevents the overlap is usually the better fix, but the identifier is what makes the problem visible in the first place.

Two runs at once, read two ways A job scheduled every fifteen minutes occasionally takes twenty, so two runs overlap. Without a run identifier the log shows an interleaved sequence of phase records from both runs, in which a start is followed by a second start, then an end, then another end, and it is impossible to tell which end belongs to which start or to attribute the row counts correctly. With a run identifier stamped on every record, the same interleaved sequence separates trivially: filtering by one identifier gives one run's records in order, and the overlap itself becomes visible as two identifiers active at once, which is the signal that the job needs either a lock or a longer interval. a 20-minute job on a 15-minute schedule no run identifier start start end · ok end · failed which end belongs to which start? the counts cannot be attributed at all run identifier on every record start · 0d41 start · 7b92 end · 0d41 end · 7b92 filter by identifier and each run reads in order the overlap itself becomes visible: two identifiers active at once which is the signal that the job needs a lock or a longer interval — a problem that was invisible above
Overlapping runs are common and usually unnoticed. The run identifier both untangles the records and reveals that the overlap is happening.

Designing for the reader six weeks later

A service's logs are read live, by somebody watching a dashboard. A job's logs are read weeks later by somebody reconstructing what happened, often without any context about what the job does. That difference should shape what gets logged.

Say what the run intended to do, not just what it did. A record at start naming the input — the date range, the source table, the file being processed — costs one field and answers the first question every later reader has. Without it, a run that processed forty thousand rows instead of the usual hundred thousand is a mystery; with it, the answer is often visible immediately because the input was smaller.

Record the counts even when nothing is wrong. The value of a successful run's numbers is entirely comparative: the run that processed forty thousand rows is identifiable only against the ninety-nine thousand of every previous night. Logging counts only on failure removes exactly the baseline that makes the failure interpretable.

Log the phase boundaries. A job that takes forty seconds normally and eleven minutes tonight has one phase responsible, and phase records localise it without any tracing at all. Three or four phase records per run is the right granularity — enough to answer where the time went, few enough to read.

Avoid logging the same fact twice in different shapes. A job that logs "processing batch 41 of 200" every batch, and then a summary, has produced two hundred records where one would do and made the summary harder to find. If progress logging is genuinely wanted for long runs, emit it on a time interval rather than per batch, so its volume is bounded by duration rather than by data size.

The records every job run should write A table of the log records every batch job run should emit and why. A start record with a run identifier, the job name and its parameters, so one run can be isolated. Periodic progress records with items processed so far, so a stalled run is visible. A summary record at the end with counts of items processed, skipped and failed, and the duration. A failure record with the exception and the run identifier, even when the job exits non-zero. The note says the summary record is the one dashboards and alerts should read, since its absence means the run never finished. record contains so that start run id, job, parameters one run can be isolated progress items processed so far a stall is visible summary processed, skipped, failed, time dashboards read one line failure exception, run id the cause is attached alert on the missing summary — its absence means the run never finished
A start, progress, a summary and any failure, all carrying the run identifier, make every run reconstructable.

Configuration options

Practice Value Why
Logging configured first line of the entry point covers import-time failures
Run identifier on every record isolates a run; reveals overlaps
Start record always an unmatched start finds killed runs
End record always, with outcome the only success signal
Counts on the end record comparison against previous runs
Per-item records never, beyond exceptions volume proportional to data
Exit code logged by the wrapper covers what Python cannot see
Absence alert on the completion timestamp the failure the job cannot report

Verification

Check that the records are complete and joinable, which is easiest to test by killing a run halfway.

# start a run and kill it, then look for the unmatched start
timeout 5 python3 /opt/jobs/reconcile.py >> /tmp/run.jsonl 2>&1
python3 - <<'PY'
import json, collections
phases = collections.defaultdict(set)
for line in open("/tmp/run.jsonl"):
    rec = json.loads(line)
    phases[rec["run_id"]].add(rec.get("phase"))
for run_id, seen in phases.items():
    if "end" not in seen:
        print(f"incomplete run: {run_id}")
PY

Expected Output: the killed run identified by the absence of its end record.

incomplete run: 0d41f2a8c9b74e1f

That query, run continuously against the log store rather than a file, is the check that catches every killed run — and it is not a check anybody writes unless the start record exists.

Common mistakes

Logging configured after the imports. Error signature: a job that fails on a missing dependency and produces an unstructured traceback nothing parses. Root cause: the formatter installed too late. Remediation: configure at the top of the entry point, before importing the application's own modules.

No start record. Error signature: killed runs indistinguishable from runs that never happened. Root cause: only the outcome is logged. Remediation: bracket every run, and query for unmatched starts.

One record per processed item. Error signature: a job dominating the fleet's log volume. Root cause: instrumenting the loop. Remediation: counts on the end record; per-item records only for exceptions.

No run identifier. Error signature: interleaved records from overlapping runs that cannot be separated. Root cause: nothing distinguishing one execution from another. Remediation: generate one at start and stamp every record with a filter, as in step 1.

Alerting only on errors. Error signature: a job that has not run for three weeks and nobody noticed. Root cause: monitoring that requires the job to produce something. Remediation: an absence alert on the age of the last completion record.

Output going nowhere. Error signature: perfect records that never reach the store. Root cause: a traditional scheduler capturing output into a mail spool or discarding it. Remediation: redirect to a collected path, or log through a handler that does not depend on the scheduler's capture.

Frequently Asked Questions

Why do my cron job logs not reach the log store?

Usually because the job writes to standard output and the scheduler captures it into a mail spool or a file nothing collects. Under a container scheduler the output is captured normally; under a traditional crontab it is not, and redirecting to a collected path or logging through a handler is required.

How do I find one run's records among a month of them?

A run identifier stamped on every record, generated once at start. Without it, isolating a run means guessing at time boundaries, which is unreliable for jobs whose duration varies and impossible for overlapping runs.

What should a job log at all?

A start record, an end record with the outcome and the counts, one record per phase, and one per genuinely exceptional item. Not one per processed row: a job handling a hundred thousand rows should produce single-digit numbers of records unless something is wrong.

How do I detect a job that did not run?

By alerting on the age of the most recent completion record, per job. Nothing the job itself does can report its own absence, so the check has to live in the monitoring system and be based on an expectation of when a run should have happened.

Related Guides