Skip to content

fix(log): route Writer through the structured encoder instead of raw passthrough - #797

Merged
skevetter merged 4 commits into
mainfrom
fix/log-writer-structured-output
Jul 29, 2026
Merged

fix(log): route Writer through the structured encoder instead of raw passthrough#797
skevetter merged 4 commits into
mainfrom
fix/log-writer-structured-output

Conversation

@skevetter

@skevetter skevetter commented Jul 28, 2026

Copy link
Copy Markdown
Contributor

log.Writer() is used as a subprocess's Stdout/Stderr at ~65 call sites (docker build, buildkit, SSH, IDE installers, git clone, etc). Its levelWriter.Write previously wrote raw bytes directly to the sink, bypassing zap's encoder and producing unencoded lines in what should be a uniform JSON/text/logfmt stream in --log-output json mode.

levelWriter now line-buffers and calls Info/Debug/Error per complete line, so subprocess output goes through the same encoder as every other log call. Close flushes any trailing partial line (previously silently dropped).

Summary by CodeRabbit

  • Bug Fixes
    • Improved log output handling by buffering writes and splitting newline-delimited content into separate entries.
    • Ensured partial final log lines are emitted when the writer is closed.
    • Enforced verbosity filtering so messages below the configured level are omitted.
    • Preserved blank lines so they generate entries with an empty message.
  • Tests
    • Added JSON writer tests covering single-line output, multi-line splitting across writes, flush-on-close behavior, blank line handling, and verbosity filtering.

…passthrough

log.Writer() is used as a subprocess's Stdout/Stderr at ~65 call sites
across the codebase (docker build, buildkit, SSH, IDE installers, git
clone, etc). Its levelWriter.Write wrote raw bytes directly to the
stderr sink, bypassing zap's encoder entirely -- contradicting its own
doc comment ("writes each line as a log entry") and producing
unencoded lines in what's supposed to be a uniform JSON/text/logfmt
stream in --log-output json mode.

levelWriter now line-buffers and calls Info/Debug/Error per complete
line, so subprocess output goes through the same encoder as every
other log call. Close flushes any trailing line left without a
newline (previously silently dropped).
@netlify

netlify Bot commented Jul 28, 2026

Copy link
Copy Markdown

Deploy Preview for images-devsy-sh canceled.

Name Link
🔨 Latest commit 3b03917
🔍 Latest deploy log https://app.netlify.com/projects/images-devsy-sh/deploys/6a697c9d4143e90008c97e0c

@coderabbitai

coderabbitai Bot commented Jul 28, 2026

Copy link
Copy Markdown

Review Change Stack

📝 Walkthrough

Walkthrough

levelWriter now buffers byte streams, logs complete newline-delimited messages at the configured level, preserves blank lines, and flushes partial messages on Close(). Tests cover JSON output, line splitting, flushing, blank lines, and verbosity filtering.

Changes

Log writer behavior

Layer / File(s) Summary
Buffered writer and level dispatch
pkg/log/writer.go
Writer creates a level-configured writer that buffers input, emits complete lines through package-level logging functions, preserves blank lines, bounds pending data, and flushes residual content on close.
Writer output validation
pkg/log/writer_test.go
Tests verify structured JSON fields, newline-delimited output across writes, close-time flushing, blank-line preservation, and discarding messages below the configured verbosity level.

Estimated code review effort: 3 (Moderate) | ~20 minutes

Sequence Diagram(s)

sequenceDiagram
  participant Writer
  participant levelWriter
  participant PackageLogger
  participant Sink
  Writer->>levelWriter: Write byte stream
  levelWriter->>levelWriter: Buffer and split complete lines
  levelWriter->>PackageLogger: Log line at configured level
  PackageLogger->>Sink: Emit JSON record
  Writer->>levelWriter: Close
  levelWriter->>PackageLogger: Flush trailing partial line
Loading

Possibly related PRs

  • devsy-org/devsy#13: Modifies the related pkg/log/writer.go writer adapter and its subprocess-output handling.
🚥 Pre-merge checks | ✅ 5
✅ Passed checks (5 passed)
Check name Status Explanation
Description Check ✅ Passed Check skipped - CodeRabbit’s high-level summary is enabled.
Title check ✅ Passed The title accurately summarizes the main change: Writer now routes output through structured logging instead of raw passthrough.
Docstring Coverage ✅ Passed No functions found in the changed files to evaluate docstring coverage. Skipping docstring coverage check.
Linked Issues check ✅ Passed Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check ✅ Passed Check skipped because no linked issues were found for this pull request.
✨ Finishing Touches 💡 1
🛠️ Fix failing CI checks 💡
  • Fix failing CI checks

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.

❤️ Share

Comment @coderabbitai help to get the list of available commands.

@netlify

netlify Bot commented Jul 28, 2026

Copy link
Copy Markdown

Deploy Preview for devsydev canceled.

Name Link
🔨 Latest commit 3b03917
🔍 Latest deploy log https://app.netlify.com/projects/devsydev/deploys/6a697c9d07e72300080b167a

Reorder levelWriter's exported Close before the unexported logLine
helper, and hoist the repeated "json" format literal in writer_test.go
into a constant.
@skevetter
skevetter marked this pull request as ready for review July 29, 2026 03:55

@coderabbitai coderabbitai Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actionable comments posted: 2

🧹 Nitpick comments (1)
pkg/log/writer_test.go (1)

37-60: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick win

Cover fragmented writes and emitted message values.

This test only checks two records from one Write and their JSON shape. Add a case such as Write("line one\nline ") followed by Write("two\n"), then decode and assert the messages are exactly line one and line two.

🤖 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 `@pkg/log/writer_test.go` around lines 37 - 60, Extend
TestWriter_SplitsMultipleLinesInOneWrite to perform fragmented writes, first
writing “line one\nline ” and then “two\n”. Decode each emitted JSON record and
assert their message values are exactly “line one” and “line two”, while
retaining the existing record-count validation.
🤖 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 `@pkg/log/writer.go`:
- Around line 44-51: The Write handling around w.buf.ReadString must avoid
resetting and copying the entire incomplete fragment on every partial write;
process complete lines incrementally while retaining only the unconsumed suffix.
Add a bounded pending-line policy for unterminated output, such as flushing or
truncating once the configured maximum is reached, so fragmented progress output
cannot grow without limit.
- Around line 68-70: The logLine method currently discards newline-only records
by returning when line is empty. Remove the empty-line early return in
levelWriter.logLine so blank output lines are preserved, relying on Close’s
existing buf.Len() guard to avoid phantom records.

---

Nitpick comments:
In `@pkg/log/writer_test.go`:
- Around line 37-60: Extend TestWriter_SplitsMultipleLinesInOneWrite to perform
fragmented writes, first writing “line one\nline ” and then “two\n”. Decode each
emitted JSON record and assert their message values are exactly “line one” and
“line two”, while retaining the existing record-count validation.
🪄 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 Plus

Run ID: 0efadac0-d1f8-4a08-8831-55a13193947a

📥 Commits

Reviewing files that changed from the base of the PR and between dcb0ace and e2a84ec.

📒 Files selected for processing (2)
  • pkg/log/writer.go
  • pkg/log/writer_test.go

Comment thread pkg/log/writer.go Outdated
Comment thread pkg/log/writer.go Outdated
@skevetter
skevetter marked this pull request as draft July 29, 2026 04:02
- levelWriter.Write now scans only the bytes passed to that call for
  '\n' (via bytes.IndexByte) instead of resetting and re-copying the
  entire accumulated pending line on every partial write, which made
  writing one large unterminated line in many small chunks effectively
  O(n^2). Previously-seen bytes are never rescanned.
- Bound the pending line to 64KiB: a subprocess that never emits a
  newline no longer grows levelWriter's buffer without limit.
- logLine no longer discards empty lines. That guard was only ever
  needed to stop Close from emitting a phantom record when nothing was
  pending, which Close already handles itself via its buf.Len() check
  -- so it was silently dropping genuine blank lines from subprocess
  output.
- Extended the multi-line test to cover a line split across two Write
  calls (as os/exec delivers chunks arbitrarily) and decode each
  emitted record to assert its exact msg, and added a test asserting
  blank lines are preserved as empty-message records.
@skevetter
skevetter marked this pull request as ready for review July 29, 2026 05:12

@coderabbitai coderabbitai Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actionable comments posted: 1

🧹 Nitpick comments (1)
pkg/log/writer_test.go (1)

90-112: 🩺 Stability & Availability | 🔵 Trivial | ⚡ Quick win

Add regression coverage for the 64 KiB pending-line boundary.

The suite covers split writes and Close flushing, but not the writer’s documented oversized unterminated-line behavior. Add a payload larger than maxPendingLine, verify it is emitted before Close, and confirm Close handles only any remaining tail.

🤖 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 `@pkg/log/writer_test.go` around lines 90 - 112, Add regression coverage
alongside TestWriter_FlushesTrailingPartialLineOnClose for a payload exceeding
maxPendingLine; verify the oversized unterminated line is emitted before calling
Writer.Close, then confirm Close flushes only any remaining tail without
duplicating the already-emitted payload.
🤖 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 `@pkg/log/writer_test.go`:
- Around line 72-86: Update assertJSONLineMsg to distinguish a missing msg field
from an explicit empty value by making the decoded Msg field nullable or
validating the raw JSON field, and reject missing fields. Replace the separate
substring assertion for the blank record with assertJSONLineMsg(t, 1, lines[1],
""), including the corresponding assertion path around the later blank-record
check.

---

Nitpick comments:
In `@pkg/log/writer_test.go`:
- Around line 90-112: Add regression coverage alongside
TestWriter_FlushesTrailingPartialLineOnClose for a payload exceeding
maxPendingLine; verify the oversized unterminated line is emitted before calling
Writer.Close, then confirm Close flushes only any remaining tail without
duplicating the already-emitted payload.
🪄 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 Plus

Run ID: 93b66d81-be19-41c0-b6b2-6e16d8325f91

📥 Commits

Reviewing files that changed from the base of the PR and between e2a84ec and 3b03917.

📒 Files selected for processing (2)
  • pkg/log/writer.go
  • pkg/log/writer_test.go
🚧 Files skipped from review as they are similar to previous changes (1)
  • pkg/log/writer.go

Comment thread pkg/log/writer_test.go
Comment on lines +72 to +86
func assertJSONLineMsg(t *testing.T, i int, line, wantMsg string) {
t.Helper()
if !strings.HasPrefix(line, "{") || !strings.HasSuffix(line, "}") {
t.Errorf("line %d is not valid single-object JSON: %q", i, line)
return
}
var rec struct {
Msg string `json:"msg"`
}
if err := json.Unmarshal([]byte(line), &rec); err != nil {
t.Errorf("line %d: json.Unmarshal: %v", i, err)
return
}
if rec.Msg != wantMsg {
t.Errorf("line %d msg = %q, want %q", i, rec.Msg, wantMsg)

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🎯 Functional Correctness | 🟡 Minor | ⚡ Quick win

Validate the blank record through the JSON helper.

The substring check can accept malformed output, while Msg string cannot distinguish a missing field from {"msg":""}. Make Msg a pointer (or validate the raw field), then call assertJSONLineMsg(t, 1, lines[1], "").

Proposed test hardening
 	var rec struct {
-		Msg string `json:"msg"`
+		Msg *string `json:"msg"`
 	}
 	if err := json.Unmarshal([]byte(line), &rec); err != nil {
 		t.Errorf("line %d: json.Unmarshal: %v", i, err)
 		return
 	}
-	if rec.Msg != wantMsg {
-		t.Errorf("line %d msg = %q, want %q", i, rec.Msg, wantMsg)
+	if rec.Msg == nil {
+		t.Errorf("line %d is missing msg", i)
+		return
+	}
+	if *rec.Msg != wantMsg {
+		t.Errorf("line %d msg = %q, want %q", i, *rec.Msg, wantMsg)
 	}
 
-	if !strings.Contains(lines[1], `"msg":""`) {
-		t.Errorf("line 1 = %q, want an empty msg field", lines[1])
-	}
+	assertJSONLineMsg(t, 1, lines[1], "")

Also applies to: 131-133

🤖 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 `@pkg/log/writer_test.go` around lines 72 - 86, Update assertJSONLineMsg to
distinguish a missing msg field from an explicit empty value by making the
decoded Msg field nullable or validating the raw JSON field, and reject missing
fields. Replace the separate substring assertion for the blank record with
assertJSONLineMsg(t, 1, lines[1], ""), including the corresponding assertion
path around the later blank-record check.

@skevetter
skevetter merged commit 6d4e72c into main Jul 29, 2026
113 of 115 checks passed
@skevetter
skevetter deleted the fix/log-writer-structured-output branch July 29, 2026 05:18
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant