netcracker/ai-for-dummies
3
0
Fork 0
Code Issues Pull Requests Actions 2 Packages Projects Releases Wiki Activity

feat: migrate skills review desk to astro

Browse Source
This commit is contained in:
Marcos Paulo
2026-09-05 16:54:37 +00:00
parent 107e429fb9
commit 71e4775573
66 changed files with 8184 additions and 96 deletions
Download Patch File Download Diff File Expand all files Collapse all files
public/submitted-skills/Gustavo Ruiz/skills/confluence-page-source.txt
+229
View File
@@ -0,0 +1,229 @@
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 |
public/submitted-skills/Gustavo Ruiz/skills/gfiber-logging/SKILL.md
+83
View File
@@ -0,0 +1,83 @@
---
name: gfiber-logging
description: >-
Decides the level of a log line in GFiber services and keeps INFO volume bounded.
Use when writing or reviewing logging code, choosing between DEBUG, INFO, WARN and
ERROR, adding observability to a service, judging whether a line belongs in a log or
a metric, or auditing a service for log volume before a merge request.
---
# GFiber Logging
Level policy and field conventions for log lines in GFiber services.
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). When this skill and the BASS page disagree, the page wins and this skill gets updated.
References: [references/levels.md](references/levels.md), [references/cases.md](references/cases.md), [references/anti-patterns.md](references/anti-patterns.md), [references/audit.md](references/audit.md).
## Hard rules
- **INFO is capped** — work received, work finished, one result per work item. Nothing else.
- **No unbounded collection at INFO** — the count is INFO, the collection behind it is DEBUG.
- **No INFO inside a loop** over alarms, ONTs, targets, services, tickets or messages. The per-item result line is the one legitimate exception.
- **Cap identifier lists** at 50 entries followed by `+N more`.
- **Always the `Ctx` variant** — `LogInfoCtx`, never `LogInfo`. The plain call drops `request_id` and every business identifier.
- **Never a full request or response body at INFO** — log a projection; bodies go to DEBUG or behind on-demand troubleshooting.
- **Mint correlation ids at ingress**, not deeper. An id created inside the handler cannot join the lines written before it.
- **No secrets, tokens or customer PII** at any level.
- **DEBUG is not present in production** — `LOG_LEVEL` is `INFO` in every shipped chart. A decision that must be explainable in production cannot live at DEBUG.
## Workflow: one log line
1. Walk the decision list in [references/levels.md](references/levels.md) and stop at the first yes.
2. If the answer was INFO, confirm the line matches one of the four INFO cases. If it does not, it is DEBUG.
3. Look the situation up in [references/cases.md](references/cases.md). Startup, scheduled ticks, Kafka, health probes and upstream calls all have a fixed answer there.
4. Apply the field format from [references/levels.md](references/levels.md): `key=value`, snake_case, subject prefix, `%q` only for values that can be empty or contain spaces.
5. Confirm the identifiers. On WARN and ERROR, add them only where no per-item result line will run for that work.
## Workflow: adding logging to a service
1. Read [references/cases.md](references/cases.md) and pick the reference implementation closest to the service shape (request handler, batch policy, scheduler, Kafka consumer).
2. Run the static audit in [references/audit.md](references/audit.md) to record the starting numbers.
3. Add the three INFO lines the policy expects, in this order, because each one is useless without the previous: work received, per-item result, batch summary.
4. Add WARN on every branch that rejects or drops work, with a fixed reason vocabulary and a counter.
5. Add ERROR on every branch that loses work after retries, carrying the identifiers and the step that stopped.
6. Demote or delete what the audit flagged: collection dumps, per-object INFO, ticks that fire on a timer, lines whose whole content is already in the runtime prefix.
7. Re-run the audit and report before and after.
## Workflow: reviewing a merge request
1. Apply the checklist in [references/audit.md](references/audit.md).
2. Check the level of each added line against [references/cases.md](references/cases.md), not against how important the code feels.
3. Scan for the known anti-patterns in [references/anti-patterns.md](references/anti-patterns.md). Pointer maps, bad verbs and silent rejections are the three that recur.
4. If the change touches a high-volume path, require the volume gate table in the merge request description.
## Workflow: auditing a service for volume
1. Run the static audit script from [references/audit.md](references/audit.md) at the service checkout root.
2. Exclude lines already behind an on-demand troubleshooting guard; the ungated count is the one that matters.
3. Rank by `dump` and `loop` rather than by raw INFO count: a service with few INFO lines that all print collections is worse than one with many bounded lines.
4. Measure the real numbers on a reference scenario per the volume gate, not only the static count.
## Choosing the channel
Most of the volume problem is picking the wrong channel. Full table in [references/levels.md](references/levels.md).
- "How often" or "how slow" is a **metric**, and it cannot carry an identifier.
- "What happened to this specific id" is a **log**, and it costs shared retention.
- "What did we do to this item, on the record" is a **BLM action log**, and it is not reachable from the SA Graylog streams.
## Safety
- **Read-only** — this skill reasons about code and proposes changes. It runs no mutation of its own.
- Source trees under `sources/product/` are read-only; propose changes, never edit.
- Sync sources with `gfiber-sources` before auditing a service.
## Related skills
| Skill | Role |
|-------|------|
| `gfiber-sources` | Clone or checkout the service before auditing it |
| `gfiber-sa-troubleshooting` | Consumer of these logs; its Graylog searches are why identifiers must be literal |
| `gfiber-svt-analysis` | Registered SVT cases used as the reference scenario for the volume gate |
| `skills/_shared/code-reviewer` | General review pass; this skill covers the logging dimension only |
public/submitted-skills/Gustavo Ruiz/skills/gfiber-logging/references/anti-patterns.md
+88
View File
@@ -0,0 +1,88 @@
# Anti-patterns
Every example below shipped and passed review in a GFiber service. Check for these first when auditing.
## Printing a pointer instead of the data
```go
logging.LogInfoCtx(ctx, "Valid alarms: %+v", validAlarms) // map[string]*Alarm
logging.LogInfoCtx(ctx, "Alarm results: %+v", alarmResults) // map[string]*AlarmResult
```
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:
```
Valid alarms: map[7c0e-1:0x7cabe66aa060]
Alarm results: map[7c0e-1:0x7cabe66b4000]
```
Print the identifiers, or a count. A struct or map of values prints fine; a map or slice of pointers does not.
## A verb that is not a verb
```go
logging.LogDebug("... for alarm %s+", alarm) // *Alarm
```
`%s+` is `%s` followed by a literal plus. On a struct with non-string fields `%s` emits error markers:
```
&{7c0e-1 %!s(int=3) %!s(bool=false) 2026-09-02 11:52:06 ...}+
```
Use `%+v`, or a short projection method such as `toShortString()`.
## INFO inside a per-object loop
```go
for _, target := range targets {
...
logging.LogInfo("ONT target %s is not eligible for this ticket: %+v", ontId, target)
}
```
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.
## A tick that logs whether or not there is work
```go
logging.LogInfoCtx(ctx, "Schedule ticket updates at %v", time.Now())
```
Fired on every scheduler tick. With a five second interval that is roughly 17k INFO lines per day per pod with no work behind them. The tick belongs at DEBUG; the INFO line belongs after the batch, with counts.
## 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.
## A result line that never runs
An early return on a failure path that skips the per-item result loop. The batch is lost and leaves one line with no identifier in it. Populate the results on every exit path, or carry the identifiers on the ERROR.
Watch the status code when fixing this: in `gfiber-policy-executor` filling the results made a fully failed batch fall through the handler condition and answer HTTP 200, and the caller only inspects the status code, so it would have marked the work completed.
## Losing the panic value
```go
logging.LogErrorCtx(ctx, "Unexpected panic: %v", reasonConstant, stackTrace)
```
One verb, two arguments. The recovered value is never printed and the stack trace arrives as `%!(EXTRA string=...)`.
## A line whose whole content is already in the prefix
```go
logging.LogInfoCtx(ctx, "x-request-id=%s", requestId)
```
The runtime prefix already carries `request_id`. The line names no work item, so it costs volume and answers nothing. Replace it with a work-received line that names the ticket or alarm.
## Retry semantics inverted
Logging every retry attempt at WARN while the exhaustion, the moment the work actually moves to a backlog, is silent. The attempt is DEBUG, the exhaustion is ERROR with the identifier.
## Non-context logging
`logging.LogInfo` and friends without `Ctx` drop `request_id` and every business identifier from the MDC, which makes the line impossible to attach to anything.
If the enclosing function has no `ctx` and it is a pure helper, do not thread `ctx` through several signatures only to log. Either move the line to the caller, which has the context, or drop it: a DEBUG line that cannot be correlated is close to useless when two work items are in flight.
public/submitted-skills/Gustavo Ruiz/skills/gfiber-logging/references/audit.md
+77
View File
@@ -0,0 +1,77 @@
# Auditing a service and the volume gate
## Static audit
Run from the checkout root of any Go service under `sources/project/`. Heuristic, not a linter: it flags short projection methods such as `toShortString()` as dumps, and it does not know about on-demand troubleshooting guards. Read what it prints; do not treat the counts as a gate on their own.
```python
import re, glob
files = [f for f in glob.glob('**/*.go', recursive=True)
if not f.endswith('_test.go') and '/vendor/' not in f]
info = dump = loop = noctx = 0
for path in files:
depth, loops = 0, []
for i, line in enumerate(open(path, errors='ignore'), 1):
stripped = line.strip()
if re.search(r'\bfor .*\{\s*$', stripped):
loops.append(depth)
depth += line.count('{') - line.count('}')
loops = [d for d in loops if d < depth]
if re.search(r'logging\.Log(Info|Debug|Warning|Error|Fatal)\(', line):
noctx += 1
print(f'noCtx {path}:{i}: {stripped[:100]}')
if re.search(r'logging\.LogInfo(Ctx)?\(', line):
info += 1
if '%+v' in line and not re.search(r'%\+v[^"]*"\s*,\s*len\(', line):
dump += 1
print(f'dump {path}:{i}: {stripped[:100]}')
if loops:
loop += 1
print(f'loop {path}:{i}: {stripped[:100]}')
print(f'INFO={info} dump={dump} loop={loop} noCtx={noctx}')
```
To exclude lines already behind an on-demand troubleshooting guard, track the brace depth of the block opened by `IsAlarmTroubleshootingActive(` and skip lines while inside it. In `gfiber-policy-executor` that moved the count from 77 INFO sites to 34 ungated ones, which is the number that matters.
### How to read the output
| Signal | Meaning |
|--------|---------|
| high `dump` against low `INFO` | the few INFO lines the service has are the expensive kind |
| any `loop` | a line scaling with item count rather than request count; the per-item result line is the one legitimate case |
| `noCtx` | lines that cannot be attached to a work item |
## Volume gate
Any change to logging on a high-volume path states its volume impact in the merge request. Measure the same scenario before and after, in the same namespace and window, using the `graylog-search` entry in [scripts/data/index.yaml](../../../scripts/data/index.yaml) with `--scope containers` and a container plus level filter, per [scripts/data/graylog-search.example.md](../../../scripts/data/graylog-search.example.md).
Repeat for INFO, DEBUG, WARN and ERROR, then rerun on the branch build.
| Metric | Before | After | Delta |
|--------|--------|-------|-------|
| INFO messages per run | | | |
| INFO bytes per run | | | |
| DEBUG messages per run | | | |
| WARN and ERROR per run | | | |
| Longest single INFO line, bytes | | | |
Acceptance: INFO message count and INFO bytes must not increase. DEBUG is allowed to grow, since it is off in production.
For SA services use the registered SVT cases from [skills/gfiber-svt-analysis/cases/index.yaml](../../gfiber-svt-analysis/cases/index.yaml). Services without an SVT case need a reference scenario agreed with the reviewer before the gate means anything.
On the same run, confirm that a sample identifier from it is still findable at `LOG_LEVEL: INFO` with the SA alarm template from [queries/graylog/index.yaml](../../../queries/graylog/index.yaml). That is the regression the policy exists to prevent, and it is satisfied by the per-item result line rather than by anything new.
## Merge request checklist
The hard rules in [levels.md](levels.md) double as the review checklist. In addition:
- Every new INFO line matches one of the four INFO cases.
- No new INFO line prints a collection, a struct or a body.
- No new INFO line sits inside a loop over domain objects.
- Every identifier list is capped.
- Every call is the `Ctx` variant.
- WARN and ERROR on failure paths carry the identifiers of the work they lost.
- The summary line is written from a `defer` that survives a panic.
- New metric labels come from a fixed vocabulary, with no identifiers in them.
- `go vet` is clean and no line prints a pointer address or a `%!s` marker.
public/submitted-skills/Gustavo Ruiz/skills/gfiber-logging/references/cases.md
+73
View File
@@ -0,0 +1,73 @@
# Case catalogue
The cases that come up in GFiber services and the level each one takes. If a case is not here, run the decision list in [levels.md](levels.md) and add a row.
## 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 |
## 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 |
## 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 |
## 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 |
## 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.
## Reference implementations
Read these before writing a new one; both were reviewed against this policy.
| What | Where |
|------|-------|
| Per-batch summary line, `key=value`, INFO on ok and ERROR otherwise | `gfiber-policy-executor`, `pkg/faultstatus/stats.go` |
| Per-alarm result line, the one support greps for | `gfiber-policy-executor`, `pkg/policies/executor.go` |
| Ingress line with counts, ids on a DEBUG companion | `gfiber-policy-executor`, `pkg/policies/executor.go` |
| Per-item result line from a defer, covering every failure path | `gfiber-ticketing-proxy`, `pkg/ticket/executor.go` |
| Rejection lines with a fixed reason vocabulary plus a counter | `gfiber-ticketing-proxy`, `pkg/ticket/routes.go` |
public/submitted-skills/Gustavo Ruiz/skills/gfiber-logging/references/levels.md
+112
View File
@@ -0,0 +1,112 @@
# 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 |