Ensure that calls to standard logger `log.Println` also output JSON

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

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

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"))
+}

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 {

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