newrelic / go-agent

New Relic Go Agent
Apache License 2.0
775 stars 295 forks source link

zerolog-writer.go panics when message has "," (and/or a combination of escaped `"`) as the last character(s) #955

Closed MarioCarrion closed 1 month ago

MarioCarrion commented 2 months ago

Description

go-agent panics when message has , (or a escaped ") as the last character(s)

Steps to Reproduce

The easiest way to reproduce is to use a message like the following:

zerolog.Ctx(ctx).Info().Msg("\"value\",")

Also notice the diff for the tests (listed below) has a test cases using only , and still panics.

Expected Behavior

Does not panic

NR Diag results

This is the normal output we get when serving the app, but below there's a shorter log that uses the diff:

| 2024/08/27 16:06:22 goroutine 2178 [running]:
| runtime/debug.Stack()
|   /usr/local/go/src/runtime/debug/stack.go:24 +0x5e
| github.com/newrelic/go-agent/v3/newrelic.(*thread).End(0xc000117470, {0x13cc040, 0xc000166db0})
|   /go/pkg/mod/github.com/newrelic/go-agent/v3@v3.33.1/newrelic/internal_txn.go:452 +0x22b
| github.com/newrelic/go-agent/v3/newrelic.(*Transaction).End(0xc00081c498)
|   /go/pkg/mod/github.com/newrelic/go-agent/v3@v3.33.1/newrelic/transaction.go:48 +0x1a9
| panic({0x13cc040?, 0xc000166db0?})
|   /usr/local/go/src/runtime/panic.go:770 +0x132
| github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter.isStringValue(...)
|   /go/pkg/mod/github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerolog!writer@v1.0.2/zerolog-writer.go:93
| github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter.parseJSONLogData({0xc00078c000, 0x1bc, 0x580})
|   /go/pkg/mod/github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerolog!writer@v1.0.2/zerolog-writer.go:74 +0x354
| github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter.ZerologWriter.Write({{0x0, {0x16bae00, 0xc000118020}, 0xc000432030, 0xc00081c498}}, {0xc00078c000, 0x1bc, 0x580})
|   /go/pkg/mod/github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerolog!writer@v1.0.2/zerolog-writer.go:47 +0x67
| github.com/rs/zerolog.LevelWriterAdapter.WriteLevel(...)
|   /go/pkg/mod/github.com/rs/zerolog@v1.33.0/writer.go:27
| github.com/rs/zerolog.(*Event).write(0xc00021e620)
|   /go/pkg/mod/github.com/rs/zerolog@v1.33.0/event.go:80 +0x103
| github.com/rs/zerolog.(*Event).msg(0xc00021e620, {0xc00035c1c0, 0xda})
|   /go/pkg/mod/github.com/rs/zerolog@v1.33.0/event.go:151 +0x21a
| github.com/rs/zerolog.(*Event).Msgf(0xc00021e620, {0x14a7cee?, 0x0?}, {0xc000eeb280?, 0x7e?, 0xc1ab9c3fb3fbec7d?})
|   /go/pkg/mod/github.com/rs/zerolog@v1.33.0/event.go:131 +0x46
| <proprietary code starts here>

Your Environment

N/A

Reproduction case

Here's a diff demonstrating the issue using the existing test cases:

diff --git a/v3/integrations/logcontext-v2/zerologWriter/zerolog-writer_test.go b/v3/integrations/logcontext-v2/zerologWriter/zerolog-writer_test.go
index ab0a2f97..2a92c570 100644
--- a/v3/integrations/logcontext-v2/zerologWriter/zerolog-writer_test.go
+++ b/v3/integrations/logcontext-v2/zerologWriter/zerolog-writer_test.go
@@ -123,6 +123,22 @@ func TestParseLogData(t *testing.T) {
                Severity: "debug",
            },
        },
+       {
+           `{"level":"info",message":"\"value\","}` + "\n",
+           "level",
+           newrelic.LogData{
+               Message:  `{"level":"info",message":"\"value\","}` + "\n",
+               Severity: "info",
+           },
+       },
+       {
+           `{"level":"info",message":","}` + "\n",
+           "level",
+           newrelic.LogData{
+               Message:  `{"level":"info",message":","}` + "\n",
+               Severity: "info",
+           },
+       },
    }
    for _, test := range tests {
        if test.levelKey != "" {

Log output:

go test -v ./...
?       github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter/example    [no test files]
=== RUN   TestParseLogData
--- FAIL: TestParseLogData (0.00s)
panic: runtime error: index out of range [-1] [recovered]
    panic: runtime error: index out of range [-1]

goroutine 21 [running]:
testing.tRunner.func1.2({0x10119e020, 0x140000de8a0})
    /opt/homebrew/Cellar/go/1.22.5/libexec/src/testing/testing.go:1631 +0x1c4
testing.tRunner.func1()
    /opt/homebrew/Cellar/go/1.22.5/libexec/src/testing/testing.go:1634 +0x33c
panic({0x10119e020?, 0x140000de8a0?})
    /opt/homebrew/Cellar/go/1.22.5/libexec/src/runtime/panic.go:770 +0x124
github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter.isStringValue(...)
    /Users/mario/Repositories/github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter/zerolog-writer.go:93
github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter.parseJSONLogData({0x100fc1788, 0x27, 0x27})
    /Users/mario/Repositories/github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter/zerolog-writer.go:74 +0x2a8
github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter.TestParseLogData(0x140000e4d00)
    /Users/mario/Repositories/github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter/zerolog-writer_test.go:147 +0x104
testing.tRunner(0x140000e4d00, 0x1011e3620)
    /opt/homebrew/Cellar/go/1.22.5/libexec/src/testing/testing.go:1689 +0xec
created by testing.(*T).Run in goroutine 1
    /opt/homebrew/Cellar/go/1.22.5/libexec/src/testing/testing.go:1742 +0x318
FAIL    github.com/newrelic/go-agent/v3/integrations/logcontext-v2/zerologWriter    0.466s
FAIL

Additional context

Maybe be related to: https://github.com/newrelic/go-agent/issues/583 ?

iamemilio commented 2 months ago

A bug to track this has been filed internally, thank you for reporting and providing so many reproducers!

iamemilio commented 1 month ago

This will be in the next release

MarioCarrion commented 1 month ago

Thanks for the update @iamemilio

nr-swilloughby commented 1 month ago

Fixed in 3.35.0