ehsan.blog
~/blog/log-level-rule-order-silently-decides-whether-your-filter-works — zsh
cat log-level-rule-order-silently-decides-whether-your-filter-works.md

My debug log rule did nothing, and the reason was the order of the commas

·8 min read

There is a bug in checkout. You want debug logs from checkout and nothing else, because your database layer is noisy enough to bury the one line you actually need.

So you set an environment variable and restart:

bash
LOG_LEVEL=debug:checkout,warn:db:*,info:*

Read it out loud and it sounds exactly right. “Debug for checkout. Warnings for the database. Info for everything else.”

I set that, restarted, and got zero debug lines from checkout.

Nothing was misspelled. Nothing threw an error. The rule was simply being thrown away, and the thing that threw it away was the last five characters of the line.

Here is what is actually happening, measured against the real code.

The setup, in plain words

A few logging libraries let you set log levels per feature instead of one level for the whole app. In @developerehsan/nextjs-logger you tag a logger with a name:

ts
import { log } from '@developerehsan/nextjs-logger'

const checkoutLog = log.child('checkout')
checkoutLog.debug('cart totals recalculated', { itemCount, subtotal })

That name is called a namespace. Then LOG_LEVEL is a comma-separated list of rules, each one shaped like level:namespace-pattern:

plaintext
debug:checkout      → debug and above, for the checkout namespace
warn:db:*           → warn and above, for anything starting with "db:"
info:*              → info and above, for everything

This borrows its shape from the well-known debug package on purpose, so the syntax feels familiar. But it also borrows something people forget about that package, and that is the whole problem.

What actually decides which rule wins

Multiple rules can match the same namespace. checkout is matched by debug:checkout. It is also matched by info:*, because * means “everything”.

So which one applies?

The instinct is “the more specific rule wins”checkout is more precise than *, so it should beat it. That is how CSS works, roughly. That is how most people’s mental model starts.

That is not what happens. The real rule is:

The last rule that matches wins.

Not the most specific. Not the strictest. The one furthest to the right.

Here is the actual loop that decides it, from the library’s compiled level-filter module:

js
let resolved = fallback
for (const rule of rules) {
  if (rule.test(key)) resolved = rule.level
}

It walks every rule, start to finish, and every rule that matches overwrites whatever the previous one decided. There is no ranking, no specificity score, no early exit. The last writer wins.

Now go back and look at my line again:

bash
LOG_LEVEL=debug:checkout,warn:db:*,info:*

info:* is at the end. * matches everything — including checkout. So for the checkout namespace, debug:checkout sets the level to debug, and then info:* immediately overwrites it back to info. Debug is below info, so debug lines get dropped.

The same thing happens to warn:db:*. The info:* at the end quietly erases both of the rules I actually cared about. All three rules parsed fine. Two of them just never got to matter.

Measuring it, instead of trusting me

You do not have to take my word for this. Both functions involved are exported from the package, so you can check it in about ten lines. This is exactly the script I ran:

js
import { parseLevelSpec, isLevelEnabled } from '@developerehsan/nextjs-logger'

function show(spec) {
  const rules = parseLevelSpec(spec)
  console.log(`LOG_LEVEL=${spec}`)
  for (const ns of ['checkout', 'checkout:payment', 'db:pool']) {
    const on = isLevelEnabled('debug', ns, rules, 'info')
    console.log(`   debug from "${ns}" -> ${on ? 'SHOWS UP' : 'hidden'}`)
  }
  console.log()
}

show('debug:checkout,warn:db:*,info:*')
show('info:*,warn:db:*,debug:checkout')

Two specs. The same three rules in both. Only the order is different. Here is the real output:

plaintext
LOG_LEVEL=debug:checkout,warn:db:*,info:*
   debug from "checkout" -> hidden
   debug from "checkout:payment" -> hidden
   debug from "db:pool" -> hidden

LOG_LEVEL=info:*,warn:db:*,debug:checkout
   debug from "checkout" -> SHOWS UP
   debug from "checkout:payment" -> SHOWS UP
   debug from "db:pool" -> hidden

Same rules, opposite results. Moving one item from the front of the list to the back is the entire difference between “I can see my bug” and “I am staring at an empty terminal wondering if logging is broken.”

That fourth argument, 'info', is the fallback — the level used when no rule matches at all.

The fix: general first, exceptions last

Once you know it is last-match-wins, the correct way to write these becomes obvious. Write it the way you would say it in English:

“Info everywhere. Except the database, which is warn. Except checkout, which is debug.”

Broadest rule first. Each exception after the thing it is an exception to:

bash
LOG_LEVEL=info:*,warn:db:*,debug:checkout

That is the shape to memorize. Put your * rule first, never last. If a config line ends in info:*, every rule in front of it is decoration.

It reads like a paragraph that gets more specific as you go, which is a nicer property than it sounds like — you can hand this string to a teammate mid-incident and they can read it left to right without knowing any of this.

Three more things I only found by testing

Once I had the test script open, I kept poking. Three behaviors here will bite you eventually, and none of them are guessable.

1. A * pattern does not match its own parent

warn:db:* sounds like “the db area”. It is not quite. When a pattern contains *, it is turned into a real regular expression anchored at both ends — db:* becomes ^db:.*$. That string requires a literal colon after db.

js
const rules = parseLevelSpec('info:*,warn:db:*')
for (const ns of ['db', 'db:pool', 'db:pool:acquire']) {
  console.log(`info from "${ns}" -> ${isLevelEnabled('info', ns, rules, 'info') ? 'SHOWS UP' : 'hidden'}`)
}
plaintext
info from "db" -> SHOWS UP
info from "db:pool" -> hidden
info from "db:pool:acquire" -> hidden

db:pool:acquire is caught, which is good — the .* happily crosses more colons, so one rule covers a whole tree however deep it grows. But plain db slips straight through and lands on the default. If you have a logger at the bare top of a feature, db:* will not cover it.

The good news is that a pattern without a * behaves the way you hoped. It matches itself and its children:

js
return (namespace) => namespace === pattern || namespace.startsWith(`${pattern}:`)

So debug:checkout already covers checkout, checkout:payment, and checkout:refund. You almost never need the star. Written plainly, checkout is both shorter and more correct than checkout*.

2. A leading - beats everything, including fatal

A rule can start with a dash instead of a level. That means “nothing from here, ever”:

js
const rules = parseLevelSpec('info:*,-checkout:polling')
console.log('fatal from "checkout:polling" ->', isLevelEnabled('fatal', 'checkout:polling', rules, 'info') ? 'SHOWS UP' : 'hidden')
console.log('fatal from "checkout" ->', isLevelEnabled('fatal', 'checkout', rules, 'info') ? 'SHOWS UP' : 'hidden')
plaintext
fatal from "checkout:polling" -> hidden
fatal from "checkout" -> SHOWS UP

Note what that first line means: fatal was suppressed. This is not “set the bar very high”, it is an off switch. Internally the rule stores a level of null, and null short-circuits before any level comparison happens.

Worth being careful with. Silencing a namespace that might one day log something genuinely alarming means you will not hear about it. Reach for a high level like warn:noisy-thing when you want quiet; save - for things that are structurally incapable of telling you anything useful.

And because it is just another rule, it obeys the same ordering law — a - rule placed before an info:* gets overwritten like anything else.

3. A typo does not crash anything, which cuts both ways

If you write dbeug:checkout, nothing explodes. The parser checks each rule against the five valid level names and quietly drops anything that does not fit:

js
const level = token.slice(0, separator).trim()
const pattern = token.slice(separator + 1).trim()
if (!VALID_LEVELS.has(level) || !pattern) continue

I think that is the right call. A logging library refusing to boot because of a misspelled environment variable would be a genuinely worse day than the one you are already having.

But it does mean a typo looks identical to a rule that is being overwritten. Both give you silence. Both leave you doubting your setup rather than your spelling. When your filter does not work, the two things to check, in this order, are: is my * rule last, and did I spell the level right.

One last piece of good news: if every rule fails to parse, the library falls back to its normal default level rather than logging nothing. You lose your filtering, not your logs.

The part I’d want someone to tell me

This is not really a story about one logging library. Last-match-wins is what the debug package does, what .gitignore does, what shell PATH resolution does in reverse. It is a common and reasonable design, because the alternative — ranking patterns by specificity — has no honest answer for which of a:*:c and a:b:* is more specific.

The trap is that last-match-wins is invisible. A config file where rule order matters looks exactly like a config file where it doesn’t. You get no error, no warning, no hint — just a rule that silently does nothing, and a person assuming their logging is broken.

So the habit worth building is smaller than the lesson: when a config takes a list of patterns, find out what happens when two of them match the same thing, before you need it to work. It is one ten-line script. I ran mine after an hour of confusion. It would have been a much better hour if I had run it first.

If you want to check your own: the two functions in every snippet above, parseLevelSpec and isLevelEnabled, are exported from the package precisely so you can test a LOG_LEVEL string without deploying it. Paste your real production value in and see what it actually does.

ls ./related
cat ./comments

Comments are not configured yet. Enable GitHub Discussions and paste the giscus repo-id / category-id into src/consts.ts.