Skip to content

Fix ToSlogHandler duplicating time and level in output - #30

Merged
umputun merged 1 commit into
masterfrom
fix-slog-handler-duplication
Mar 23, 2026
Merged

Fix ToSlogHandler duplicating time and level in output#30
umputun merged 1 commit into
masterfrom
fix-slog-handler-duplication

Conversation

@umputun

@umputun umputun commented Mar 23, 2026

Copy link
Copy Markdown
Member

Fix lgrSlogHandler.Handle() prepending its own timestamp and level to the message before passing to lgr.Logf, which adds its own formatting — resulting in doubled time and level in output. Closes #29

  • Remove redundant time construction from Handle(), keep level prefix for lgr's extractLevel detection
  • Add TestSlogHandlerNoDuplication verifying INFO/DEBUG levels and timestamp appear exactly once
  • Fix existing test assertions to match correct lgr output format (padded levels)
  • Fix Go version in CLAUDE.md (1.20 to 1.21 per go.mod)

lgrSlogHandler.Handle() was prepending its own timestamp and level
to the message before passing to lgr.Logf, which adds its own
formatting. Remove redundant time construction, keep level prefix
for lgr's extractLevel detection.
Copilot AI review requested due to automatic review settings March 23, 2026 01:04
@umputun
umputun merged commit ecca49c into master Mar 23, 2026
7 of 9 checks passed
@umputun
umputun deleted the fix-slog-handler-duplication branch March 23, 2026 01:05

Copilot AI 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.

Pull request overview

Fixes ToSlogHandler output duplication by preventing lgrSlogHandler.Handle() from injecting its own timestamp/level formatting before delegating to lgr.Logf, and updates/extends tests to validate the corrected output format.

Changes:

  • Remove redundant timestamp construction from lgrSlogHandler.Handle() to avoid double time/level in output.
  • Update slog integration tests for padded level formatting and add a new no-duplication test.
  • Add CLAUDE.md development guidelines (notably Go 1.21).

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 2 comments.

File Description
slog.go Removes timestamp prefixing in Handle() and adjusts how the message is composed before calling Logf.
slog_test.go Updates assertions for padded INFO/WARN, adds TestSlogHandlerNoDuplication, and adjusts TRACE-level test setup/record creation.
CLAUDE.md Adds repository development guidelines reflecting Go 1.21 and local conventions.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread slog.go
logMsg := fmt.Sprintf("%s%s %s%s", timeStr, level, msg, attrs.String())
// combine level prefix and message; lgr.Logf adds its own timestamp and level formatting
logMsg := fmt.Sprintf("%s %s%s", level, msg, attrs.String())
h.lgr.Logf(logMsg)

Copilot AI Mar 23, 2026

Copy link

Choose a reason for hiding this comment

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

Handle passes the fully formatted logMsg as the format string to h.lgr.Logf(logMsg). For lgr.L implementations that delegate to fmt.Printf/log.Printf (e.g. lgr.Std), any % in the slog message or attribute values will be interpreted as formatting verbs, corrupting output (and can emit %! artifacts). Prefer calling Logf with a constant format (e.g., h.lgr.Logf("%s", logMsg)) so messages are treated as data, not a format string.

Suggested change
h.lgr.Logf(logMsg)
h.lgr.Logf("%s", logMsg)

Copilot uses AI. Check for mistakes.
Comment thread slog_test.go
Comment on lines +71 to +72
// must not contain INFO for a debug message
assert.NotContains(t, line, "INFO")

Copilot AI Mar 23, 2026

Copy link

Choose a reason for hiding this comment

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

The duplication assertions use substring counting / NotContains on the entire log line (e.g., strings.Count(line, "INFO")). This can produce false failures if the message or attribute values legitimately contain the same token (e.g., value contains "INFO" or "DEBUG"). Consider asserting on the structured prefix instead (regex anchored to the start, or stripping the initial timestamp+level and then checking the remainder doesn’t start with another timestamp/level).

Suggested change
// must not contain INFO for a debug message
assert.NotContains(t, line, "INFO")
// ensure the structured prefix has DEBUG as the level (and not INFO)
levelRe := regexp.MustCompile(`^\d{4}/\d{2}/\d{2}.*\bDEBUG\b`)
assert.True(t, levelRe.MatchString(line), "expected DEBUG level in structured prefix, got: %s", line)

Copilot uses AI. Check for mistakes.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

slog.Logger duplicates time & level

2 participants