fix(logger): attribute parallel logs to the correct test under go test -json#1873
Conversation
|
Note Reviews pausedIt looks like this branch is under active development. To avoid overwhelming you with review comments due to an influx of new commits, CodeRabbit has automatically paused this review. You can configure this behavior by changing the Use the following commands to manage reviews:
Use the checkboxes below for quick actions:
WalkthroughLogger output now uses per-test logging for stdout when a compatible testing sink exists. Parser logic recognizes indented Terratest output and attributes interleaved parallel-test logs to the correct test. Tests cover routing, fallback behavior, parsing, and de-interleaving. ChangesTesting-aware logger routing and attribution
Estimated code review effort: 3 (Moderate) | ~20 minutes Sequence Diagram(s)sequenceDiagram
participant GoTest
participant DoLog
participant TestingT
participant Parser
participant TestLog
GoTest->>DoLog: emit test log
DoLog->>TestingT: route stdout through Log
TestingT-->>Parser: test-attributed output
Parser->>TestLog: write line to owning test log
Suggested reviewers: Poem
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (1)
modules/core/logger/parser/parser.go (1)
59-63: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low valueConsider supporting non-
Testprefixes likeBenchmarkorFuzz.Currently, the regex specifically looks for the
Testprefix. While this is consistent with the existing heuristic lower down inparser.go, it means that logs from Terratest instances running insideBenchmark,Fuzz, orExamplefunctions will be missed by this parser branch.Since the timestamp signature (
\d{4}-\d{2}-\d{2}T) is extremely strict and unlikely to cause false positives, you could safely broaden the capture group to match any non-whitespace string, ensuring future-proofing for other Go test frameworks.💡 Proposed tweak to generalize the capture group
- regexIndentedTerratestLog = regexp.MustCompile(`^\s+\S+:\d+:\s+(Test[^\s]*)\s+\d{4}-\d{2}-\d{2}T`) + regexIndentedTerratestLog = regexp.MustCompile(`^\s+\S+:\d+:\s+([^\s]+)\s+\d{4}-\d{2}-\d{2}T`)🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@modules/core/logger/parser/parser.go` around lines 59 - 63, Update regexIndentedTerratestLog to capture any non-whitespace test identifier instead of requiring the identifier to begin with “Test,” while preserving the existing indentation, file decoration, and RFC3339 timestamp constraints so Benchmark, Fuzz, and Example logs are parsed.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@modules/core/logger/parser/parser.go`:
- Around line 123-128: Update GetTestNameFromIndentedTerratestLogLine to check
that FindStringSubmatch returns a match containing the capture group before
accessing m[1]. Return the function’s safe empty-string fallback when the input
does not match, while preserving the existing extracted test name for valid
matches.
---
Nitpick comments:
In `@modules/core/logger/parser/parser.go`:
- Around line 59-63: Update regexIndentedTerratestLog to capture any
non-whitespace test identifier instead of requiring the identifier to begin with
“Test,” while preserving the existing indentation, file decoration, and RFC3339
timestamp constraints so Benchmark, Fuzz, and Example logs are parsed.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro
Run ID: 53800129-1659-4ad7-b381-c595ad5d7907
📒 Files selected for processing (2)
modules/core/logger/parser/parser.gomodules/core/logger/parser/terratest_log_line_test.go
| // GetTestNameFromIndentedTerratestLogLine extracts the test name embedded in a terratest log line emitted through | ||
| // t.Log. See regexIndentedTerratestLog. | ||
| func GetTestNameFromIndentedTerratestLogLine(text string) string { | ||
| m := regexIndentedTerratestLog.FindStringSubmatch(text) | ||
| return m[1] | ||
| } |
There was a problem hiding this comment.
🩺 Stability & Availability | 🟡 Minor | ⚡ Quick win
Add a bounds check to prevent potential panics.
Because this function is exported, it can be called by other packages with arbitrary strings. If the input string doesn't match the regex, FindStringSubmatch returns nil, and indexing m[1] will cause a runtime panic.
Even though it's called safely within this file's switch block, adding a quick bounds check makes the function robust for any future use. (Note: The other exported helpers in this file share this vulnerability and could also benefit from similar checks.)
🛡️ Proposed fix
func GetTestNameFromIndentedTerratestLogLine(text string) string {
m := regexIndentedTerratestLog.FindStringSubmatch(text)
- return m[1]
+ if len(m) > 1 {
+ return m[1]
+ }
+ return ""
}📝 Committable suggestion
‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.
| // GetTestNameFromIndentedTerratestLogLine extracts the test name embedded in a terratest log line emitted through | |
| // t.Log. See regexIndentedTerratestLog. | |
| func GetTestNameFromIndentedTerratestLogLine(text string) string { | |
| m := regexIndentedTerratestLog.FindStringSubmatch(text) | |
| return m[1] | |
| } | |
| // GetTestNameFromIndentedTerratestLogLine extracts the test name embedded in a terratest log line emitted through | |
| // t.Log. See regexIndentedTerratestLog. | |
| func GetTestNameFromIndentedTerratestLogLine(text string) string { | |
| m := regexIndentedTerratestLog.FindStringSubmatch(text) | |
| if len(m) > 1 { | |
| return m[1] | |
| } | |
| return "" | |
| } |
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@modules/core/logger/parser/parser.go` around lines 123 - 128, Update
GetTestNameFromIndentedTerratestLogLine to check that FindStringSubmatch returns
a match containing the capture group before accessing m[1]. Return the
function’s safe empty-string fallback when the input does not match, while
preserving the existing extracted test name for valid matches.
37daae3 to
f341866
Compare
| // and prepends its own "file.go:NN: " decoration, e.g. " apply_test.go:42: TestFoo 2006-01-02T15:04:05Z07:00 | ||
| // caller.go:7: message". It captures the embedded test name so parallel output can still be de-interleaved. The | ||
| // "TestName <RFC3339 timestamp>" signature is what distinguishes a terratest line from an ordinary t.Log line. | ||
| regexIndentedTerratestLog = regexp.MustCompile(`^\s+\S+:\d+:\s+(Test[^\s]*)\s+\d{4}-\d{2}-\d{2}T`) |
There was a problem hiding this comment.
Minor nit: We could use 'Test\S*' here instead of 'Test[^\s]*' to match the style used in other areas. Not a blocker though.
f341866 to
58d655a
Compare
…t -json The default Terratest logger wrote formatted lines straight to os.Stdout. For parallel tests, go test -json cannot tell which test a raw stdout write belongs to, so it tags each line with whichever test was active, mixing up the output of parallel tests (issue gruntwork-io#1871). When a *testing.T is available, DoLog now routes the line through t.Log so the framework attributes it to the correct test, including under t.Parallel(). t.Log still streams immediately under -v on Go 1.14+, and an explicit non-stdout writer is still honored. If the test has already completed, it falls back to a direct stdout write instead of panicking.
Routing logs through t.Log (previous commit) indents each line and prepends the testing framework's "file.go:NN: " decoration, so terratest_log_parser's un-indented "Test"-prefix heuristic no longer matched and every parallel line fell through to the previousTestName rollup. Both parallel tests resume up front via === CONT and never pause again, so that rollup attributed all output to the last test resumed. The indented lines still embed their owning test name, so detect that format and extract the name directly, restoring correct de-interleaving. The existing un-indented case still handles the stdout fallback path. Adds unit tests for the new matcher and an end-to-end SpawnParsers test over interleaved t.Log output.
802c30c to
6c6132a
Compare
2 participants
Fixes #1871.
What
The default
Terratestlogger wrote formatted lines directly toos.Stdout. Undergo test -json, the JSON runner cannot attribute a raw stdout write to a specific parallel test, so it tags each line with whichever test was active. The result is output where theTestfield does not match the line it carries, which makes the JSON stream unusable for de-interleaving parallel tests. PR #1467 only added a mutex to stop garbled lines; attribution was never addressed.Change
Two commits:
logger:DoLognow routes throught.Logwhen a*testing.Tis available and the destination is stdout. The framework then attributes each line to the correct test, including undert.Parallel(). Behavior is otherwise preserved:t.Logstreams immediately under-von Go 1.14+, so the always on streaming rationale in the doc comment still holds.bytes.Buffer) is always honored.logger/parser: routing throught.Logindents each line and prepends the frameworkfile.go:NN:decoration, which broketerratest_log_parserde-interleaving of parallel non JSON output (every line rolled up to the last test resumed via=== CONT). The indented lines still embed their owning test name, so the parser now detects that format and extracts the name directly. The un-indented path (stdout fallback) is unchanged.Verification
t.Parallel()tests each runningterraform.InitAndApplyContextagainst arandom_integer+time_sleepconfig (mirrors the reporter repro, no cloud needed). Before: 134 of 188 terratest log lines misattributed. After: 0 of 190.-json: 0 of 24 misattributed.*testing.Tloggers still stream to stdout at column 0;*testing.Broutes throughb.Log.-voutput verified end to end viaSpawnParsers; existing fixture based parser tests still pass.modules/coresuite green under-race;go buildacross the workspace,go vet, andgofmtclean.Notes for review
t.Logmeans Go prepends its ownfile:line:decoration, so a line now carries both Go and Terratest prefixes. I kept the Terratest prefix intact to avoid dropping the test name and timestamp. Happy to trim the redundancy if you prefer.go test -v -jsonis indistinguishable from-vat runtime, so it applies whenever a real*testing.Tis present.Summary by CodeRabbit
t.Logwhen available to keep parallelgo test -jsonattribution correct.t.Log-routed output.