From 9ff3bb0c87ff352ad4962416e9f42c31dd3e3fc0 Mon Sep 17 00:00:00 2001 From: binwiederhier Date: Fri, 17 Feb 2023 20:52:48 -0500 Subject: [PATCH] Ensure that calls to standard logger `log.Println` also output JSON --- docs/releases.md | 1 + log/event.go | 31 +++++++++++++++++++------------ log/log.go | 48 +++++++++++++++++++++++++++++++++++++----------- log/log_test.go | 48 ++++++++++++++++++++++++++++++++++++++++++++++++ server/server.go | 4 ++-- 5 files changed, 107 insertions(+), 25 deletions(-) diff --git a/docs/releases.md b/docs/releases.md index 17c2430..491f90b 100644 --- a/docs/releases.md +++ b/docs/releases.md @@ -7,6 +7,7 @@ and the [ntfy Android app](https://github.com/binwiederhier/ntfy-android/release **Bug fixes + maintenance:** * Avoid panic in manager when `attachment-cache-dir` is not set ([#617](https://github.com/binwiederhier/ntfy/issues/617), thanks to [@ksurl](https://github.com/ksurl)) +* Ensure that calls to standard logger `log.Println` also output JSON (no ticket) ## ntfy server v2.0.0 Released February 16, 2023 diff --git a/log/event.go b/log/event.go index 0dd4be0..4ab0439 100644 --- a/log/event.go +++ b/log/event.go @@ -11,10 +11,11 @@ import ( ) const ( - tagField = "tag" - errorField = "error" - timeTakenField = "time_taken_ms" - exitCodeField = "exit_code" + fieldTag = "tag" + fieldError = "error" + fieldTimeTaken = "time_taken_ms" + fieldExitCode = "exit_code" + tagStdLog = "stdlog" timestampFormat = "2006-01-02T15:04:05.999Z07:00" ) @@ -40,7 +41,7 @@ func newEvent() *Event { // Fatal logs the event as FATAL, and exits the program with exit code 1 func (e *Event) Fatal(message string, v ...any) { - e.Field(exitCodeField, 1).maybeLog(FatalLevel, message, v...) + e.Field(fieldExitCode, 1).maybeLog(FatalLevel, message, v...) fmt.Fprintf(os.Stderr, message+"\n", v...) // Always output error to stderr os.Exit(1) } @@ -72,7 +73,7 @@ func (e *Event) Trace(message string, v ...any) { // Tag adds a "tag" field to the log event func (e *Event) Tag(tag string) *Event { - return e.Field(tagField, tag) + return e.Field(fieldTag, tag) } // Time sets the time field @@ -85,7 +86,7 @@ func (e *Event) Time(t time.Time) *Event { func (e *Event) Timing(f func()) *Event { start := time.Now() f() - return e.Field(timeTakenField, time.Since(start).Milliseconds()) + return e.Field(fieldTimeTaken, time.Since(start).Milliseconds()) } // Err adds an "error" field to the log event @@ -95,7 +96,7 @@ func (e *Event) Err(err error) *Event { } else if c, ok := err.(Contexter); ok { return e.With(c) } - return e.Field(errorField, err.Error()) + return e.Field(fieldError, err.Error()) } // Field adds a custom field and value to the log event @@ -136,9 +137,16 @@ func (e *Event) With(contexts ...Contexter) *Event { // is actually logged. If overrides are defined, then Contexters have to be applied in any case // to determine if they match. This is super complicated, but required for efficiency. func (e *Event) maybeLog(l Level, message string, v ...any) { + m := e.Render(l, message, v...) + if m != "" { + log.Println(m) + } +} + +func (e *Event) Render(l Level, message string, v ...any) string { appliedContexters := e.maybeApplyContexters() if !e.shouldLog(l) { - return + return "" } e.Message = fmt.Sprintf(message, v...) e.Level = l @@ -147,10 +155,9 @@ func (e *Event) maybeLog(l Level, message string, v ...any) { e.applyContexters() } if CurrentFormat() == JSONFormat { - log.Println(e.JSON()) - } else { - log.Println(e.String()) + return e.JSON() } + return e.String() } // Loggable returns true if the given log level is lower or equal to the current log level diff --git a/log/log.go b/log/log.go index c4934f0..7c0f9cd 100644 --- a/log/log.go +++ b/log/log.go @@ -4,6 +4,7 @@ import ( "io" "log" "os" + "strings" "sync" "time" ) @@ -12,7 +13,7 @@ import ( var ( DefaultLevel = InfoLevel DefaultFormat = TextFormat - DefaultOutput = os.Stderr + DefaultOutput = &peekLogWriter{os.Stderr} ) var ( @@ -20,9 +21,18 @@ var ( format = DefaultFormat overrides = make(map[string]*levelOverride) output io.Writer = DefaultOutput + filename = "" mu = &sync.RWMutex{} ) +// init sets the default log output (including log.SetOutput) +// +// This has to be explicitly called, because DefaultOutput is a peekLogWriter, +// which wraps os.Stderr. +func init() { + SetOutput(DefaultOutput) +} + // Fatal prints the given message, and exits the program func Fatal(message string, v ...any) { newEvent().Fatal(message, v...) @@ -132,28 +142,27 @@ func SetFormat(newFormat Format) { func SetOutput(w io.Writer) { mu.Lock() defer mu.Unlock() - log.SetOutput(w) - output = w + output = &peekLogWriter{w} + if f, ok := w.(*os.File); ok { + filename = f.Name() + } else { + filename = "" + } + log.SetOutput(output) } // File returns the log file, if any, or an empty string otherwise func File() string { mu.RLock() defer mu.RUnlock() - if f, ok := output.(*os.File); ok { - return f.Name() - } - return "" + return filename } // IsFile returns true if the output is a non-default file func IsFile() bool { mu.RLock() defer mu.RUnlock() - if _, ok := output.(*os.File); ok && output != DefaultOutput { - return true - } - return false + return filename != "" } // DisableDates disables the date/time prefix @@ -175,3 +184,20 @@ func IsTrace() bool { func IsDebug() bool { return Loggable(DebugLevel) } + +// peekLogWriter is an io.Writer which will peek at the rendered log event, +// and ensure that the rendered output is valid JSON. This is a hack! +type peekLogWriter struct { + w io.Writer +} + +func (w *peekLogWriter) Write(p []byte) (n int, err error) { + if len(p) == 0 || p[0] == '{' || CurrentFormat() == TextFormat { + return w.w.Write(p) + } + m := newEvent().Tag(tagStdLog).Render(InfoLevel, strings.TrimSpace(string(p))) + if m == "" { + return 0, nil + } + return w.w.Write([]byte(m + "\n")) +} diff --git a/log/log_test.go b/log/log_test.go index b016494..0d1ec4a 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -4,7 +4,10 @@ import ( "bytes" "encoding/json" "github.com/stretchr/testify/require" + "io" + "log" "os" + "path/filepath" "testing" "time" ) @@ -170,6 +173,51 @@ func TestLog_LevelOverrideAny(t *testing.T) { {"time":"1970-01-01T00:00:14Z","level":"INFO","message":"this is also logged","time_taken_ms":0} ` require.Equal(t, expected, out.String()) + require.False(t, IsFile()) + require.Equal(t, "", File()) +} + +func TestLog_UsingStdLogger_JSON(t *testing.T) { + t.Cleanup(resetState) + + var out bytes.Buffer + SetOutput(&out) + SetFormat(JSONFormat) + + log.Println("Some other library is using the standard Go logger") + require.Contains(t, out.String(), `,"level":"INFO","message":"Some other library is using the standard Go logger","tag":"stdlog"}`+"\n") +} + +func TestLog_UsingStdLogger_Text(t *testing.T) { + t.Cleanup(resetState) + + var out bytes.Buffer + SetOutput(&out) + + log.Println("Some other library is using the standard Go logger") + require.Contains(t, out.String(), `Some other library is using the standard Go logger`+"\n") + require.NotContains(t, out.String(), `{`) +} + +func TestLog_File(t *testing.T) { + t.Cleanup(resetState) + + logfile := filepath.Join(t.TempDir(), "ntfy.log") + f, err := os.OpenFile(logfile, os.O_CREATE|os.O_WRONLY, 0600) + require.Nil(t, err) + SetOutput(f) + SetFormat(JSONFormat) + require.True(t, IsFile()) + require.Equal(t, logfile, File()) + + Time(time.Unix(11, 0).UTC()).Field("this_one", "11").Info("this is logged") + require.Nil(t, f.Close()) + + f, err = os.Open(logfile) + require.Nil(t, err) + contents, err := io.ReadAll(f) + require.Nil(t, err) + require.Equal(t, `{"time":"1970-01-01T00:00:11Z","level":"INFO","message":"this is logged","this_one":"11"}`+"\n", string(contents)) } type fakeError struct { diff --git a/server/server.go b/server/server.go index 4588614..4853dab 100644 --- a/server/server.go +++ b/server/server.go @@ -333,9 +333,9 @@ func (s *Server) handleError(w http.ResponseWriter, r *http.Request, v *visitor, return } if isNormalError { - logvr(v, r).Err(httpErr).Debug("Connection closed with HTTP %d (ntfy error %d)", httpErr.HTTPCode, httpErr.Code) + logvr(v, r).Err(err).Debug("Connection closed with HTTP %d (ntfy error %d)", httpErr.HTTPCode, httpErr.Code) } else { - logvr(v, r).Err(httpErr).Info("Connection closed with HTTP %d (ntfy error %d)", httpErr.HTTPCode, httpErr.Code) + logvr(v, r).Err(err).Info("Connection closed with HTTP %d (ntfy error %d)", httpErr.HTTPCode, httpErr.Code) } w.Header().Set("Content-Type", "application/json") w.Header().Set("Access-Control-Allow-Origin", s.config.AccessControlAllowOrigin) // CORS, allow cross-origin requests