From 19784e381bfe6e0aa44cd03928e0ce74edda14eb Mon Sep 17 00:00:00 2001 From: kim Date: Sun, 7 Sep 2025 14:47:45 +0200 Subject: [PATCH] [performance] more logging tweaks (#4415) - reduces number of necessary function calls by moving log level checking out of the uninlineable `logf(...)` function and into each of its caller (which are all inlined). this in turn means the log level check is performed in-situ wherever a call to `log.Debug(...)` (etc) is made, reduce unnecessary calls when a certain log level is disabled. - sets the http.Server{}.ErrorLog to output to our internal logging package (which in turn ensures it gets wrapped in either our logfmt or json log formatting) Reviewed-on: https://codeberg.org/superseriousbusiness/gotosocial/pulls/4415 Co-authored-by: kim Co-committed-by: kim --- internal/log/entry.go | 42 ++++++++++++++++++ internal/log/log.go | 89 ++++++++++++++++++++++++++++++++++++--- internal/log/log_test.go | 89 +++++++++++++++++++++++++++++++++++++++ internal/log/std.go | 43 +++++++++++++++++++ internal/router/router.go | 7 ++- 5 files changed, 263 insertions(+), 7 deletions(-) create mode 100644 internal/log/log_test.go create mode 100644 internal/log/std.go diff --git a/internal/log/entry.go b/internal/log/entry.go index 5b18ddf0f..efbae8478 100644 --- a/internal/log/entry.go +++ b/internal/log/entry.go @@ -49,51 +49,81 @@ func (e Entry) WithFields(kvs ...kv.Field) Entry { // Trace will log formatted args as 'msg' field to the log at TRACE level. func (e Entry) Trace(a ...interface{}) { + if TRACE > loglvl { + return + } logf(e.ctx, TRACE, e.kvs, "", a...) } // Tracef will log format string as 'msg' field to the log at TRACE level. func (e Entry) Tracef(s string, a ...interface{}) { + if TRACE > loglvl { + return + } logf(e.ctx, TRACE, e.kvs, s, a...) } // Debug will log formatted args as 'msg' field to the log at DEBUG level. func (e Entry) Debug(a ...interface{}) { + if DEBUG > loglvl { + return + } logf(e.ctx, DEBUG, e.kvs, "", a...) } // Debugf will log format string as 'msg' field to the log at DEBUG level. func (e Entry) Debugf(s string, a ...interface{}) { + if DEBUG > loglvl { + return + } logf(e.ctx, DEBUG, e.kvs, s, a...) } // Info will log formatted args as 'msg' field to the log at INFO level. func (e Entry) Info(a ...interface{}) { + if INFO > loglvl { + return + } logf(e.ctx, INFO, e.kvs, "", a...) } // Infof will log format string as 'msg' field to the log at INFO level. func (e Entry) Infof(s string, a ...interface{}) { + if INFO > loglvl { + return + } logf(e.ctx, INFO, e.kvs, s, a...) } // Warn will log formatted args as 'msg' field to the log at WARN level. func (e Entry) Warn(a ...interface{}) { + if WARN > loglvl { + return + } logf(e.ctx, WARN, e.kvs, "", a...) } // Warnf will log format string as 'msg' field to the log at WARN level. func (e Entry) Warnf(s string, a ...interface{}) { + if WARN > loglvl { + return + } logf(e.ctx, WARN, e.kvs, s, a...) } // Error will log formatted args as 'msg' field to the log at ERROR level. func (e Entry) Error(a ...interface{}) { + if ERROR > loglvl { + return + } logf(e.ctx, ERROR, e.kvs, "", a...) } // Errorf will log format string as 'msg' field to the log at ERROR level. func (e Entry) Errorf(s string, a ...interface{}) { + if ERROR > loglvl { + return + } logf(e.ctx, ERROR, e.kvs, s, a...) } @@ -101,6 +131,9 @@ func (e Entry) Errorf(s string, a ...interface{}) { // This will then call panic causing the application to crash. func (e Entry) Panic(a ...interface{}) { defer panic(fmt.Sprint(a...)) + if PANIC > loglvl { + return + } logf(e.ctx, PANIC, e.kvs, "", a...) } @@ -108,16 +141,25 @@ func (e Entry) Panic(a ...interface{}) { // This will then call panic causing the application to crash. func (e Entry) Panicf(s string, a ...interface{}) { defer panic(fmt.Sprintf(s, a...)) + if PANIC > loglvl { + return + } logf(e.ctx, PANIC, e.kvs, s, a...) } // Log will log formatted args as 'msg' field to the log at given level. func (e Entry) Log(lvl LEVEL, a ...interface{}) { + if lvl > loglvl { + return + } logf(e.ctx, lvl, e.kvs, "", a...) } // Logf will log format string as 'msg' field to the log at given level. func (e Entry) Logf(lvl LEVEL, s string, a ...interface{}) { + if lvl > loglvl { + return + } logf(e.ctx, lvl, e.kvs, s, a...) } diff --git a/internal/log/log.go b/internal/log/log.go index 50236db6e..8be846945 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -112,101 +112,161 @@ func WithFields(fields ...kv.Field) Entry { // Trace will log formatted args as 'msg' field to the log at TRACE level. func Trace(ctx context.Context, a ...interface{}) { + if TRACE > loglvl { + return + } logf(ctx, TRACE, nil, "", a...) } // Tracef will log format string as 'msg' field to the log at TRACE level. func Tracef(ctx context.Context, s string, a ...interface{}) { + if TRACE > loglvl { + return + } logf(ctx, TRACE, nil, s, a...) } // TraceKV will log the one key-value field to the log at TRACE level. func TraceKV(ctx context.Context, key string, value interface{}) { + if TRACE > loglvl { + return + } logf(ctx, TRACE, []kv.Field{{K: key, V: value}}, "") } // TraceKVs will log key-value fields to the log at TRACE level. func TraceKVs(ctx context.Context, kvs ...kv.Field) { + if TRACE > loglvl { + return + } logf(ctx, TRACE, kvs, "") } // Debug will log formatted args as 'msg' field to the log at DEBUG level. func Debug(ctx context.Context, a ...interface{}) { + if DEBUG > loglvl { + return + } logf(ctx, DEBUG, nil, "", a...) } // Debugf will log format string as 'msg' field to the log at DEBUG level. func Debugf(ctx context.Context, s string, a ...interface{}) { + if DEBUG > loglvl { + return + } logf(ctx, DEBUG, nil, s, a...) } // DebugKV will log the one key-value field to the log at DEBUG level. func DebugKV(ctx context.Context, key string, value interface{}) { + if DEBUG > loglvl { + return + } logf(ctx, DEBUG, []kv.Field{{K: key, V: value}}, "") } // DebugKVs will log key-value fields to the log at DEBUG level. func DebugKVs(ctx context.Context, kvs ...kv.Field) { + if DEBUG > loglvl { + return + } logf(ctx, DEBUG, kvs, "") } // Info will log formatted args as 'msg' field to the log at INFO level. func Info(ctx context.Context, a ...interface{}) { + if INFO > loglvl { + return + } logf(ctx, INFO, nil, "", a...) } // Infof will log format string as 'msg' field to the log at INFO level. func Infof(ctx context.Context, s string, a ...interface{}) { + if INFO > loglvl { + return + } logf(ctx, INFO, nil, s, a...) } // InfoKV will log the one key-value field to the log at INFO level. func InfoKV(ctx context.Context, key string, value interface{}) { + if INFO > loglvl { + return + } logf(ctx, INFO, []kv.Field{{K: key, V: value}}, "") } // InfoKVs will log key-value fields to the log at INFO level. func InfoKVs(ctx context.Context, kvs ...kv.Field) { + if INFO > loglvl { + return + } logf(ctx, INFO, kvs, "") } // Warn will log formatted args as 'msg' field to the log at WARN level. func Warn(ctx context.Context, a ...interface{}) { + if WARN > loglvl { + return + } logf(ctx, WARN, nil, "", a...) } // Warnf will log format string as 'msg' field to the log at WARN level. func Warnf(ctx context.Context, s string, a ...interface{}) { + if WARN > loglvl { + return + } logf(ctx, WARN, nil, s, a...) } // WarnKV will log the one key-value field to the log at WARN level. func WarnKV(ctx context.Context, key string, value interface{}) { + if WARN > loglvl { + return + } logf(ctx, WARN, []kv.Field{{K: key, V: value}}, "") } // WarnKVs will log key-value fields to the log at WARN level. func WarnKVs(ctx context.Context, kvs ...kv.Field) { + if WARN > loglvl { + return + } logf(ctx, WARN, kvs, "") } // Error will log formatted args as 'msg' field to the log at ERROR level. func Error(ctx context.Context, a ...interface{}) { + if ERROR > loglvl { + return + } logf(ctx, ERROR, nil, "", a...) } // Errorf will log format string as 'msg' field to the log at ERROR level. func Errorf(ctx context.Context, s string, a ...interface{}) { + if ERROR > loglvl { + return + } logf(ctx, ERROR, nil, s, a...) } // ErrorKV will log the one key-value field to the log at ERROR level. func ErrorKV(ctx context.Context, key string, value interface{}) { + if ERROR > loglvl { + return + } logf(ctx, ERROR, []kv.Field{{K: key, V: value}}, "") } // ErrorKVs will log key-value fields to the log at ERROR level. func ErrorKVs(ctx context.Context, kvs ...kv.Field) { + if ERROR > loglvl { + return + } logf(ctx, ERROR, kvs, "") } @@ -214,6 +274,9 @@ func ErrorKVs(ctx context.Context, kvs ...kv.Field) { // This will then call panic causing the application to crash. func Panic(ctx context.Context, a ...interface{}) { defer panic(fmt.Sprint(a...)) + if PANIC > loglvl { + return + } logf(ctx, PANIC, nil, "", a...) } @@ -221,6 +284,9 @@ func Panic(ctx context.Context, a ...interface{}) { // This will then call panic causing the application to crash. func Panicf(ctx context.Context, s string, a ...interface{}) { defer panic(fmt.Sprintf(s, a...)) + if PANIC > loglvl { + return + } logf(ctx, PANIC, nil, s, a...) } @@ -228,6 +294,9 @@ func Panicf(ctx context.Context, s string, a ...interface{}) { // This will then call panic causing the application to crash. func PanicKV(ctx context.Context, key string, value interface{}) { defer panic(kv.Field{K: key, V: value}.String()) + if PANIC > loglvl { + return + } logf(ctx, PANIC, []kv.Field{{K: key, V: value}}, "") } @@ -235,26 +304,41 @@ func PanicKV(ctx context.Context, key string, value interface{}) { // This will then call panic causing the application to crash. func PanicKVs(ctx context.Context, kvs ...kv.Field) { defer panic(kv.Fields(kvs).String()) + if PANIC > loglvl { + return + } logf(ctx, PANIC, kvs, "") } // Log will log formatted args as 'msg' field to the log at given level. func Log(ctx context.Context, lvl LEVEL, a ...interface{}) { //nolint:revive + if lvl > loglvl { + return + } logf(ctx, lvl, nil, "", a...) } // Logf will log format string as 'msg' field to the log at given level. func Logf(ctx context.Context, lvl LEVEL, s string, a ...interface{}) { //nolint:revive + if lvl > loglvl { + return + } logf(ctx, lvl, nil, s, a...) } // LogKV will log the one key-value field to the log at given level. func LogKV(ctx context.Context, lvl LEVEL, key string, value interface{}) { //nolint:revive + if lvl > loglvl { + return + } logf(ctx, lvl, []kv.Field{{K: key, V: value}}, "") } // LogKVs will log key-value fields to the log at given level. func LogKVs(ctx context.Context, lvl LEVEL, kvs ...kv.Field) { //nolint:revive + if lvl > loglvl { + return + } logf(ctx, lvl, kvs, "") } @@ -272,11 +356,6 @@ func Printf(s string, a ...interface{}) { func logf(ctx context.Context, lvl LEVEL, fields []kv.Field, msg string, args ...interface{}) { var out *os.File - // Check if enabled. - if lvl > loglvl { - return - } - // Split errors to stderr, // all else goes to stdout. if lvl <= ERROR { diff --git a/internal/log/log_test.go b/internal/log/log_test.go new file mode 100644 index 000000000..40f6420a4 --- /dev/null +++ b/internal/log/log_test.go @@ -0,0 +1,89 @@ +// GoToSocial +// Copyright (C) GoToSocial Authors admin@gotosocial.org +// SPDX-License-Identifier: AGPL-3.0-or-later +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU Affero General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Affero General Public License for more details. +// +// You should have received a copy of the GNU Affero General Public License +// along with this program. If not, see . + +package log_test + +import ( + "testing" + + "code.superseriousbusiness.org/gotosocial/internal/log" + "codeberg.org/gruf/go-kv/v2" +) + +func TestInlineability(t *testing.T) { + t.Skip() + + // to check the output of this run: + // go test -gcflags=all='-m=2' ./internal/log/ -run=TestInlineability 2>&1 | grep 'internal/log/log_test.go.*cannot inline' + // + // the output should not include any + // of the below log package func calls. + + ctx := t.Context() + const s = "hello world" + + log.Debug(ctx, s) + log.Debugf(ctx, s) + log.DebugKV(ctx, "key", s) + log.DebugKVs(ctx, kv.Fields{{K: "key", V: s}}...) + + log.Info(ctx, s) + log.Infof(ctx, s) + log.InfoKV(ctx, "key", s) + log.InfoKVs(ctx, kv.Fields{{K: "key", V: s}}...) + + log.Warn(ctx, s) + log.Warnf(ctx, s) + log.WarnKV(ctx, "key", s) + log.WarnKVs(ctx, kv.Fields{{K: "key", V: s}}...) + + log.Error(ctx, s) + log.Errorf(ctx, s) + log.ErrorKV(ctx, "key", s) + log.ErrorKVs(ctx, kv.Fields{{K: "key", V: s}}...) + + log.Panic(ctx, s) + log.Panicf(ctx, s) + log.PanicKV(ctx, "key", s) + log.PanicKVs(ctx, kv.Fields{{K: "key", V: s}}...) + + log.Print(s) + log.Printf(s) + + e := log.New() + e = e.WithContext(ctx) + e = e.WithField("key", s) + e = e.WithFields(kv.Fields{{K: "key", V: s}}...) + + e.Debug(s) + e.Debugf(s) + + e.Info(s) + e.Infof(s) + + e.Warn(s) + e.Warnf(s) + + e.Error(s) + e.Errorf(s) + + e.Panic(s) + e.Panicf(s) + + e.Print(s) + e.Printf(s) +} diff --git a/internal/log/std.go b/internal/log/std.go new file mode 100644 index 000000000..47adec128 --- /dev/null +++ b/internal/log/std.go @@ -0,0 +1,43 @@ +// GoToSocial +// Copyright (C) GoToSocial Authors admin@gotosocial.org +// SPDX-License-Identifier: AGPL-3.0-or-later +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU Affero General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Affero General Public License for more details. +// +// You should have received a copy of the GNU Affero General Public License +// along with this program. If not, see . + +package log + +import ( + "log" + + "codeberg.org/gruf/go-kv/v2" +) + +// NewStdLogger returns a new standard library +// log.Logger instance that will write output +// to this library's logging functions at 'lvl'. +func NewStdLogger(lvl LEVEL) *log.Logger { + return log.New(stdLogWriter{lvl: lvl}, "", 0) +} + +type stdLogWriter struct{ lvl LEVEL } + +func (w stdLogWriter) Write(b []byte) (int, error) { + if w.lvl <= loglvl { + logf(nil, w.lvl, kv.Fields{ + {K: "caller", V: Caller(5)}, + {K: "msg", V: b}, + }, "") + } + return len(b), nil +} diff --git a/internal/router/router.go b/internal/router/router.go index 45419807d..fd7a18ebe 100644 --- a/internal/router/router.go +++ b/internal/router/router.go @@ -23,6 +23,7 @@ import ( "fmt" "net" "net/http" + "strconv" "time" "code.superseriousbusiness.org/gotosocial/internal/config" @@ -93,9 +94,10 @@ func New(ctx context.Context) (*Router, error) { // `server start` command anyway. baseCtx := func(_ net.Listener) context.Context { return ctx } - addr := fmt.Sprintf("%s:%d", + // Create joined listen addr. + addr := net.JoinHostPort( config.GetBindAddress(), - config.GetPort(), + strconv.Itoa(config.GetPort()), ) // Wrap the gin engine handler in our @@ -111,6 +113,7 @@ func New(ctx context.Context) (*Router, error) { WriteTimeout: writeTimeout, IdleTimeout: idleTimeout, BaseContext: baseCtx, + ErrorLog: log.NewStdLogger(log.ERROR), } return &Router{