diff --git a/docs/releases.md b/docs/releases.md
index 17c24308..491f90b5 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 0dd4be07..4ab04399 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 c4934f05..7c0f9cdc 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 b0164944..0d1ec4af 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 4588614b..4853dabd 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