Marcos Paulo
230 lines
12 KiB
Plaintext
230 lines
12 KiB
Plaintext
h2. Overview
|
|
|
|
Which level to use for a log line in GFiber services.
|
|
|
|
Graylog storage is shared, so every INFO line written on a healthy run is paid for in retention days: the more a service logs, the shorter the window for grepping an incident that already happened. A service that logs too little is untriageable. This page is the line between the two.
|
|
|
|
Applies to all GFiber services. The 13 Go services log through {{mano.netcracker.com/go-logging/v3}}; the Java services follow the same levels with different API names.
|
|
|
|
Three things to know before choosing a level:
|
|
|
|
* {{LOG_LEVEL}} is {{INFO}} in every shipped Helm chart. Treat DEBUG as *not present in production*.
|
|
* Support starts from one identifier, usually an alarm id or a ticket id, and searches Graylog full text. A decision that never printed that identifier cannot be found.
|
|
* Batch sizes are not capped upstream. A line inside a loop scales with ONT or item count, not with request count.
|
|
|
|
h2. Levels
|
|
|
|
|| Level || Use for || Volume on a healthy run ||
|
|
| ERROR | Work was lost and a human must look. Carries the identifiers of the lost work. | rare, each one actionable |
|
|
| WARN | An item was dropped or degraded and the service continues. Carries identifiers when no result line will be written. | rare |
|
|
| INFO | Work received, work finished, one result per work item. | O(1) per request or batch, plus one line per item |
|
|
| DEBUG | Everything else: intermediate collections, per-object detail, payloads, filter internals. | unbounded |
|
|
| FATAL | Cannot start and serve. Terminates the process. | startup only |
|
|
|
|
h2. How to choose
|
|
|
|
Stop at the first yes.
|
|
|
|
# Work was lost and someone has to look at it. → *ERROR*
|
|
# An item was dropped or degraded, and the service keeps going. → *WARN*
|
|
# It is one of these four: work received, work finished, the result of one item, or a decision that ends an item and is not already in that item's result message. → *INFO*
|
|
# It fires more than once per item, or prints a collection, a struct or a body. → *DEBUG*
|
|
# Anything else. → *DEBUG*
|
|
|
|
{tip}
|
|
Unsure between two levels? Take the lower one. A line at DEBUG can be recovered with on-demand troubleshooting or promoted next release. Retention days spent on a line nobody reads cannot.
|
|
{tip}
|
|
|
|
h3. WARN or ERROR
|
|
|
|
The boundary that gets argued about most.
|
|
|
|
* *ERROR* means the service could not do what it was asked and no automatic mechanism will fix it. A human has to look.
|
|
* *WARN* means the service did not do something, but that outcome is defined and expected in operation: input was unusable, capacity was full, a business rule dropped the item.
|
|
|
|
The test: *if this fires two hundred times tonight, does someone need to be paged?* Yes is ERROR. No is WARN.
|
|
|
|
Two consequences worth stating, because both are commonly got wrong:
|
|
|
|
* A call that failed but *will be retried automatically* is not an ERROR on the attempt. The attempt is DEBUG. It becomes ERROR when the retries are exhausted and the work is actually lost.
|
|
* A validation rejection is never an ERROR, however loud it looks. The client sent something unusable and the service behaved correctly. That is WARN.
|
|
|
|
h3. FATAL
|
|
|
|
Startup only, and only when the process cannot serve at all: unreadable configuration, no database, a required dependency that will never appear. {{LogFatal}} terminates the process, so calling it on a request path turns one bad request into an outage. There is no case for FATAL after the service reports ready.
|
|
|
|
h2. Cases
|
|
|
|
h3. Work intake and results
|
|
|
|
|| Case || Level || Note ||
|
|
| Request, batch or message arrived | INFO | counts and the values that identify the scope, such as alarm names, severities, OLT, HUT; no payload and no id list |
|
|
| Batch finished | INFO if ok, ERROR otherwise | one summary line with in, out, duration and status, written from a defer registered before any recover so a panic still produces it |
|
|
| Result of one work item | INFO | one per item, with its identifier and outcome; this is the line support greps for, and the one line that must never be demoted |
|
|
| Payload of the work item | DEBUG | or behind on-demand troubleshooting |
|
|
| Decision that ends the item | INFO | only when it is not already visible in that item's result message |
|
|
| Intermediate lookup or filter result | DEBUG | log the count at INFO if it matters, the members at DEBUG |
|
|
| Anything inside a loop over domain objects | DEBUG | plus one count after the loop |
|
|
|
|
h3. Rejections and failures
|
|
|
|
|| Case || Level || Note ||
|
|
| Input malformed, null or failed validation | WARN | carry the identifiers that survived parsing, and the body size |
|
|
| Rejected for capacity or backpressure | WARN | one line per rejected request, never per item |
|
|
| No handler or policy matched the work | WARN | carry the identifiers, because no result line will be written |
|
|
| Upstream call failed, will be retried | DEBUG | the attempt is not yet a failure |
|
|
| Upstream call failed after retries | ERROR | carry the identifiers and the step that stopped |
|
|
| Some items succeeded, some failed | ERROR | on the summary line, with the split |
|
|
| Panic recovered | ERROR | log the recovered value and the stack, and keep serving |
|
|
|
|
h3. Service lifecycle
|
|
|
|
|| Case || Level || Note ||
|
|
| Started, listeners bound, dependencies resolved | INFO | a handful of lines, once per process |
|
|
| Effective configuration | DEBUG | never secrets, tokens or credentials |
|
|
| Graceful shutdown | INFO | |
|
|
| Cannot start at all | FATAL | the only place FATAL is allowed |
|
|
| Database connection established | INFO | once at startup; per query is DEBUG |
|
|
|
|
h3. Background work
|
|
|
|
|| Case || Level || Note ||
|
|
| Scheduled tick that found nothing to do | DEBUG | a tick every few seconds at INFO is one of the cheapest ways to burn retention |
|
|
| Scheduled tick that did work | INFO | one line with counts, not one per item |
|
|
| Kafka batch consumed | INFO | one summary per batch, same shape as an HTTP batch |
|
|
| One Kafka message processed | DEBUG | the per-item result line already covers what support needs |
|
|
| Message that cannot be parsed | ERROR | carry the message key and raise a metric; it will never parse, so it is lost work |
|
|
| Consumer rebalance or lag | none | leave it to the client library and to metrics |
|
|
|
|
h3. Keep out
|
|
|
|
|| Case || Level || Note ||
|
|
| Health, liveness and readiness probes | none on success | probe traffic is constant; log only a failing probe |
|
|
| Every outbound HTTP request and response | DEBUG | rates and durations belong in metrics |
|
|
| Upstream returned an empty result | DEBUG | unless it changes the outcome, and then it belongs in the item's result message |
|
|
| Third-party library output | set it explicitly | do not let a dependency inherit DEBUG in production |
|
|
| Secrets, tokens, passwords | never | at any level |
|
|
| ONT serial, account id, hostname | not at INFO | on high-volume paths; fine in a bounded projection or at DEBUG |
|
|
|
|
If a line has to be INFO and is still too frequent, *sample it*: log one in N with the count of what was skipped. Demoting it to DEBUG removes it from production entirely, which is usually not the intent.
|
|
|
|
h2. Rules
|
|
|
|
# No unbounded collection at INFO. The count belongs at INFO, the collection behind it at DEBUG.
|
|
# No INFO inside a loop over domain objects.
|
|
# Cap identifier lists at 50 entries followed by {{+N more}}.
|
|
# Always use the {{Ctx}} variant. {{LogInfo}} without {{Ctx}} drops {{request_id}} and every business identifier from the MDC, which makes the line impossible to attach to anything.
|
|
# Never log a full request or response body at INFO.
|
|
# Mint correlation ids at ingress, not deeper. An id created inside the handler that already needed it cannot join the lines written before that point.
|
|
# No secrets, tokens or customer PII at any level.
|
|
|
|
These double as the review checklist. Ask them on any MR that adds or moves a log line.
|
|
|
|
h2. Field format
|
|
|
|
{{key=value}} pairs, snake_case keys, prefixed by the subject of the line. Quote with {{%q}} only when the value can be empty or contain spaces.
|
|
|
|
{code:go}
|
|
logging.LogInfoCtx(ctx, "policy batch received: batch_id=%s policy=%q alarms=%d alarm_names=%s",
|
|
batchID, request.Policy, len(request.Alarms), distinctAlarmNames(request.Alarms))
|
|
{code}
|
|
|
|
The runtime already adds a prefix, so do not repeat any of it in the message:
|
|
|
|
{noformat}
|
|
[2026-09-02T11:52:06.222] [INFO] [request_id=-] [tenant_id=-] [thread=-] [class=policies:executor.go:68] <your message>
|
|
{noformat}
|
|
|
|
|| Key || Source || Present on ||
|
|
| request_id | MDC, from the cloud-core context propagation middleware | every line, automatically |
|
|
| batch_id | minted once at ingress, carried in the context | every line handling that batch |
|
|
| alarm_id, ticket_id, order_id | the domain object | every line naming a single work item |
|
|
| alarm_ids | capped list | lines describing a set |
|
|
|
|
{note}
|
|
This is not structured logging. The logger emits a text message behind a fixed prefix, so Graylog does not extract these keys into searchable fields. They are found by full text search, which is exactly why identifiers have to appear literally in the message.
|
|
{note}
|
|
|
|
h2. Anti-patterns
|
|
|
|
All of these shipped and passed review.
|
|
|
|
h3. Printing a pointer instead of the data
|
|
|
|
{code:go}
|
|
logging.LogInfoCtx(ctx, "Valid alarms: %+v", validAlarms) // map[string]*Alarm
|
|
{code}
|
|
|
|
Go's {{fmt}} does not dereference pointers held inside a map or a slice, so what reaches Graylog is a map key and a heap address:
|
|
|
|
{noformat}
|
|
Valid alarms: map[7c0e-1:0x7cabe66aa060]
|
|
{noformat}
|
|
|
|
Print the identifiers, or a count.
|
|
|
|
h3. A verb that is not a verb
|
|
|
|
{code:go}
|
|
logging.LogDebug("... for alarm %s+", alarm) // *Alarm
|
|
{code}
|
|
|
|
{{%s+}} is {{%s}} followed by a literal plus. On a struct with non-string fields {{%s}} emits error markers:
|
|
|
|
{noformat}
|
|
&{7c0e-1 %!s(int=3) %!s(bool=false) 2026-09-02 11:52:06 ...}+
|
|
{noformat}
|
|
|
|
h3. INFO inside a per-object loop
|
|
|
|
{code:go}
|
|
for _, target := range targets {
|
|
...
|
|
logging.LogInfo("ONT target %s is not eligible for this ticket: %+v", ontId, target)
|
|
}
|
|
{code}
|
|
|
|
One INFO line per monitoring target, dumping the whole struct, where the logged branch is the *normal* outcome and not an exception. This scales with ONT count, not with request count. Log the members at DEBUG and one count after the loop.
|
|
|
|
h3. A rejection that returns in silence
|
|
|
|
A request rejected for capacity, for an unmatched handler or for a malformed body, returning a status code with no log line and no metric. Every identifier in that request is then absent from Graylog, and the request counter and the result counter diverge with nothing to explain the gap.
|
|
|
|
h3. Losing the panic value
|
|
|
|
{code:go}
|
|
logging.LogErrorCtx(ctx, "Unexpected panic: %v", reasonConstant, stackTrace)
|
|
{code}
|
|
|
|
One verb, two arguments. The recovered value is never printed and the stack trace arrives as {{%!(EXTRA string=...)}}.
|
|
|
|
h2. On-demand extended logging
|
|
|
|
How a service gets full detail in production without raising {{LOG_LEVEL}} and without paying for it on every healthy run. Every service handling a high-volume work item should implement it. {{gfiber-policy-executor}} is the reference:
|
|
|
|
{noformat}
|
|
PUT /troubleshooting/{entityKey}?minutes=1440
|
|
DELETE /troubleshooting/{entityKey}
|
|
GET /troubleshooting/{entityKey}
|
|
{noformat}
|
|
|
|
In code it is a guard around the verbose block, so the cost when off is one cached lookup:
|
|
|
|
{code:go}
|
|
logging.LogInfoCtx(ctx, "Handling Full Pon Loss for alarm: %+v", alarm.toShortString())
|
|
if m.IsAlarmTroubleshootingActive(ctx, alarm) {
|
|
logging.LogInfoCtx(ctx, "Alarm (full): %+v", alarm.toFullString())
|
|
}
|
|
{code}
|
|
|
|
The default line carries a bounded projection; the full payload is behind the guard. Setup and the supported entity keys: [How to enable troubleshooting logs [gfiber-policy-executor]|https://bass.netcracker.com/pages/viewpage.action?pageId=2466165241].
|
|
|
|
h2. Logs are not the only channel
|
|
|
|
Choosing the right channel is most of the volume problem. A line that belongs in a metric should not be a log.
|
|
|
|
|| Channel || Answers || Cannot ||
|
|
| Service log (Graylog) | what happened to this specific id | show trends, and it costs shared retention |
|
|
| Prometheus metric | how often, how slow, alerting | carry an identifier; label cardinality forbids it |
|
|
| BLM policy_actions_log | what we did to this item, on the record | be found from the SA Graylog streams |
|