refactor: rework app logging, dependency injection and cancellation (#844)

* feat: add new logger

* refactor: use one struct for context handling and cancellation

* refactor: rework logging and config in controllers

* refactor: rework logging and config in middlewares

* refactor: rework logging and cancellation in services

* refactor: rework cli logging

* fix: improve logging in routines

* feat: use sync groups for better cancellation

* refactor: simplify middleware, controller and service init

* tests: fix controller tests

* tests: use require instead of assert where previous step is required

* tests: fix middleware tests

* tests: fix service tests

* tests: fix context tests

* fix: fix typos

* feat: add option to enable or disable concurrent listeners

* fix: assign public key correctly in oidc server

* tests: fix don't try to test logger with char size

* fix: coderabbit comments

* tests: use filepath join instead of path join

* fix: ensure unix socket shutdown doesn't run twice

* chore: remove temp lint file

internal/utils/app_utils.go

@@ -7,8 +7,6 @@ import (
 	"net/url"
 	"strings"
 
-	"github.com/tinyauthapp/tinyauth/internal/utils/tlog"
-
 	"github.com/weppos/publicsuffix-go/publicsuffix"
 )
 
@@ -28,7 +26,6 @@ func GetCookieDomain(u string) (string, error) {
 	parts := strings.Split(host, ".")
 
 	if len(parts) == 2 {
-		tlog.App.Warn().Msgf("Running on the root domain, cookies will be set for .%v", host)
 		return host, nil
 	}
 

internal/utils/logger/logger.go

@@ -0,0 +1,160 @@
+package logger
+
+import (
+	"io"
+	"os"
+	"strings"
+	"time"
+
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
+	"github.com/tinyauthapp/tinyauth/internal/model"
+)
+
+type Logger struct {
+	HTTP   zerolog.Logger
+	App    zerolog.Logger
+	config model.LogConfig
+	base   zerolog.Logger
+	audit  zerolog.Logger
+	writer io.Writer
+}
+
+func NewLogger() *Logger {
+	return &Logger{
+		writer: os.Stderr,
+		config: model.LogConfig{
+			Level: "error",
+			Json:  true,
+			Streams: model.LogStreams{
+				HTTP: model.LogStreamConfig{
+					Enabled: true,
+				},
+				App: model.LogStreamConfig{
+					Enabled: true,
+				},
+				// No reason to enable audit by default since it will be suppressed by the log level
+			},
+		},
+	}
+}
+
+func (l *Logger) WithConfig(cfg model.LogConfig) *Logger {
+	l.config = cfg
+	return l
+}
+
+func (l *Logger) WithSimpleConfig() *Logger {
+	l.config = model.LogConfig{
+		Level: "info",
+		Json:  false,
+		Streams: model.LogStreams{
+			HTTP:  model.LogStreamConfig{Enabled: true},
+			App:   model.LogStreamConfig{Enabled: true},
+			Audit: model.LogStreamConfig{Enabled: false},
+		},
+	}
+	return l
+}
+
+func (l *Logger) WithTestConfig() *Logger {
+	l.config = model.LogConfig{
+		Level: "trace",
+		Streams: model.LogStreams{
+			HTTP:  model.LogStreamConfig{Enabled: true},
+			App:   model.LogStreamConfig{Enabled: true},
+			Audit: model.LogStreamConfig{Enabled: true},
+		},
+	}
+	return l
+}
+
+func (l *Logger) WithWriter(writer io.Writer) *Logger {
+	l.writer = writer
+	return l
+}
+
+func (l *Logger) Init() {
+	base := log.With().
+		Timestamp().
+		Logger().
+		Level(l.parseLogLevel(l.config.Level)).Output(l.writer)
+
+	if !l.config.Json {
+		base = base.Output(zerolog.ConsoleWriter{
+			Out:        l.writer,
+			TimeFormat: time.RFC3339,
+		})
+	}
+
+	if base.GetLevel() == zerolog.TraceLevel || base.GetLevel() == zerolog.DebugLevel {
+		base = base.With().Caller().Logger()
+	}
+
+	l.base = base
+	l.audit = l.createLogger("audit", l.config.Streams.Audit)
+	l.HTTP = l.createLogger("http", l.config.Streams.HTTP)
+	l.App = l.createLogger("app", l.config.Streams.App)
+}
+
+func (l *Logger) parseLogLevel(level string) zerolog.Level {
+	if level == "" {
+		return zerolog.InfoLevel
+	}
+	parsed, err := zerolog.ParseLevel(strings.ToLower(level))
+	if err != nil {
+		log.Warn().Err(err).Str("level", level).Msg("Invalid log level, defaulting to error")
+		parsed = zerolog.ErrorLevel
+	}
+	return parsed
+}
+
+func (l *Logger) createLogger(component string, cfg model.LogStreamConfig) zerolog.Logger {
+	if !cfg.Enabled {
+		return zerolog.Nop()
+	}
+	sub := l.base.With().Str("stream", component).Logger()
+	if cfg.Level != "" {
+		sub = sub.Level(l.parseLogLevel(cfg.Level))
+	}
+	return sub
+}
+
+func (l *Logger) AuditLoginSuccess(username, provider, ip string) {
+	l.audit.Info().
+		CallerSkipFrame(1).
+		Str("event", "login").
+		Str("result", "success").
+		Str("username", username).
+		Str("provider", provider).
+		Str("ip", ip).
+		Send()
+}
+
+func (l *Logger) AuditLoginFailure(username, provider, ip, reason string) {
+	l.audit.Warn().
+		CallerSkipFrame(1).
+		Str("event", "login").
+		Str("result", "failure").
+		Str("username", username).
+		Str("provider", provider).
+		Str("ip", ip).
+		Str("reason", reason).
+		Send()
+}
+
+func (l *Logger) AuditLogout(username, provider, ip string) {
+	l.audit.Info().
+		CallerSkipFrame(1).
+		Str("event", "logout").
+		Str("result", "success").
+		Str("username", username).
+		Str("provider", provider).
+		Str("ip", ip).
+		Send()
+}
+
+// Used for testing
+func (l *Logger) GetConfig() model.LogConfig {
+	return l.config
+}

internal/utils/logger/logger_test.go

@@ -0,0 +1,173 @@
+package logger_test
+
+import (
+	"bytes"
+	"encoding/json"
+	"testing"
+
+	"github.com/rs/zerolog"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"github.com/tinyauthapp/tinyauth/internal/model"
+	"github.com/tinyauthapp/tinyauth/internal/utils/logger"
+)
+
+func TestLogger(t *testing.T) {
+	type testCase struct {
+		description string
+		run         func(t *testing.T)
+	}
+
+	tests := []testCase{
+		{
+			description: "Should create a simple logger with the expected config",
+			run: func(t *testing.T) {
+				l := logger.NewLogger().WithSimpleConfig()
+				l.Init()
+
+				cfg := l.GetConfig()
+
+				assert.Equal(t, cfg, model.LogConfig{
+					Level: "info",
+					Json:  false,
+					Streams: model.LogStreams{
+						HTTP:  model.LogStreamConfig{Enabled: true},
+						App:   model.LogStreamConfig{Enabled: true},
+						Audit: model.LogStreamConfig{Enabled: false},
+					},
+				})
+			},
+		},
+		{
+			description: "Should create a test logger with the expected config",
+			run: func(t *testing.T) {
+				l := logger.NewLogger().WithTestConfig()
+				l.Init()
+
+				cfg := l.GetConfig()
+
+				assert.Equal(t, cfg, model.LogConfig{
+					Level: "trace",
+					Json:  false,
+					Streams: model.LogStreams{
+						HTTP:  model.LogStreamConfig{Enabled: true},
+						App:   model.LogStreamConfig{Enabled: true},
+						Audit: model.LogStreamConfig{Enabled: true},
+					},
+				})
+			},
+		},
+		{
+			description: "Should create a logger with a custom config",
+			run: func(t *testing.T) {
+				customCfg := model.LogConfig{
+					Level: "debug",
+					Json:  true,
+					Streams: model.LogStreams{
+						HTTP:  model.LogStreamConfig{Enabled: false},
+						App:   model.LogStreamConfig{Enabled: true},
+						Audit: model.LogStreamConfig{Enabled: false},
+					},
+				}
+
+				l := logger.NewLogger().WithConfig(customCfg)
+				l.Init()
+
+				cfg := l.GetConfig()
+
+				assert.Equal(t, cfg, customCfg)
+			},
+		},
+		{
+			description: "Default logger should use error type and log json",
+			run: func(t *testing.T) {
+				buf := bytes.Buffer{}
+
+				l := logger.NewLogger().WithWriter(&buf)
+				l.Init()
+
+				cfg := l.GetConfig()
+
+				assert.Equal(t, cfg, model.LogConfig{
+					Level: "error",
+					Json:  true,
+					Streams: model.LogStreams{
+						HTTP:  model.LogStreamConfig{Enabled: true},
+						App:   model.LogStreamConfig{Enabled: true},
+						Audit: model.LogStreamConfig{Enabled: false},
+					},
+				})
+
+				l.App.Error().Msg("test")
+
+				var entry map[string]any
+				err := json.Unmarshal(buf.Bytes(), &entry)
+				require.NoError(t, err)
+
+				assert.Equal(t, "test", entry["message"])
+				assert.Equal(t, "app", entry["stream"])
+				assert.Equal(t, "error", entry["level"])
+				assert.NotEmpty(t, entry["time"])
+			},
+		},
+		{
+			description: "Should default to error level if an invalid level is provided",
+			run: func(t *testing.T) {
+				buf := bytes.Buffer{}
+
+				customCfg := model.LogConfig{
+					Level: "invalid",
+					Json:  false,
+					Streams: model.LogStreams{
+						HTTP:  model.LogStreamConfig{Enabled: true},
+						App:   model.LogStreamConfig{Enabled: true},
+						Audit: model.LogStreamConfig{Enabled: false},
+					},
+				}
+
+				l := logger.NewLogger().WithConfig(customCfg).WithWriter(&buf)
+				l.Init()
+
+				assert.Equal(t, zerolog.ErrorLevel, l.App.GetLevel())
+				assert.Equal(t, zerolog.ErrorLevel, l.HTTP.GetLevel())
+
+				// should not get logged
+				l.AuditLoginFailure("test", "test", "test", "test")
+
+				assert.Empty(t, buf.String())
+			},
+		},
+		{
+			description: "Should use nop logger for disabled streams",
+			run: func(t *testing.T) {
+				buf := bytes.Buffer{}
+
+				customCfg := model.LogConfig{
+					Level: "info",
+					Json:  false,
+					Streams: model.LogStreams{
+						HTTP:  model.LogStreamConfig{Enabled: false},
+						App:   model.LogStreamConfig{Enabled: true},
+						Audit: model.LogStreamConfig{Enabled: false},
+					},
+				}
+
+				l := logger.NewLogger().WithConfig(customCfg).WithWriter(&buf)
+				l.Init()
+
+				assert.Equal(t, zerolog.Disabled, l.HTTP.GetLevel())
+
+				l.App.Info().Msg("test")
+
+				l.AuditLoginFailure("test_nop", "test_nop", "test_nop", "test_nop")
+
+				assert.NotEmpty(t, buf.String())
+				assert.NotContains(t, buf.String(), "test_nop")
+			},
+		},
+	}
+
+	for _, test := range tests {
+		t.Run(test.description, test.run)
+	}
+}

internal/utils/tlog/log_audit.go

@@ -1,39 +0,0 @@
-package tlog
-
-import "github.com/gin-gonic/gin"
-
-// functions here use CallerSkipFrame to ensure correct caller info is logged
-
-func AuditLoginSuccess(c *gin.Context, username, provider string) {
-	Audit.Info().
-		CallerSkipFrame(1).
-		Str("event", "login").
-		Str("result", "success").
-		Str("username", username).
-		Str("provider", provider).
-		Str("ip", c.ClientIP()).
-		Send()
-}
-
-func AuditLoginFailure(c *gin.Context, username, provider string, reason string) {
-	Audit.Warn().
-		CallerSkipFrame(1).
-		Str("event", "login").
-		Str("result", "failure").
-		Str("username", username).
-		Str("provider", provider).
-		Str("ip", c.ClientIP()).
-		Str("reason", reason).
-		Send()
-}
-
-func AuditLogout(c *gin.Context, username, provider string) {
-	Audit.Info().
-		CallerSkipFrame(1).
-		Str("event", "logout").
-		Str("result", "success").
-		Str("username", username).
-		Str("provider", provider).
-		Str("ip", c.ClientIP()).
-		Send()
-}

internal/utils/tlog/log_wrapper.go

@@ -1,97 +0,0 @@
-package tlog
-
-import (
-	"os"
-	"strings"
-	"time"
-
-	"github.com/rs/zerolog"
-	"github.com/rs/zerolog/log"
-	"github.com/tinyauthapp/tinyauth/internal/model"
-)
-
-type Logger struct {
-	Audit zerolog.Logger
-	HTTP  zerolog.Logger
-	App   zerolog.Logger
-}
-
-var (
-	Audit zerolog.Logger
-	HTTP  zerolog.Logger
-	App   zerolog.Logger
-)
-
-func NewLogger(cfg model.LogConfig) *Logger {
-	baseLogger := log.With().
-		Timestamp().
-		Caller().
-		Logger().
-		Level(parseLogLevel(cfg.Level))
-
-	if !cfg.Json {
-		baseLogger = baseLogger.Output(zerolog.ConsoleWriter{
-			Out:        os.Stderr,
-			TimeFormat: time.RFC3339,
-		})
-	}
-
-	return &Logger{
-		Audit: createLogger("audit", cfg.Streams.Audit, baseLogger),
-		HTTP:  createLogger("http", cfg.Streams.HTTP, baseLogger),
-		App:   createLogger("app", cfg.Streams.App, baseLogger),
-	}
-}
-
-func NewSimpleLogger() *Logger {
-	return NewLogger(model.LogConfig{
-		Level: "info",
-		Json:  false,
-		Streams: model.LogStreams{
-			HTTP:  model.LogStreamConfig{Enabled: true},
-			App:   model.LogStreamConfig{Enabled: true},
-			Audit: model.LogStreamConfig{Enabled: false},
-		},
-	})
-}
-
-func NewTestLogger() *Logger {
-	return NewLogger(model.LogConfig{
-		Level: "trace",
-		Streams: model.LogStreams{
-			HTTP:  model.LogStreamConfig{Enabled: true},
-			App:   model.LogStreamConfig{Enabled: true},
-			Audit: model.LogStreamConfig{Enabled: true},
-		},
-	})
-}
-
-func (l *Logger) Init() {
-	Audit = l.Audit
-	HTTP = l.HTTP
-	App = l.App
-}
-
-func createLogger(component string, streamCfg model.LogStreamConfig, baseLogger zerolog.Logger) zerolog.Logger {
-	if !streamCfg.Enabled {
-		return zerolog.Nop()
-	}
-	subLogger := baseLogger.With().Str("log_stream", component).Logger()
-	// override level if specified, otherwise use base level
-	if streamCfg.Level != "" {
-		subLogger = subLogger.Level(parseLogLevel(streamCfg.Level))
-	}
-	return subLogger
-}
-
-func parseLogLevel(level string) zerolog.Level {
-	if level == "" {
-		return zerolog.InfoLevel
-	}
-	parsedLevel, err := zerolog.ParseLevel(strings.ToLower(level))
-	if err != nil {
-		log.Warn().Err(err).Str("level", level).Msg("Invalid log level, defaulting to info")
-		parsedLevel = zerolog.InfoLevel
-	}
-	return parsedLevel
-}

internal/utils/tlog/log_wrapper_test.go

@@ -1,93 +0,0 @@
-package tlog_test
-
-import (
-	"bytes"
-	"encoding/json"
-	"testing"
-
-	"github.com/stretchr/testify/assert"
-	"github.com/tinyauthapp/tinyauth/internal/model"
-	"github.com/tinyauthapp/tinyauth/internal/utils/tlog"
-
-	"github.com/rs/zerolog"
-)
-
-func TestNewLogger(t *testing.T) {
-	cfg := model.LogConfig{
-		Level: "debug",
-		Json:  true,
-		Streams: model.LogStreams{
-			HTTP:  model.LogStreamConfig{Enabled: true, Level: "info"},
-			App:   model.LogStreamConfig{Enabled: true, Level: ""},
-			Audit: model.LogStreamConfig{Enabled: false, Level: ""},
-		},
-	}
-
-	logger := tlog.NewLogger(cfg)
-
-	assert.NotNil(t, logger)
-	assert.Equal(t, zerolog.InfoLevel, logger.HTTP.GetLevel())
-	assert.Equal(t, zerolog.DebugLevel, logger.App.GetLevel())
-	assert.Equal(t, zerolog.Disabled, logger.Audit.GetLevel())
-}
-
-func TestNewSimpleLogger(t *testing.T) {
-	logger := tlog.NewSimpleLogger()
-	assert.NotNil(t, logger)
-	assert.Equal(t, zerolog.InfoLevel, logger.HTTP.GetLevel())
-	assert.Equal(t, zerolog.InfoLevel, logger.App.GetLevel())
-	assert.Equal(t, zerolog.Disabled, logger.Audit.GetLevel())
-}
-
-func TestLoggerInit(t *testing.T) {
-	logger := tlog.NewSimpleLogger()
-	logger.Init()
-
-	assert.NotEqual(t, zerolog.Disabled, tlog.App.GetLevel())
-}
-
-func TestLoggerWithDisabledStreams(t *testing.T) {
-	cfg := model.LogConfig{
-		Level: "info",
-		Json:  false,
-		Streams: model.LogStreams{
-			HTTP:  model.LogStreamConfig{Enabled: false},
-			App:   model.LogStreamConfig{Enabled: false},
-			Audit: model.LogStreamConfig{Enabled: false},
-		},
-	}
-
-	logger := tlog.NewLogger(cfg)
-
-	assert.Equal(t, zerolog.Disabled, logger.HTTP.GetLevel())
-	assert.Equal(t, zerolog.Disabled, logger.App.GetLevel())
-	assert.Equal(t, zerolog.Disabled, logger.Audit.GetLevel())
-}
-
-func TestLogStreamField(t *testing.T) {
-	var buf bytes.Buffer
-
-	cfg := model.LogConfig{
-		Level: "info",
-		Json:  true,
-		Streams: model.LogStreams{
-			HTTP:  model.LogStreamConfig{Enabled: true},
-			App:   model.LogStreamConfig{Enabled: true},
-			Audit: model.LogStreamConfig{Enabled: true},
-		},
-	}
-
-	logger := tlog.NewLogger(cfg)
-
-	// Override output for HTTP logger to capture output
-	logger.HTTP = logger.HTTP.Output(&buf)
-
-	logger.HTTP.Info().Msg("test message")
-
-	var logEntry map[string]interface{}
-	err := json.Unmarshal(buf.Bytes(), &logEntry)
-	assert.NoError(t, err)
-
-	assert.Equal(t, "http", logEntry["log_stream"])
-	assert.Equal(t, "test message", logEntry["message"])
-}