Marcos Silva
113 lines
6.3 KiB
Markdown
113 lines
6.3 KiB
Markdown
# Levels and the decision list
|
|
|
|
Canonical source: [How To: What logs belong at INFO, DEBUG, WARN and ERROR in GFiber services](https://bass.netcracker.com/display/GF/How+To%3A++What+logs+belongs+at+INFO%2C+DEBUG%2C+WARN+and+ERROR+in+GFiber+services). This file is the working copy for agents; when the two disagree, the BASS page wins.
|
|
|
|
## Why there is a ceiling on INFO
|
|
|
|
Graylog storage is shared across the platform. Every INFO line written on a healthy run is paid for in retention days, so the more a service logs, the shorter the window for grepping an incident that already happened. A service that logs too little is untriageable. The policy is the line between the two.
|
|
|
|
Three facts that drive every rule below:
|
|
|
|
- `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 item count, not with request count.
|
|
|
|
## 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 |
|
|
|
|
`mano.netcracker.com/go-logging/v3` exposes `LogDebug`, `LogInfo`, `LogWarning`, `LogError`, `LogFatal` and a `Ctx` variant of each. There is no TRACE.
|
|
|
|
## Decision list
|
|
|
|
Walk in order, stop at the first yes.
|
|
|
|
1. Work was lost and someone has to look at it. Use ERROR.
|
|
2. An item was dropped or degraded, and the service keeps going. Use WARN.
|
|
3. 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. Use INFO.
|
|
4. It fires more than once per item, or prints a collection, a struct or a body. Use DEBUG.
|
|
5. Anything else. Use DEBUG.
|
|
|
|
When two levels look defensible, 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.
|
|
|
|
## 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, both 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.
|
|
|
|
## 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.
|
|
|
|
## 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.
|
|
|
|
```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))
|
|
```
|
|
|
|
The runtime already adds a prefix, so do not repeat any of it in the message:
|
|
|
|
```
|
|
[2026-09-02T11:52:06.222] [INFO] [request_id=-] [tenant_id=-] [thread=-] [class=policies:executor.go:68] <your message>
|
|
```
|
|
|
|
### Correlation keys
|
|
|
|
| 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 |
|
|
|
|
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.
|
|
|
|
## 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:
|
|
|
|
```
|
|
PUT /troubleshooting/{entityKey}?minutes=1440
|
|
DELETE /troubleshooting/{entityKey}
|
|
GET /troubleshooting/{entityKey}
|
|
```
|
|
|
|
In code it is a guard around the verbose block, so the cost when off is one cached lookup:
|
|
|
|
```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())
|
|
}
|
|
```
|
|
|
|
The default line carries a bounded projection; the full payload is behind the guard. Setup and supported entity keys: [How to enable troubleshooting logs (gfiber-policy-executor)](https://bass.netcracker.com/pages/viewpage.action?pageId=2466165241).
|
|
|
|
## Logs are not the only channel
|
|
|
|
Choosing the right channel is most of the volume problem.
|
|
|
|
| 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 |
|