FLOGO-19401: Fix data race on the shared logger's tracing context - #299
FLOGO-19401: Fix data race on the shared logger's tracing context#299awakchau-tibco wants to merge 2 commits into
Conversation
One *zapLoggerImpl is shared by every concurrently executing flow instance
and activity - flow/action.go does `instLogger := logger` and only replaces
it with a per-instance child when FLOGO_LOG_CTX=true, which is off by
default. SetTracingContext therefore mutates that shared object while every
log call on it reads the same fields, with no synchronisation.
tracePrefix was a plain string field. A Go string is a two-word
{data, len} value and assigning one is not atomic, so a racing reader could
observe the torn combination {data: nil, len: N}: the `!= ""` guard passed
because len was non-zero, and the following prefix concatenation then copied
N bytes from address 0 and segfaulted, taking the whole app down.
Because the concatenation is an argument to Debugf/Infof it is evaluated on
every call regardless of the configured log level, so apps running at INFO or
ERROR were still crashing inside Debugf. Reported in the field as pods
restarting under high traffic, with SIGSEGV addr=0x0 at zap.go:84 and :92.
Publish the prefix and the trace context together as one immutable value held
in an atomic.Value, so a reader always observes a complete state. Uses
atomic.Value rather than atomic.Pointer[T] to stay within the module's
existing go 1.18 directive. No API or behaviour change.
Verified with the race detector: the added test reports a data race and the
standalone reproduction segfaults within about a second before this change,
and both are clean after it.
Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
Regression test verified in both directionsThe claim in the PR body that the new test catches this has now been checked both ways, rather than only green. Green — patched, with the race detector (Ubuntu 24.04, Go 1.25.11, 16 CPUs): Red — unpatched. Reverting only Running just the concurrency test against an unmodified Same signature as the field reports: So the test is a genuine regression test — it goes red on the defect and green on the fix, and it is fast (0.02 s) and quiet (level is set to ERROR, and the prefix is still built on every call because it is an argument). Note for anyone reproducing this: |
Comment-only change, no functional difference. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
What kind of change does this PR introduce? (check one with "x")
Fixes: FLOGO-19401
What is the current behavior?
Apps crash with an unrecovered
SIGSEGVunder concurrent load, and the container is restarted. Reported in the field as pods restarting under high traffic; three separate pods produced the same panic:One
*zapLoggerImplis shared by every concurrently executing flow instance and activity —flow/action.godoesinstLogger := loggerand only replaces it with a per-instance child whenFLOGO_LOG_CTX=true, which is off by default.SetTracingContexttherefore mutates that shared object while every log call on it reads the same fields, with no synchronisation:flow/action.go:355— sets the prefix on flow startflow/action.go:392,:397— clears it on flow completionflow/instance/taskinst.go:349— sets it per activitysupport/log/zap.go:84—l.mainLogger.Debugf(l.tracePrefix+template, args...)support/log/zap.go:92—l.mainLogger.Infof(l.tracePrefix+template, args...)tracePrefixwas a plainstringfield. A Go string is a two-word{data *byte, len int}value and assigning one is not atomic, so a racing reader could observe the torn combination{data: nil, len: N}:zap.go:83— thel.tracePrefix != ""guard passes, becauselenis non-zerozap.go:84—l.tracePrefix + templatethen copiesNbytes from address0Running the reproduction with
GOTRACEBACK=systemunhides the runtime frames and shows exactly that:Two things make this easy to hit:
Debugf, so it is evaluated on every call regardless of the configured log level. Apps running at INFO or ERROR still crash insideDebugf.DefaultLogTracingContextEnabled = true, so no opt-in is required to reach the code.traceContext map[string]stringhas the same problem — it is assigned unsynchronised on the line above.What is the new behavior?
The prefix and the trace context are published together as one immutable
*traceStateheld in anatomic.Value, so a reader always observes a complete, self-consistent state. Every log method loads it once into a local.support/log/zap.go. No API change, no behaviour change.atomic.Valuerather thanatomic.Pointer[T]so it stays within the module's existinggo 1.18directive.Testing
Adds
support/log/zap_test.go(the package previously had no tests):TestSetTracingContext— pins prefix set/clear/round-trip behaviour, including a context with no trace idTestSetTracingContextDisabled— coversFLOGO_LOG_TRACE_CTX_ENABLED=falseTestSetTracingContextConcurrentWithLogging— the regression test: 2 writers against 8 readers exercisingDebugf/Infof/Debug/Info. Reports a data race under-racebefore this change, clean afterVerified on Ubuntu 24.04, Go 1.25.11, 16 CPUs:
SIGSEGV addr=0x0within approx 1 s-raceWARNING: DATA RACE, exit 66gofmtandgo vetare clean.go test ./...passes on 30 packages; the one failure,TestURLStringToFilePathinsupport, is a pre-existing Windows-only path-separator assertion that reproduces identically on unmodifiedmaster.Note for reviewers
There is a related correctness issue this PR deliberately does not address: because the logger is shared, one flow's trace id can be stamped onto another flow's log lines. That is misleading observability data rather than a crash, and fixing it means giving each flow instance its own logger — a larger change in
flow. Raising separately.