remotelogger: 6 of 30 remote log-level transitions are announced at a level that discards the announcement
- Dominant language
- Go
- Stars
- 20.9k
- Forks
- 1.8k
- Avg merge
- 5d 18h
- Merged PRs (30d)
- 39
Description
**Describe the bug**
When the log level is changed through the remote log-level service, `remotelogger` is supposed to announce it. The announcement itself is emitted at a level that the *current* gate discards, so **6 of the 30 possible transitions are completely silent** — the level really does change, but nothing is written and the operator has no confirmation that the remote service was honoured.
Every transition **out of** `FATAL` is silent, plus `ERROR → FATAL`:
| from | to | operator sees |
|---|---|---|
| DEBUG / INFO / NOTICE / WARN | FATAL | the change |
| **ERROR** | **FATAL** | **nothing** |
| **FATAL** | **DEBUG / INFO / NOTICE / WARN / ERROR** | **nothing** |
Two things combine to cause it, both in `pkg/gofr/logging/remotelogger/dynamic_level_logger.go`:
1. **`logLevelChange` runs before `ChangeLevel`**, so the entry is gated by the **old** level:
```go
logLevelChange(r, oldLevel, newLevel) // line 197 — logged here
r.ChangeLevel(newLevel) // line 198 — level applied here
```
2. **The `FATAL` branch logs at `WARN`**, which is strictly below `FATAL`, so it can never survive a `FATAL` gate — despite the comment directly above saying the opposite:
```go
// Use the higher level to ensure visibility
logLevel := oldLevel
if newLevel > oldLevel {
logLevel = newLevel
}
switch logLevel {
case logging.FATAL:
r.Warnf("%s", message) // WARN < FATAL — always discarded
...
```
Taken together: whenever `max(old, new) == FATAL` **and** the old level is above `WARN`, the message is dropped. `FATAL` is exactly the level an operator reaches for to silence a noisy service, so the case where confirmation matters most is the case that produces nothing.
**To Reproduce**
1. The code is — driving `logLevelChange` directly for every ordered pair, with the logger at the *old* level as `checkAndUpdateLevel` leaves it:
```go
for _, old := range levels {
for _, nw := range levels {
if old == nw {
continue
}
base := logging.NewFileLogger("/dev/null")
base.ChangeLevel(old) // level at the moment logLevelChange runs
r := &remoteLogger{Logger: capture(base, old), currentLevel: old}
logLevelChange(r, old, nw) // did anything survive the gate?
}
}
```
2. The output is
```
from -> to | operator sees
--------------------------------------
DEBUG -> FATAL | the change
INFO -> FATAL | the change
NOTICE -> FATAL | the change
WARN -> FATAL | the change
ERROR -> FATAL | >>> NOTHING <<<
FATAL -> DEBUG | >>> NOTHING <<<
FATAL -> INFO | >>> NOTHING <<<
FATAL -> NOTICE | >>> NOTHING <<<
FATAL -> WARN | >>> NOTHING <<<
FATAL -> ERROR | >>> NOTHING <<<
silent transitions: 6 of 30
```
It also reproduces end to end against a real server. Running a GoFr app with `REMOTE_LOG_URL` pointed at a stub config service and `REMOTE_LOG_FETCH_INTERVAL=1`, then walking the remote level through `DEBUG → NOTICE → WARN → ERROR → FATAL → INFO → DEBUG`, the log carries a line for every step except the two involving `FATAL`:
```
{"level":"NOTICE",...,"message":"LOG_LEVEL updated from DEBUG to NOTICE"}
{"level":"WARN", ...,"message":"LOG_LEVEL updated from NOTICE to WARN"}
{"level":"ERROR", ...,"message":"LOG_LEVEL updated from WARN to ERROR"}
(ERROR -> FATAL : nothing)
(FATAL -> INFO : nothing)
{"level":"INFO", ...,"message":"LOG_LEVEL updated from INFO to DEBUG"}
```
The level change *is* applied in every case — only the announcement is lost.
**Expected behavior**
A remote level change is always announced, whichever direction it goes. The message is a control-plane event, not application logging: it reports that an external service reconfigured the process, and it should not be filtered by the very setting it is reporting on.
Two possible fixes, either of which closes it:
- Emit the announcement **after** `ChangeLevel`, at the level that is guaranteed to pass — i.e. use the **more permissive** of the two levels (`min(old, new)`), not the more restrictive one. The current code takes `max`, which is backwards relative to its own comment.
- Or write the announcement unconditionally, bypassing the gate, since it is a lifecycle event rather than a log line.
The first is smaller and keeps everything inside the existing gate.
**Environments**
- OS: macOS (darwin/arm64); not platform-specific
- gofr version: reproduced on `development` @ `7cbb41a3`
- go version: 1.26.3
**More description**
Found while verifying #3974 against `development` — it reproduces identically on both, so it is pre-existing and not caused by that PR. Filing separately rather than widening that PR's scope.
Related but not the same: #2226 proposes refactoring the remote-config coupling; this is a self-contained visibility bug in the current implementation and can be fixed independently.
Happy to raise a PR for this.
Contributor guide
Research direction
Start in pkg/gofr/logging/remotelogger/dynamic_level_logger.go, tracing logLevelChange and checkAndUpdateLevel around the ordering of the announcement and level update. Run the provided ordered-pair reproduction with the logger at each old level, then verify that all 30 transitions produce an announcement, including transitions to and from FATAL.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- observability
- Issue type
- Bug
- Difficulty
- 2/5
- Estimated time
- 1-3 hours
- Activity status
- Active
- Clarity
- Clearly specified
- Newbie friendliness
- 78/100