skip to content

With unittest's assertLogs and assertNoLogs, how do you test that a worker warns above its budget but not at it?

level: seniorimportance: should knowfreq 30%

answer

  1. One test proves nothing about a threshold
  2. Pin both sides of the comparison
  3. The silent case needs its own assertion
  4. Assert the level, not the wording
  5. Structured extra fields beat message text

basics

~10 s

Write both sides of the boundary: assertLogs(logger, level=logging.WARNING) around the budget+1 case, checking levelno and a structured field on the record, and assertNoLogs(logger, level=logging.WARNING) around the exactly-at-budget case.

solid answer

~40 s

An off-by-one in a threshold only shows up if the test pins both sides, so write two tests against the same logger. The positive one uses `with self.assertLogs("thumbs.batch", level=logging.WARNING) as captured:` at budget+1 and then asserts on the record, not the rendered line: `records[0].levelno == logging.WARNING` plus a value passed through `extra=` (say the measured milliseconds), so an edit to the message wording cannot break the test. The negative one uses `assertNoLogs("thumbs.batch", level=logging.WARNING)` — added in **Python 3.10** — at exactly the budget; without it, "no exception was raised" is not evidence of silence. Name the subsystem logger rather than the root: the root captures every library in the process, and `assertNoLogs` on it will fail on unrelated noise.

code

python · 28 lines
python
import logging
import unittest

log = logging.getLogger("thumbs.batch")
BUDGET_MS = 240  # the 92nd-percentile render budget


def render(batch, elapsed_ms):
    if elapsed_ms > BUDGET_MS:
        log.warning("batch %s over budget", batch, extra={"elapsed_ms": elapsed_ms})
    return batch


class BoundaryTest(unittest.TestCase):
    def test_one_over_budget_warns(self):
        with self.assertLogs("thumbs.batch", level=logging.WARNING) as captured:
            render("b-1", BUDGET_MS + 1)
        record = captured.records[0]
        self.assertEqual(record.levelno, logging.WARNING)
        self.assertEqual(record.elapsed_ms, 241)

    def test_exactly_at_budget_is_silent(self):
        with self.assertNoLogs("thumbs.batch", level=logging.WARNING):
            render("b-2", BUDGET_MS)


if __name__ == "__main__":
    unittest.main()

go deeper

for a junior

Remember that a threshold needs two tests, one either side, and that the quiet case is expressed with assertNoLogs, not by leaving the call unwrapped and hoping nothing happens.

for a middle

Explain why records[0].levelno and an extra= attribute make a better assertion than the rendered output line, and why the level argument must be stated when the code also emits INFO records.

for a senior

Show the diagnostic judgement: name the subsystem logger rather than the root, derive both cases from one budget constant, and state plainly that these assertions cover the call site and not the deployed logging configuration.

for a principal

Decide which log lines are a contract worth pinning in tests at all, and push for structured fields over prose so that operational messages can be reworded without breaking builds — and so alerting keys off data, not on regex over text.

### Why a boundary needs two assertions A threshold test that only exercises the failing side proves nothing about the comparison operator. `elapsed > BUDGET` and `elapsed >= BUDGET` both warn at budget+1; they differ only exactly *at* the budget. So the pair is the test: one case one unit over the line, asserted to warn, and one case on the line, asserted to be silent. Everything else in this question is about making those two assertions precise rather than incidentally true. Take a thumbnail-rendering worker whose 92nd-percentile budget is 240 ms and which is meant to warn only when a batch overruns it. ### The positive side ```python with self.assertLogs("thumbs.batch", level=logging.WARNING) as captured: render("b-1", 241) record = captured.records[0] self.assertEqual(record.levelno, logging.WARNING) self.assertEqual(record.elapsed_ms, 241) ``` Three deliberate choices here. **A named logger, not the root.** Passing no logger targets the root, which in a real process also carries every library's output; the assertion then passes for the wrong reason, and its `assertNoLogs` twin fails on noise you did not write. Naming `"thumbs.batch"` also still captures descendants, because a child's records propagate up to the ancestor's handler — so `"thumbs"` is the right target when several submodules may legitimately emit. **`level` stated explicitly.** The default is INFO, so an unqualified `assertLogs` would also capture a chatty info line and hand you the *wrong* record at index 0. Pinning WARNING makes `records[0]` mean what you think it means; asserting `len(records) == 1` is worth adding when the code path should say exactly one thing. **Assertions on the record.** `captured.output` renders through a fixed `"LEVEL:logger:message"` format, so comparing against it welds the test to the message's wording and to `%`-interpolation of its arguments. The record view is stable: `levelno` is the field a bug is most likely to change (a demoted warning that becomes a debug line is invisible to any text-only assertion), `getMessage()` performs the deferred interpolation when you genuinely want a substring, and anything passed through `extra={"elapsed_ms": ...}` lands as a plain attribute on the record — the cleanest way to assert on the *number* that crossed the threshold rather than on prose about it. ### The negative side ```python with self.assertNoLogs("thumbs.batch", level=logging.WARNING): render("b-2", 240) ``` `assertNoLogs` arrived in **Python 3.10**. It fails if any record at or above the level reaches that logger, and it yields `None` — there is nothing to bind with `as`. Note that it is not the inverse of the whole positive test: it is scoped to one logger and one level, so the worker may still log an INFO line at the boundary and the assertion holds. That is usually what you want; if it is not, drop the level to capture everything. The alternative some codebases still carry — wrapping `assertLogs` in `assertRaises(AssertionError)` to mean "nothing was logged" — works but reads as a trick and swallows any *other* assertion error from the body. Recognise it in old code; do not write it on 3.10 or later. ### What the block does to the logger, and what that means for the test's reach Inside either block the target logger is rewired: its handler list is replaced by a single capturing handler, its level is forced to the requested one, and propagation is switched off so the records do not also hit the root handlers and pollute the runner's output. All three are restored on exit, including on an exception. The consequence to state in an interview is a limitation: because the level is forced, these assertions test **the call site's behaviour, not the deployed logging configuration**. If production ships that logger at ERROR, the warning your test proves is emitted will never be seen by an operator. Configuration is a separate concern and needs a separate test — or a smoke check — rather than being smuggled into `assertLogs`. A second consequence is about isolation: because the handlers are swapped rather than added to, a fixture that installs a capturing handler of its own is bypassed inside the block, and because propagation is disabled, a record emitted in the block never reaches an outer `assertLogs` on an ancestor. Nesting captures on a logger and its parent does not do what it looks like it does. ### Making the pair readable Keep the two cases as two test methods rather than one method with both blocks: a failure then names which side of the boundary broke, and the negative case cannot be quietly shadowed by an exception from the positive one. Derive both inputs from the same named constant (`BUDGET_MS` and `BUDGET_MS + 1`) so that raising the budget moves both sides together and the test keeps testing the boundary rather than two frozen numbers.

  • Does passing `assertLogs` a level prove that the record would be visible in production?
    No. The block forces the logger's level and replaces its handlers for the duration, so it proves the call site emitted the record, not that the deployed configuration would let it through. Whether the logger is enabled at that level in production, and whether a handler is attached, is a configuration concern that needs its own check.
  • Why assert on a value passed through `extra=` rather than on the message text?
    Keys given in `extra=` become plain attributes on the `logging.LogRecord`, so the assertion reads the measured number directly and survives any rewording of the message. Asserting on the rendered text couples the test to the format string and to `%`-style interpolation, which makes harmless copy edits break the build.
  • What goes wrong if you target the root logger in the `assertNoLogs` half of the pair?
    The root receives everything that propagates from every logger in the process, including third-party libraries, so an unrelated warning fails the test and the failure looks like a regression in your worker. Target the subsystem logger by name; children still propagate up to it, so coverage is not lost.

saying these in an interview costs you the question

  • Testing only the side that warns
  • Treating no exception as proof of silence
  • Comparing against the formatted output line
  • Using the root logger for both assertions
  • Forgetting assertLogs defaults to INFO
  • Claiming assertLogs validates production log configuration

context