Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Zerolog in Context #507

Merged
merged 47 commits into from Jun 29, 2022
Merged
Show file tree
Hide file tree
Changes from 43 commits
Commits
Show all changes
47 commits
Select commit Hold shift + click to select a range
b10a13e
harvest log events
iamemilio Apr 25, 2022
9565130
added logging in context metrics
iamemilio May 9, 2022
8be7166
More Configurability and Testing
iamemilio May 10, 2022
2fdbfbf
Zerolog logs in context support
iamemilio May 24, 2022
cc5e7cc
RecordLog documentation
iamemilio May 24, 2022
6b7c071
Supportability Metrics
iamemilio May 26, 2022
22adddd
button up zerolog plugin
iamemilio May 26, 2022
514119b
correct config settings in readme and example
iamemilio May 26, 2022
d71870a
remove changes to short-lived-process-example
iamemilio May 26, 2022
96b4b58
stress-tests
iamemilio May 24, 2022
f0b6b53
dont use time.Now().UnixMillisecond() due to old versions of go not s…
iamemilio May 26, 2022
69e13d2
clean up the implementation of record logs to make it more user friendly
iamemilio May 27, 2022
c87eba3
clean up vet issues
iamemilio May 27, 2022
eaef803
priority inheretence
iamemilio May 27, 2022
d4806f8
fixing scale tests
iamemilio May 27, 2022
320057e
make the linter happy for logging constants
iamemilio May 27, 2022
bcf0c6e
some clean up
iamemilio May 28, 2022
317b6a0
remove scale tests
iamemilio May 31, 2022
6ffb77a
Async Log Event Support
iamemilio May 31, 2022
138d1bd
support timestamps on older go versions
iamemilio May 31, 2022
1d326f4
Safe Reads
iamemilio May 31, 2022
7f28d60
turns out that the synchronization is handled already
iamemilio May 31, 2022
3607461
avoid alloc when creating logEvent
iamemilio Jun 13, 2022
d33379f
improve efficiency of getting harvest data by avoiding memAlloc
iamemilio Jun 14, 2022
cbc801f
Revert "improve efficiency of getting harvest data by avoiding memAlloc"
iamemilio Jun 15, 2022
77fc73b
better benchmarks for log events
iamemilio Jun 15, 2022
e6083ed
more granular benchmarks for pinpointing json buffer writing runtime …
iamemilio Jun 15, 2022
5594e30
logging readme improved
iamemilio Jun 15, 2022
6cf172d
return go.mod to upstream
iamemilio Jun 16, 2022
2e6700e
remove comparison to write string
iamemilio Jun 16, 2022
0901501
group struct fields by type to avoid overallocation of contiguous memory
iamemilio Jun 17, 2022
f3b5b5b
piggyback log events on transactions to pool their priorities
iamemilio Jun 17, 2022
561ab2d
style update for zerolog in context
iamemilio Jun 21, 2022
900b6f4
if statements checking booleans simplified to just check value
iamemilio Jun 21, 2022
9660625
safeguard memory for transaction log events
iamemilio Jun 21, 2022
ace7225
made go vet happy :)
iamemilio Jun 21, 2022
458f9d0
autogenerate timestamps instead of failing
iamemilio Jun 21, 2022
6f02ca7
cleanup and testing for autotimestamps
iamemilio Jun 21, 2022
1f766f4
Fix Spelling mistakes
iamemilio Jun 23, 2022
814b1d6
simplify supportability for zerolog
iamemilio Jun 23, 2022
33f7217
a ConfigZerologEnabled() function call was separated from its heard
iamemilio Jun 23, 2022
d916ec5
app log trace id was set to span id
iamemilio Jun 28, 2022
92a4a37
Additional Testing covering Application Function Calls
iamemilio Jun 28, 2022
ad1a864
fix sample size selection for logging
iamemilio Jun 28, 2022
91ca115
cleaner server example
iamemilio Jun 28, 2022
d1385ff
make it more user friendly to record transaction logs
iamemilio Jun 28, 2022
f137814
background logs
iamemilio Jun 28, 2022
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
24 changes: 24 additions & 0 deletions v3/examples/server/main.go
Expand Up @@ -4,6 +4,7 @@
package main

import (
"context"
"errors"
"fmt"
"io"
Expand Down Expand Up @@ -251,6 +252,7 @@ func main() {
newrelic.ConfigAppName("Example App"),
newrelic.ConfigFromEnvironment(),
newrelic.ConfigDebugLogger(os.Stdout),
newrelic.ConfigAppLogForwardingEnabled(true),
)
if err != nil {
fmt.Println(err)
Expand All @@ -274,6 +276,28 @@ func main() {
http.HandleFunc(newrelic.WrapHandleFunc(app, "/browser", browser))
http.HandleFunc(newrelic.WrapHandleFunc(app, "/async", async))
http.HandleFunc(newrelic.WrapHandleFunc(app, "/message", message))
http.HandleFunc("/log", func(w http.ResponseWriter, req *http.Request) {
app.RecordLog(newrelic.LogData{
iamemilio marked this conversation as resolved.
Show resolved Hide resolved
Message: "Log Message",
Severity: "info",
})

io.WriteString(w, "A log message was recorded")
})

http.HandleFunc("/transaction_log", func(w http.ResponseWriter, req *http.Request) {
txn := app.StartTransaction("Log Transaction")
defer txn.End()
ctx := newrelic.NewContext(context.Background(), txn)

app.RecordLog(newrelic.LogData{
Message: "Transaction Log Message",
Severity: "info",
Context: ctx,
})

io.WriteString(w, "A log message was recorded as part of a transaction")
iamemilio marked this conversation as resolved.
Show resolved Hide resolved
})

http.HandleFunc("/background", func(w http.ResponseWriter, req *http.Request) {
// Transactions started without an http.Request are classified as
Expand Down
95 changes: 95 additions & 0 deletions v3/integrations/logcontext-v2/nrzerolog/Readme.md
@@ -0,0 +1,95 @@
# Zerolog In Context

This plugin for zerolog implements the logs in context tooling for the go agent. This hook
function can be added to any zerolog logger, and will automatically collect the log data
from zerolog, and send it to New Relic through the go agent. The following Logging features
are supported by this plugin in the current release:

| Logging Feature | Supported |
| ------- | --------- |
| Forwarding | :heavy_check_mark: |
| Metrics | :heavy_check_mark: |
| Enrichment | :x: |
Copy link
Contributor

Choose a reason for hiding this comment

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

I see span.id and trace.id being put on the log lines -- is there more enrichment that needs to be supported? Also, there are the three common attributes of entity GUID, entity name, and hostname.

Copy link
Contributor Author

@iamemilio iamemilio Jun 23, 2022

Choose a reason for hiding this comment

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

By enrichment, I mean that we do not support enriching the local logs that get printed to console in this release. We add all of the enrichments to the logs, including entity GUID, entity name, and hostname at harvest


## Installation

The nrzerolog plugin, and the go-agent need to be integrated into your code
in order to use this tool. Make sure to set `newrelic.ConfigAppLogForwardingEnabled(true)`
in your config settings for the application. This will enable log forwarding
in the go agent. If you want to disable metrics, set `newrelic.ConfigAppLogMetricsEnabled(false),`.
Note that the agent sets the default number of logs per harverst cycle to 10000, but that
number may be reduced by the server. You can manually set this number by setting
`newrelic.ConfigAppLogForwardingMaxSamplesStored(123),`.

The following example will shows how to install and set up your code to send logs to new relic from zerolog.

```go

import (
"github.com/rs/zerolog"
"github.com/newrelic/go-agent/v3/newrelic"
"github.com/newrelic/go-agent/v3/integrations/logcontext-v2/nrzerolog"
)

func main() {
// Initialize a zerolog logger
baseLogger := zerolog.New(os.Stdout)

app, err := newrelic.NewApplication(
newrelic.ConfigFromEnvironment(),
newrelic.ConfigAppName("NRZerolog Example"),
newrelic.ConfigInfoLogger(os.Stdout),
newrelic.ConfigAppLogForwarding(true),
)
if err != nil {
fmt.Println(err)
os.Exit(1)
}

// Send logs to New Relic outside of a transaction
nrHook := nrzerolog.NewRelicHook{
App: app,
}

// Wrap logger with New Relic Hook
nrLogger := baseLogger.Hook(nrHook)
nrLogger.Info().Msg("Hello World")

// Send logs to New Relic inside of a transaction
txn := app.StartTransaction("My Transaction")
ctx := newrelic.NewContext(context.Background(), txn)

nrTxnHook := nrzerolog.NewRelicHook{
App: app,
Context: ctx,
}

txnLogger := baseLogger.Hook(nrTxnHook)
txnLogger.Debug().Msg("This is a transaction log")

txn.End()
}
```

## Usage

Please enable the agent to ingest your logs by calling newrelic.ConfigAppLogForwardingEnabled(true),
when setting up your application. This is not enabled by default.

This integration for the zerolog logging frameworks uses a built in feature
of the zerolog framework called hook functions. Zerolog loggers can be modified
to have hook functions run on them before each time a write is executed. When a
logger is hooked, meaning a hook function was added to that logger with the Hook()
funciton, a copy of that logger is created with those changes. Note that zerolog
will *never* attempt to verify that any hook functions have not been not duplicated, or
that fields are not repeated in any way. As a result, we recommend that you create
a base logger that is configured in the way you prefer to use zerolog. Then you
create hooked loggers to send log data to New Relic from that base logger.

The plugin captures the log level, and the message from zerolog. It will also collect
distributed tracing data from your transaction context. At the moment the hook function is
called in zerolog, a timestamp will be generated for your log. In most cases, this
timestamp will be the same as the time posted in the zerolog log message, however it is possible that
there could be a slight offset depending on the the performance of your system.


53 changes: 53 additions & 0 deletions v3/integrations/logcontext-v2/nrzerolog/example/main.go
@@ -0,0 +1,53 @@
package main

import (
"context"
"fmt"
"os"
"time"

"github.com/newrelic/go-agent/v3/integrations/logcontext-v2/nrzerolog"
"github.com/newrelic/go-agent/v3/newrelic"
"github.com/rs/zerolog"
)

func main() {
baseLogger := zerolog.New(os.Stdout)

app, err := newrelic.NewApplication(
newrelic.ConfigFromEnvironment(),
newrelic.ConfigAppName("NRZerolog Example"),
newrelic.ConfigInfoLogger(os.Stdout),
newrelic.ConfigAppLogForwardingEnabled(true),
)
if err != nil {
fmt.Println(err)
os.Exit(1)
}

app.WaitForConnection(5 * time.Second)

nrHook := nrzerolog.NewRelicHook{
App: app,
}

nrLogger := baseLogger.Hook(nrHook)
nrLogger.Info().Msg("Hello World")

// With transaction context
txn := app.StartTransaction("My Transaction")
ctx := newrelic.NewContext(context.Background(), txn)

nrTxnHook := nrzerolog.NewRelicHook{
App: app,
Context: ctx,
}

txnLogger := baseLogger.Hook(nrTxnHook)
txnLogger.Debug().Msg("This is a transaction log")

txn.End()

nrLogger.Info().Msg("Goodbye")
app.Shutdown(10 * time.Second)
}
8 changes: 8 additions & 0 deletions v3/integrations/logcontext-v2/nrzerolog/go.mod
@@ -0,0 +1,8 @@
module github.com/newrelic/go-agent/v3/integrations/logcontext-v2/nrzerolog

go 1.15

require (
github.com/newrelic/go-agent/v3 v3.16.0
github.com/rs/zerolog v1.26.1
)
32 changes: 32 additions & 0 deletions v3/integrations/logcontext-v2/nrzerolog/hook.go
@@ -0,0 +1,32 @@
package nrzerolog

import (
"context"

"github.com/newrelic/go-agent/v3/internal"
"github.com/newrelic/go-agent/v3/newrelic"
"github.com/rs/zerolog"
)

func init() { internal.TrackUsage("integration", "logcontext", "zerolog") }

type NewRelicHook struct {
App *newrelic.Application
Context context.Context
}

func (h NewRelicHook) Run(e *zerolog.Event, level zerolog.Level, msg string) {
logLevel := ""
if level == zerolog.NoLevel {
logLevel = newrelic.LogSeverityUnknown
} else {
logLevel = level.String()
}
data := newrelic.LogData{
Severity: logLevel,
Message: msg,
Context: h.Context,
}

h.App.RecordLog(data)
}
2 changes: 2 additions & 0 deletions v3/internal/connect_reply.go
Expand Up @@ -118,6 +118,7 @@ type EventHarvestConfig struct {
Limits struct {
TxnEvents *uint `json:"analytic_event_data,omitempty"`
CustomEvents *uint `json:"custom_event_data,omitempty"`
LogEvents *uint `json:"log_event_data,omitempty"`
ErrorEvents *uint `json:"error_event_data,omitempty"`
SpanEvents *uint `json:"span_event_data,omitempty"`
} `json:"harvest_limits"`
Expand All @@ -141,6 +142,7 @@ func DefaultEventHarvestConfig(maxTxnEvents int) EventHarvestConfig {
cfg.ReportPeriodMs = DefaultConfigurableEventHarvestMs
cfg.Limits.TxnEvents = uintPtr(uint(maxTxnEvents))
cfg.Limits.CustomEvents = uintPtr(uint(MaxCustomEvents))
cfg.Limits.LogEvents = uintPtr(uint(MaxLogEvents))
cfg.Limits.ErrorEvents = uintPtr(uint(MaxErrorEvents))
return cfg
}
Expand Down
6 changes: 4 additions & 2 deletions v3/internal/connect_reply_test.go
Expand Up @@ -177,7 +177,9 @@ func TestDefaultEventHarvestConfigJSON(t *testing.T) {
if err != nil {
t.Error(err)
}
if string(js) != `{"report_period_ms":60000,"harvest_limits":{"analytic_event_data":10000,"custom_event_data":10000,"error_event_data":100}}` {
t.Error(string(js))

expect := `{"report_period_ms":60000,"harvest_limits":{"analytic_event_data":10000,"custom_event_data":10000,"log_event_data":10000,"error_event_data":100}}`
if string(js) != expect {
t.Errorf("DefaultEventHarvestConfig does not match expected valued:\nExpected:\t%s\nActual:\t\t%s", expect, string(js))
}
}
10 changes: 10 additions & 0 deletions v3/internal/expect.go
Expand Up @@ -26,6 +26,15 @@ type WantError struct {
AgentAttributes map[string]interface{}
}

// WantLog is a traced log event expectation
type WantLog struct {
Severity string
Message string
SpanID string
TraceID string
Timestamp int64
}

func uniquePointer() *struct{} {
s := struct{}{}
return &s
Expand Down Expand Up @@ -112,6 +121,7 @@ type WantTxn struct {
// captured.
type Expect interface {
ExpectCustomEvents(t Validator, want []WantEvent)
ExpectLogEvents(t Validator, want []WantLog)
ExpectErrors(t Validator, want []WantError)
ExpectErrorEvents(t Validator, want []WantEvent)

Expand Down
7 changes: 7 additions & 0 deletions v3/internal/integrationsupport/integrationsupport.go
Expand Up @@ -93,6 +93,13 @@ var DTEnabledCfgFn = func(cfg *newrelic.Config) {
cfg.DistributedTracer.Enabled = true
}

var AppLogEnabledCfgFn = func(cfg *newrelic.Config) {
cfg.Enabled = false
cfg.ApplicationLogging.Enabled = true
cfg.ApplicationLogging.Forwarding.Enabled = true
cfg.ApplicationLogging.Metrics.Enabled = true
}

// SampleEverythingReplyFn is a reusable ConnectReply function that samples everything
var SampleEverythingReplyFn = func(reply *internal.ConnectReply) {
reply.SetSampleEverything()
Expand Down
16 changes: 16 additions & 0 deletions v3/internal/jsonx/encode_test.go
Expand Up @@ -180,3 +180,19 @@ func TestAppendString(t *testing.T) {
}
}
}

func BenchmarkAppendString(b *testing.B) {
buf := &bytes.Buffer{}

for i := 0; i < b.N; i++ {
AppendString(buf, "s")
}
}

func BenchmarkAppendString10(b *testing.B) {
buf := &bytes.Buffer{}

for i := 0; i < b.N; i++ {
AppendString(buf, "qwertyuiop")
}
}
3 changes: 3 additions & 0 deletions v3/internal/limits.go
Expand Up @@ -17,6 +17,9 @@ const (
// MaxCustomEvents is the maximum number of Transaction Events that can be captured
// per 60-second harvest cycle
MaxCustomEvents = 10 * 1000
// MaxLogEvents is the maximum number of Log Events that can be captured per
// 60-second harvest cycle
MaxLogEvents = 10 * 1000
// MaxTxnEvents is the maximum number of Transaction Events that can be captured
// per 60-second harvest cycle
MaxTxnEvents = 10 * 1000
Expand Down
2 changes: 1 addition & 1 deletion v3/newrelic/analytics_events.go
Expand Up @@ -19,8 +19,8 @@ type analyticsEventHeap []analyticsEvent

type analyticsEvents struct {
numSeen int
events analyticsEventHeap
failedHarvests int
events analyticsEventHeap
}

func (events *analyticsEvents) NumSeen() float64 { return float64(events.numSeen) }
Expand Down
20 changes: 20 additions & 0 deletions v3/newrelic/app_run.go
Expand Up @@ -122,6 +122,7 @@ func newAppRun(config config, reply *internal.ConnectReply) *appRun {
MaxCustomEvents: run.MaxCustomEvents(),
MaxErrorEvents: run.MaxErrorEvents(),
MaxSpanEvents: run.MaxSpanEvents(),
LoggingConfig: run.LoggingConfig(),
}

return run
Expand Down Expand Up @@ -187,17 +188,35 @@ func (run *appRun) txnTraceThreshold(apdexThreshold time.Duration) time.Duration

func (run *appRun) ptrTxnEvents() *uint { return run.Reply.EventData.Limits.TxnEvents }
func (run *appRun) ptrCustomEvents() *uint { return run.Reply.EventData.Limits.CustomEvents }
func (run *appRun) ptrLogEvents() *uint { return run.Reply.EventData.Limits.LogEvents }
func (run *appRun) ptrErrorEvents() *uint { return run.Reply.EventData.Limits.ErrorEvents }
func (run *appRun) ptrSpanEvents() *uint { return run.Reply.EventData.Limits.SpanEvents }

func (run *appRun) MaxTxnEvents() int { return run.limit(run.Config.maxTxnEvents(), run.ptrTxnEvents) }
func (run *appRun) MaxCustomEvents() int {
return run.limit(internal.MaxCustomEvents, run.ptrCustomEvents)
}
func (run *appRun) MaxLogEvents() int {
return run.limit(internal.MaxLogEvents, run.ptrLogEvents)
}
func (run *appRun) MaxErrorEvents() int {
return run.limit(internal.MaxErrorEvents, run.ptrErrorEvents)
}

func (run *appRun) LoggingConfig() (config loggingConfig) {
logging := run.Config.ApplicationLogging

config.loggingEnabled = logging.Enabled
config.collectEvents = logging.Enabled && logging.Forwarding.Enabled && !run.Config.HighSecurity
config.maxLogEvents = run.MaxLogEvents()
config.collectMetrics = logging.Enabled && logging.Metrics.Enabled

//TODO
config.localEnrichment = false

return config
}

// MaxSpanEvents returns the reservoir limit for collected span events,
// which will be the default or the user's configured size (if any), but
// may be capped to the maximum allowed by the collector.
Expand All @@ -219,6 +238,7 @@ func (run *appRun) ReportPeriods() map[harvestTypes]time.Duration {
for tp, fn := range map[harvestTypes]func() *uint{
harvestTxnEvents: run.ptrTxnEvents,
harvestCustomEvents: run.ptrCustomEvents,
harvestLogEvents: run.ptrLogEvents,
harvestErrorEvents: run.ptrErrorEvents,
harvestSpanEvents: run.ptrSpanEvents,
} {
Expand Down