Server logs: structured JSON, verbosity and log rotation

conceptThe concept

Since 4.4 every line in mongod.log is a JSON document:

• t: timestamp, s: severity (F fatal, E error, W warning, I info, D1 to D5 debug), c: component (COMMAND, NETWORK, REPL, STORAGE, ACCESS, CONTROL and others).
• id: a stable numeric identifier for the message. Search and alert on the id, not the wording; the wording can change between releases. Slow operations are id 51803, "Slow query".
• ctx: the thread or connection (conn1234), msg: the message, attr: structured details such as ns, durationMillis, planSummary, keysExamined, docsExamined.

What gets logged. At the default verbosity 0, an operation is logged when it takes longer than slowms (100 ms by default, set with db.setProfilingLevel(level, { slowms }) or operationProfiling.slowOpThresholdMs). The profiler level does not matter: level 0 still logs slow operations. slowOpSampleRate logs only a fraction of them on very busy servers.

Verbosity is set globally and per component, from 0 (info) to 5 (very chatty debug); -1 means "inherit from the parent". db.setLogLevel(2, "replication.heartbeats") raises one component at runtime; db.getLogComponents() shows the whole tree. With the command component at 1 or higher, every operation is logged regardless of duration, so raise it briefly and lower it again.

The server also keeps the most recent 1,024 lines in memory. db.adminCommand({ getLog: "global" }) returns them as JSON strings, and show log startupWarnings prints the warnings from startup, which is where problems like low ulimits or an unsupported filesystem first appear.

whyWhy it matters

Logs are the first place to look after an incident and the only record of slow queries when the profiler is off. Structured lines make them easy to filter, aggregate and ship to a log platform, but only if you know the fields and keep verbosity and rotation under control. A debug level left on for a week can fill the log volume and stop the server.

Use caseReal-world scenario

At 14:05 the checkout API slowed down for ten minutes. The on-call DBA filters mongod.log for id 51803 between 14:00 and 14:20, groups by attr.ns and attr.planSummary, and finds hundreds of COLLSCANs on orders from one appName: a new report that filtered on an unindexed field. The fix is an index and a meeting with the report owner; the evidence came from the log.

Try itExamples

Run and edit these in the interactive lesson.

show logs
show log startupWarnings

db.orders.find({ "shipping.city": "Pune" }).toArray().length
db.adminCommand({ getLog: "global" }).log
  .map(JSON.parse)
  .filter(l => l.id === 51803)
  .map(l => ({ ns: l.attr.ns, ms: l.attr.durationMillis, plan: l.attr.planSummary, docsExamined: l.attr.docsExamined, nreturned: l.attr.nreturned }))

db.setProfilingLevel(0, { slowms: 50 })
db.events.find({ type: "purchase" }).toArray().length
const slow = db.adminCommand({ getLog: "global" }).log.map(JSON.parse).filter(l => l.id === 51803)
slow.map(l => l.attr.ns + " " + l.attr.durationMillis + " ms")
db.setProfilingLevel(0, { slowms: 100 })

db.setLogLevel(1, "command")
db.products.find({ sku: "SKU-0001" }).toArray().length
const fast = db.adminCommand({ getLog: "global" }).log.map(JSON.parse).filter(l => l.id === 51803 && l.attr.ns === "shop.products")
db.setLogLevel(-1, "command")
fast.map(l => l.attr.durationMillis + " ms, " + l.attr.planSummary)

db.adminCommand({ setParameter: 1, logComponentVerbosity: { replication: { heartbeats: { verbosity: 2 } } } })
db.adminCommand({ getParameter: 1, logComponentVerbosity: 1 }).logComponentVerbosity.replication
db.setLogLevel(-1, "replication.heartbeats")

db.runCommand({ getLog: "global" })

db.adminCommand({ logRotate: 1 })

# /etc/mongod.conf
systemLog:
  destination: file
  path: /var/log/mongodb/mongod.log
  logAppend: true
  logRotate: reopen          # logrotate moves the file, mongod reopens the path
operationProfiling:
  mode: off
  slowOpThresholdMs: 100
  slowOpSampleRate: 1.0

# /etc/logrotate.d/mongod
/var/log/mongodb/mongod.log {
  daily
  rotate 14
  compress
  delaycompress
  missingok
  notifempty
  sharedscripts
  postrotate
    /bin/kill -SIGUSR1 $(pidof mongod) 2>/dev/null || true
  endscript
}

# slow queries: namespace, duration, plan
jq -c 'select(.id == 51803) | {t: .t["$date"], ns: .attr.ns, ms: .attr.durationMillis, plan: .attr.planSummary, docs: .attr.docsExamined}' /var/log/mongodb/mongod.log

# which namespaces and plans are slow most often
jq -r 'select(.id == 51803) | [.attr.ns, .attr.planSummary] | @tsv' /var/log/mongodb/mongod.log | sort | uniq -c | sort -rn | head

# errors and fatals only
jq -c 'select(.s == "E" or .s == "F") | {t: .t["$date"], c, id, msg}' /var/log/mongodb/mongod.log

internalsUnder the hood

Log lines are written synchronously by the thread that produced them, so extremely high verbosity costs real latency, not only disk. Long attributes are truncated (maxLogSizeKB, 10 KB by default), which is why very large queries appear with a truncated marker.

systemLog.logRotate decides what logRotate or SIGUSR1 does: rename (the default) renames the current file with a timestamp and opens a new one; reopen closes and reopens the same path, which is what Linux logrotate expects after it has moved the file (and requires logAppend: true).

Avoid / preferDo this, not that

grep "Slow query" /var/log/mongodb/mongod.log | head

jq -c 'select(.id == 51803) | {ns: .attr.ns, ms: .attr.durationMillis, plan: .attr.planSummary}' /var/log/mongodb/mongod.log

db.adminCommand({ setParameter: 1, logLevel: 3 })   // and then forget

db.setLogLevel(2, "replication.election")
// reproduce, read the log
db.setLogLevel(-1, "replication.election")

PitfallsCommon mistakes

• Searching logs for message text instead of the numeric id, then missing lines after an upgrade reworded them.
• Setting the global log level to 2 or more to "see what is happening" and leaving it on until the disk fills.
• Using logRotate: rename together with logrotate, so both rename the file and the server keeps writing to a moved file.
• Treating profiler level 0 as "slow query logging off". slowms still applies to the log.

LimitsWhen not to use it

Logs are for events and slow operations, not for metrics. Do not raise verbosity to measure throughput or cache pressure; use serverStatus, FTDC or PMM, which sample continuously at almost no cost. For a full record of who did what, use auditing rather than a high log level.

SecuritySecurity notes

Slow query lines include the filter, so they can contain email addresses, names or tokens. Restrict the log directory to the mongod user, ship logs over TLS to a platform with access control, and consider security.redactClientLogData (MongoDB Enterprise and Percona Server for MongoDB), which replaces values in log messages with "###".

ChallengeTry it yourself

db.setProfilingLevel(0, { slowms: 20 })
db.reviews.find({ title: "Exactly as described" }).toArray().length
const lines = db.adminCommand({ getLog: "global" }).log.map(JSON.parse)
const out = lines.filter(l => l.id === 51803 && l.attr.ns === "shop.reviews").map(l => ({ plan: l.attr.planSummary, docsExamined: l.attr.docsExamined }))
db.setProfilingLevel(0, { slowms: 100 })
out

InterviewQuestions you should be able to answer

QuizCheck your understanding

5 questions with instant feedback in the interactive lesson; a wrong answer goes into your review deck.