feat(server): logging & error-visibility hardening

Make server failures debuggable without leaking secrets:
- configurable stdout log level (config.yaml logging.level + OWNCORD_LOGGING_LEVEL)
- preserve the DB cause in ErrInternal wraps; log auth-DB failures distinctly
  from bad tokens; log the previously-silent expired-session cleanup goroutine
- route HTTP handler panics through slog (was chi stderr-only, invisible to
  the admin log stream)
- stackutil: argument-free panic stacks so key/token bytes never reach the
  admin ring buffer / SSE; slog.LogValuer redaction on VoiceConfig/GitHubConfig/
  GIFConfig/Config and db.User/db.Session
- logctx: req_id/trace_id correlation on ...Context log calls

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
J3vb
2026-07-24 11:07:12 +02:00
co-authored by Claude Opus 4.8
parent 4b36a3339a
commit 4fc21cb372
29 changed files with 623 additions and 64 deletions
+10 -7
View File
@@ -1,6 +1,7 @@
package api
import (
"context"
"errors"
"log/slog"
"net/http"
@@ -134,7 +135,7 @@ func handleGetMessages(svc *service.Services) http.HandlerFunc {
msgs, hasMore, err := svc.Messages.GetMessages(r.Context(), user.ID, channelID, before, limit)
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
@@ -200,7 +201,7 @@ func handleSearch(svc *service.Services) http.HandlerFunc {
})
return
}
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
if results == nil {
@@ -232,7 +233,7 @@ func handleGetPins(svc *service.Services) http.HandlerFunc {
msgs, err := svc.Messages.GetPinnedMessages(r.Context(), user.ID, channelID)
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
@@ -265,7 +266,7 @@ func handleSetPinned(svc *service.Services, pinned bool) http.HandlerFunc {
}
if err := svc.Messages.SetMessagePinned(r.Context(), user.ID, channelID, messageID, pinned); err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
w.WriteHeader(http.StatusNoContent)
@@ -273,7 +274,7 @@ func handleSetPinned(svc *service.Services, pinned bool) http.HandlerFunc {
}
// writeServiceError maps a service-layer error to an HTTP response.
func writeServiceError(w http.ResponseWriter, err error) {
func writeServiceError(ctx context.Context, w http.ResponseWriter, err error) {
switch {
case errors.Is(err, service.ErrRateLimited):
writeJSON(w, http.StatusTooManyRequests, errorResponse{Error: "RATE_LIMITED", Message: err.Error()})
@@ -286,10 +287,12 @@ func writeServiceError(w http.ResponseWriter, err error) {
case errors.Is(err, service.ErrConflict):
writeJSON(w, http.StatusConflict, errorResponse{Error: "CONFLICT", Message: err.Error()})
case errors.Is(err, service.ErrInternal):
slog.Error("service error", "err", err)
// ErrorContext so the enriching handler attaches req_id/trace_id,
// linking this 500 to its request log line and trace.
slog.ErrorContext(ctx, "service error", "error", err)
writeJSON(w, http.StatusInternalServerError, errorResponse{Error: "INTERNAL_ERROR", Message: "an internal error occurred"})
default:
slog.Error("service error", "err", err)
slog.ErrorContext(ctx, "service error", "error", err)
writeJSON(w, http.StatusInternalServerError, errorResponse{Error: "INTERNAL_ERROR", Message: "internal error"})
}
}
+6 -6
View File
@@ -75,7 +75,7 @@ func handleCreateDM(svc *service.Services) http.HandlerFunc {
result, err := svc.DMs.CreateDM(r.Context(), user.ID, req.RecipientID)
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
@@ -115,7 +115,7 @@ func handleListDMs(svc *service.Services) http.HandlerFunc {
channels, err := svc.DMs.ListDMs(r.Context(), user.ID)
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
writeJSON(w, http.StatusOK, listDMsResponse{DMChannels: channels})
@@ -139,7 +139,7 @@ func handleCloseDM(svc *service.Services, broadcaster DMBroadcaster) http.Handle
}
if err := svc.DMs.CloseDM(r.Context(), user.ID, channelID); err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
@@ -170,7 +170,7 @@ func handleBlockUser(svc *service.Services) http.HandlerFunc {
}
if err := svc.Blocks.BlockUser(r.Context(), user.ID, targetID); err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
writeJSON(w, http.StatusOK, map[string]string{"message": "user blocked"})
@@ -192,7 +192,7 @@ func handleUnblockUser(svc *service.Services) http.HandlerFunc {
}
if err := svc.Blocks.UnblockUser(r.Context(), user.ID, targetID); err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
writeJSON(w, http.StatusOK, map[string]string{"message": "user unblocked"})
@@ -210,7 +210,7 @@ func handleListBlocks(svc *service.Services) http.HandlerFunc {
ids, err := svc.Blocks.ListBlocked(r.Context(), user.ID)
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
writeJSON(w, http.StatusOK, map[string]any{"blocked_user_ids": ids})
+3 -3
View File
@@ -75,7 +75,7 @@ func handleCreateInvite(svc *service.Services) http.HandlerFunc {
inv, err := svc.Invites.CreateInvite(r.Context(), user.ID, req.MaxUses, req.ExpiresInHours)
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
writeJSON(w, http.StatusCreated, toInviteResponse(inv))
@@ -87,7 +87,7 @@ func handleListInvites(svc *service.Services) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
invites, err := svc.Invites.ListInvites(r.Context())
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
@@ -104,7 +104,7 @@ func handleRevokeInvite(svc *service.Services) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
code := chi.URLParam(r, "code")
if err := svc.Invites.RevokeInvite(r.Context(), code); err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
w.WriteHeader(http.StatusNoContent)
+14 -1
View File
@@ -44,6 +44,11 @@ func AuthMiddleware(database *db.DB) func(http.Handler) http.Handler {
hash := auth.HashToken(token)
sess, err := database.GetSessionByTokenHash(r.Context(), hash)
if err != nil || sess == nil {
if err != nil {
// A DB error here is an outage, not a bad token — log it so
// it's distinguishable from ordinary invalid-token 401s.
slog.ErrorContext(r.Context(), "auth: session lookup failed", "error", err)
}
writeJSON(w, http.StatusUnauthorized, errorResponse{
Error: "UNAUTHORIZED",
Message: "invalid or expired session",
@@ -58,7 +63,9 @@ func AuthMiddleware(database *db.DB) func(http.Handler) http.Handler {
// written, so detach cancellation: the deletion must complete.
cleanupCtx := context.WithoutCancel(r.Context())
go func(h string) {
_ = database.DeleteSession(cleanupCtx, h)
if err := database.DeleteSession(cleanupCtx, h); err != nil {
slog.WarnContext(cleanupCtx, "expired session cleanup failed", "error", err)
}
}(hash)
writeJSON(w, http.StatusUnauthorized, errorResponse{
Error: "UNAUTHORIZED",
@@ -70,6 +77,9 @@ func AuthMiddleware(database *db.DB) func(http.Handler) http.Handler {
// Load user.
user, err := database.GetUserByID(r.Context(), sess.UserID)
if err != nil || user == nil {
if err != nil {
slog.ErrorContext(r.Context(), "auth: user lookup failed", "error", err, "user_id", sess.UserID)
}
writeJSON(w, http.StatusUnauthorized, errorResponse{
Error: "UNAUTHORIZED",
Message: "user not found",
@@ -92,6 +102,9 @@ func AuthMiddleware(database *db.DB) func(http.Handler) http.Handler {
// and every downstream permission check has to re-guard it.
role, err := database.GetRoleByID(r.Context(), user.RoleID)
if err != nil || role == nil {
if err != nil {
slog.ErrorContext(r.Context(), "auth: role lookup failed", "error", err, "user_id", user.ID, "role_id", user.RoleID)
}
writeJSON(w, http.StatusUnauthorized, errorResponse{
Error: "UNAUTHORIZED",
Message: "role not found",
+4 -4
View File
@@ -171,7 +171,7 @@ func handleUpdateProfile(svc *service.Services, broadcaster ProfileBroadcaster)
updated, err := svc.Users.UpdateProfile(r.Context(), user.ID, req.Username, req.Avatar)
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
@@ -275,7 +275,7 @@ func handleChangePassword(svc *service.Services, limiter *auth.RateLimiter) http
res, err := svc.Users.ChangePassword(r.Context(), user.ID, hash, keepSessionID)
if err != nil {
// Only reachable when the password itself failed to commit.
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
if res.RevokeFailed {
@@ -314,7 +314,7 @@ func handleListSessions(svc *service.Services) http.HandlerFunc {
sessions, err := svc.Users.ListSessions(r.Context(), user.ID)
if err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
@@ -353,7 +353,7 @@ func handleRevokeSession(svc *service.Services) http.HandlerFunc {
}
if err := svc.Users.RevokeSession(r.Context(), user.ID, sessionID); err != nil {
writeServiceError(w, err)
writeServiceError(r.Context(), w, err)
return
}
+40 -1
View File
@@ -18,6 +18,7 @@ import (
"github.com/owncord/server/permissions"
"github.com/owncord/server/plugin"
"github.com/owncord/server/service"
"github.com/owncord/server/stackutil"
"github.com/owncord/server/storage"
"github.com/owncord/server/telemetry"
"github.com/owncord/server/updater"
@@ -39,7 +40,7 @@ func NewRouter(cfg *config.Config, database *db.DB, ver string, logBuf *admin.Ri
// NOTE: middleware.RealIP is intentionally omitted — trusting X-Real-IP from
// any source allows IP spoofing for rate-limit bypass. IP header trust is now
// handled explicitly in clientIPWithProxies using the trusted_proxies config.
r.Use(middleware.Recoverer)
r.Use(recoverer) // slog-routing panic recovery (replaces chi's stderr-only Recoverer)
r.Use(requestLogger) // structured request/response logging
// Phase B Step 8 — OpenTelemetry HTTP tracing. No-op when telemetry is
// disabled or the otel build tag is not set, so this is safe to mount
@@ -363,6 +364,44 @@ func setRequestIDHeader(next http.Handler) http.Handler {
})
}
// recoverer recovers from panics in HTTP handlers and logs them through slog —
// so they reach the admin log stream and are structured — unlike chi's default
// middleware.Recoverer, which writes an unstructured stack to stderr only. The
// stack is captured via stackutil so it never embeds argument values (which on
// auth/upload paths can carry tokens or passwords).
func recoverer(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
// Capture correlation IDs before dispatch so the recovery closure makes
// no context calls (which trip contextcheck inside a defer), while the
// panic log still carries req_id/trace_id.
reqID := middleware.GetReqID(r.Context())
traceID := telemetry.TraceIDFromContext(r.Context())
defer func() {
if rec := recover(); rec != nil {
// Preserve chi's behaviour of not swallowing the abort sentinel.
if rec == http.ErrAbortHandler {
panic(rec)
}
attrs := []any{
"method", r.Method,
"path", r.URL.Path,
"panic", rec,
"stack", stackutil.Capture(),
}
if reqID != "" {
attrs = append(attrs, "req_id", reqID)
}
if traceID != "" {
attrs = append(attrs, "trace_id", traceID)
}
slog.Error("http handler panic recovered", attrs...)
w.WriteHeader(http.StatusInternalServerError)
}
}()
next.ServeHTTP(w, r)
})
}
// requestLogger logs every HTTP request with method, path, status, and duration.
// Health checks are logged at Debug level to avoid noise.
func requestLogger(next http.Handler) http.Handler {
+39
View File
@@ -30,6 +30,36 @@ type Config struct {
Telemetry TelemetryConfig `koanf:"telemetry"`
Plugins PluginsConfig `koanf:"plugins"`
GIF GIFConfig `koanf:"gif"`
Logging LoggingConfig `koanf:"logging"`
}
// LoggingConfig controls server log verbosity. The in-memory ring buffer that
// backs the admin panel's live log view always captures DEBUG regardless of
// this setting — Level only gates what is written to stdout.
type LoggingConfig struct {
// Level is the minimum level written to stdout: "debug" | "info" | "warn" |
// "error". Override at runtime without editing config.yaml via the
// OWNCORD_LOGGING_LEVEL environment variable.
Level string `koanf:"level"`
}
// ParseLevel maps a config log-level string to a slog.Level. It is
// case-insensitive and treats "" as info. The bool is false for an
// unrecognised value (in which case slog.LevelInfo is returned and the caller
// should warn) so a typo doesn't silently disable logging.
func ParseLevel(s string) (slog.Level, bool) {
switch strings.ToLower(strings.TrimSpace(s)) {
case "debug":
return slog.LevelDebug, true
case "", "info":
return slog.LevelInfo, true
case "warn", "warning":
return slog.LevelWarn, true
case "error":
return slog.LevelError, true
default:
return slog.LevelInfo, false
}
}
// GIFConfig holds the credentials for the server-side GIF (Klipy) proxy.
@@ -221,6 +251,9 @@ func defaults() Config {
CPUBudgetMs: 100,
HTTPAllowlist: []string{},
},
Logging: LoggingConfig{
Level: "info",
},
}
}
@@ -305,6 +338,12 @@ voice:
# Get a key at https://partner.klipy.com
# gif:
# api_key: ""
# Logging. "level" gates what is written to stdout; the admin panel's live log
# view always captures debug regardless. Override without editing this file via
# the OWNCORD_LOGGING_LEVEL environment variable.
# logging:
# level: "info" # debug | info | warn | error
`
// Load reads configuration from the given YAML file path, merging with
+48
View File
@@ -0,0 +1,48 @@
package config
import (
"log/slog"
"path/filepath"
"testing"
)
func TestParseLevel(t *testing.T) {
cases := []struct {
in string
want slog.Level
ok bool
}{
{"debug", slog.LevelDebug, true},
{"info", slog.LevelInfo, true},
{"", slog.LevelInfo, true},
{"WARN", slog.LevelWarn, true},
{"warning", slog.LevelWarn, true},
{"error", slog.LevelError, true},
{" Debug ", slog.LevelDebug, true},
{"bogus", slog.LevelInfo, false},
}
for _, c := range cases {
got, ok := ParseLevel(c.in)
if got != c.want || ok != c.ok {
t.Errorf("ParseLevel(%q) = %v,%v want %v,%v", c.in, got, ok, c.want, c.ok)
}
}
}
// TestLoggingLevelFromEnv verifies the end-to-end wiring: OWNCORD_LOGGING_LEVEL
// overrides config.yaml via koanf's existing env layer.
func TestLoggingLevelFromEnv(t *testing.T) {
cfgPath := filepath.Join(t.TempDir(), "config.yaml")
t.Setenv("OWNCORD_LOGGING_LEVEL", "debug")
cfg, err := Load(cfgPath)
if err != nil {
t.Fatalf("Load: %v", err)
}
if cfg.Logging.Level != "debug" {
t.Errorf("expected level %q from env, got %q", "debug", cfg.Logging.Level)
}
if lvl, ok := ParseLevel(cfg.Logging.Level); !ok || lvl != slog.LevelDebug {
t.Errorf("ParseLevel(%q) = %v,%v", cfg.Logging.Level, lvl, ok)
}
}
+69
View File
@@ -0,0 +1,69 @@
package config
import "log/slog"
// This file makes secret-bearing config types safe to log by construction.
// Without it, "never log secrets" holds only by call-site discipline — a
// single slog.Info("cfg", "voice", cfg.Voice) would dump the LiveKit key. By
// implementing slog.LogValuer, secrets are redacted no matter how the value
// reaches a log record. Non-secret fields stay visible so the logs remain
// useful for debugging.
// redactSecret masks a secret for logging. An empty value stays empty (so an
// unset credential is still visible as "unset"); anything else becomes a fixed
// marker that reveals neither the value nor its length.
func redactSecret(s string) string {
if s == "" {
return ""
}
return "[REDACTED]"
}
// LogValue redacts the LiveKit API key and secret.
func (v VoiceConfig) LogValue() slog.Value {
return slog.GroupValue(
slog.String("livekit_api_key", redactSecret(v.LiveKitAPIKey)),
slog.String("livekit_api_secret", redactSecret(v.LiveKitAPISecret)),
slog.String("livekit_url", v.LiveKitURL),
slog.String("livekit_binary", v.LiveKitBinaryPath),
slog.String("node_ip", v.NodeIP),
slog.Bool("advertise_internal_ip", v.AdvertiseInternalIP),
slog.String("quality", v.Quality),
)
}
// LogValue redacts the GitHub token.
func (g GitHubConfig) LogValue() slog.Value {
return slog.GroupValue(
slog.String("token", redactSecret(g.Token)),
slog.String("owner", g.Owner),
slog.String("repo", g.Repo),
)
}
// LogValue redacts the Klipy (GIF proxy) API key.
func (g GIFConfig) LogValue() slog.Value {
return slog.GroupValue(
slog.String("api_key", redactSecret(g.APIKey)),
)
}
// LogValue delegates each section through slog.Any so secret-bearing sections
// are redacted via their own LogValue even when the whole Config is logged.
// A section added to Config but not listed here is omitted from the log (safe:
// it is hidden, never leaked).
func (c Config) LogValue() slog.Value {
return slog.GroupValue(
slog.Any("server", c.Server),
slog.Any("database", c.Database),
slog.Any("tls", c.TLS),
slog.Any("upload", c.Upload),
slog.Any("voice", c.Voice),
slog.Any("github", c.GitHub),
slog.Any("event_persistence", c.EventPersistence),
slog.Any("telemetry", c.Telemetry),
slog.Any("plugins", c.Plugins),
slog.Any("gif", c.GIF),
slog.Any("logging", c.Logging),
)
}
+45
View File
@@ -0,0 +1,45 @@
package config
import (
"bytes"
"log/slog"
"strings"
"testing"
)
// TestSecretConfigsRedactedInLogs is the security guard for config redaction:
// no matter whether the whole Config or a single section is logged, the
// LiveKit key/secret, GitHub token, and Klipy key must never reach the output.
func TestSecretConfigsRedactedInLogs(t *testing.T) {
const (
lkKey = "LIVEKIT_KEY_should_not_appear"
lkSecret = "LIVEKIT_SECRET_should_not_appear"
ghToken = "ghp_token_should_not_appear"
gifKey = "klipy_key_should_not_appear"
)
cfg := Config{
Voice: VoiceConfig{LiveKitAPIKey: lkKey, LiveKitAPISecret: lkSecret, Quality: "high"},
GitHub: GitHubConfig{Token: ghToken, Owner: "acme"},
GIF: GIFConfig{APIKey: gifKey},
}
var buf bytes.Buffer
log := slog.New(slog.NewTextHandler(&buf, nil))
log.Info("whole", "config", cfg) // whole-config path (delegating LogValue)
log.Info("voice", "voice", cfg.Voice)
log.Info("github", "github", cfg.GitHub)
log.Info("gif", "gif", cfg.GIF)
out := buf.String()
for _, secret := range []string{lkKey, lkSecret, ghToken, gifKey} {
if strings.Contains(out, secret) {
t.Errorf("secret leaked into log output: %q\n%s", secret, out)
}
}
if !strings.Contains(out, "high") || !strings.Contains(out, "acme") {
t.Errorf("expected non-secret fields in output:\n%s", out)
}
if !strings.Contains(out, "[REDACTED]") {
t.Errorf("expected redaction marker in output:\n%s", out)
}
}
+34
View File
@@ -0,0 +1,34 @@
package db
import "log/slog"
// This file makes the secret-bearing domain types safe to log by construction.
// User.PasswordHash / User.TOTPSecret and Session.TokenHash are json:"-", but
// that only guards JSON responses — slog renders struct fields regardless. By
// implementing slog.LogValuer, logging a *db.User or *db.Session (e.g.
// slog.Info("x", "user", user)) never emits the credential. Secret fields are
// omitted entirely; the useful identifying fields stay visible.
// LogValue omits PasswordHash and TOTPSecret. It exposes whether TOTP is
// enabled (not the secret) since that is often what a log line needs.
func (u User) LogValue() slog.Value {
return slog.GroupValue(
slog.Int64("id", u.ID),
slog.String("username", u.Username),
slog.Int64("role_id", u.RoleID),
slog.String("status", u.Status),
slog.Bool("banned", u.Banned),
slog.Bool("totp_enabled", u.TOTPSecret != nil),
)
}
// LogValue omits TokenHash (the session-identifying secret).
func (s Session) LogValue() slog.Value {
return slog.GroupValue(
slog.Int64("id", s.ID),
slog.Int64("user_id", s.UserID),
slog.String("device", s.Device),
slog.String("ip", s.IP),
slog.String("expires_at", s.ExpiresAt),
)
}
+41
View File
@@ -0,0 +1,41 @@
package db
import (
"bytes"
"log/slog"
"strings"
"testing"
)
// TestUserSessionRedactedInLogs is the security guard for domain-type
// redaction: logging a db.User / db.Session (by value or by pointer) must never
// emit the password hash, TOTP secret, or session token hash.
func TestUserSessionRedactedInLogs(t *testing.T) {
const (
pwHash = "PWHASH_should_not_appear"
totp = "TOTP_SECRET_should_not_appear"
token = "TOKENHASH_should_not_appear"
)
totpPtr := totp
user := User{ID: 7, Username: "alice", PasswordHash: pwHash, TOTPSecret: &totpPtr, RoleID: 2}
sess := Session{ID: 3, UserID: 7, TokenHash: token, Device: "cli"}
var buf bytes.Buffer
log := slog.New(slog.NewTextHandler(&buf, nil))
// Value and pointer paths — both must resolve LogValue.
log.Info("u", "user", user, "user_ptr", &user)
log.Info("s", "session", sess, "session_ptr", &sess)
out := buf.String()
for _, secret := range []string{pwHash, totp, token} {
if strings.Contains(out, secret) {
t.Errorf("secret leaked into log output: %q\n%s", secret, out)
}
}
if !strings.Contains(out, "alice") {
t.Errorf("expected username in output:\n%s", out)
}
if !strings.Contains(out, "totp_enabled=true") {
t.Errorf("expected totp_enabled flag in output:\n%s", out)
}
}
+54
View File
@@ -0,0 +1,54 @@
// Package logctx provides a slog.Handler that enriches every log record with
// correlation IDs pulled from the context: the chi request ID (as req_id) and,
// under -tags otel, the OpenTelemetry trace ID (as trace_id).
//
// Wrapping the base handler with New means any log call using the ...Context
// variants (slog.InfoContext, slog.ErrorContext, …) automatically carries
// these IDs, so a log line can be tied back to its HTTP request and its
// distributed trace without threading the IDs through by hand at every site.
package logctx
import (
"context"
"log/slog"
"github.com/go-chi/chi/v5/middleware"
"github.com/owncord/server/telemetry"
)
type handler struct {
inner slog.Handler
}
// New wraps inner so that records handled with a context carrying a chi request
// ID (and, in the otel build, an active span) are enriched with req_id and
// trace_id attributes.
func New(inner slog.Handler) slog.Handler {
return handler{inner: inner}
}
func (h handler) Enabled(ctx context.Context, l slog.Level) bool {
return h.inner.Enabled(ctx, l)
}
func (h handler) Handle(ctx context.Context, r slog.Record) error {
if reqID := middleware.GetReqID(ctx); reqID != "" {
r.AddAttrs(slog.String("req_id", reqID))
}
if tid := telemetry.TraceIDFromContext(ctx); tid != "" {
r.AddAttrs(slog.String("trace_id", tid))
}
return h.inner.Handle(ctx, r)
}
func (h handler) WithAttrs(attrs []slog.Attr) slog.Handler {
return handler{inner: h.inner.WithAttrs(attrs)}
}
// WithGroup re-wraps so enrichment survives logger.WithGroup.
// ponytail: req_id/trace_id are added at the record's top level; the codebase
// opens no logger-level groups, so there is no group-nesting concern to handle
// here. Revisit if slog group usage is introduced.
func (h handler) WithGroup(name string) slog.Handler {
return handler{inner: h.inner.WithGroup(name)}
}
+38
View File
@@ -0,0 +1,38 @@
package logctx
import (
"bytes"
"context"
"log/slog"
"strings"
"testing"
"github.com/go-chi/chi/v5/middleware"
)
// TestHandlerAddsReqID verifies the enriching handler stamps req_id when the
// context carries a chi request ID, and omits it otherwise. (trace_id is only
// populated under -tags otel and is covered by manual verification.)
func TestHandlerAddsReqID(t *testing.T) {
var buf bytes.Buffer
log := slog.New(New(slog.NewTextHandler(&buf, nil)))
ctx := context.WithValue(context.Background(), middleware.RequestIDKey, "req-abc-123")
log.InfoContext(ctx, "hello")
if !strings.Contains(buf.String(), "req_id=req-abc-123") {
t.Errorf("expected req_id in output, got: %s", buf.String())
}
buf.Reset()
log.InfoContext(context.Background(), "plain")
if strings.Contains(buf.String(), "req_id") {
t.Errorf("did not expect req_id without a request ID: %s", buf.String())
}
// Enrichment must survive logger.With (WithAttrs re-wrap).
buf.Reset()
log.With("k", "v").InfoContext(ctx, "withattrs")
if !strings.Contains(buf.String(), "req_id=req-abc-123") {
t.Errorf("expected req_id to survive With(): %s", buf.String())
}
}
+20 -5
View File
@@ -23,6 +23,7 @@ import (
"github.com/owncord/server/auth"
"github.com/owncord/server/config"
"github.com/owncord/server/db"
"github.com/owncord/server/logctx"
"github.com/owncord/server/plugin"
"github.com/owncord/server/storage"
"github.com/owncord/server/telemetry"
@@ -36,12 +37,18 @@ func main() {
// Create ring buffer for admin log viewer, then build a multi-handler
// that tees log records to both stdout (INFO+) and the ring buffer (DEBUG+).
logBuf := admin.NewRingBuffer(2000)
stdoutHandler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo})
// levelVar controls the stdout handler's threshold. It starts at INFO (the
// zero value) so early-startup logs are captured, then run() raises/lowers
// it once config.yaml / OWNCORD_LOGGING_LEVEL is loaded.
levelVar := new(slog.LevelVar)
stdoutHandler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: levelVar})
multiHandler := admin.NewMultiHandler(stdoutHandler, logBuf, slog.LevelDebug)
log := slog.New(multiHandler)
// logctx enriches records logged with a request/trace context (the
// ...Context slog variants) with req_id and, under -tags otel, trace_id.
log := slog.New(logctx.New(multiHandler))
slog.SetDefault(log)
if err := run(log, logBuf); err != nil {
if err := run(log, logBuf, levelVar); err != nil {
_, _ = fmt.Fprintf(os.Stderr, "\n [ERROR] %v\n\n", err)
log.Error("server exited with error", "error", err)
os.Exit(1)
@@ -49,7 +56,7 @@ func main() {
}
// run is the real entrypoint — separated for testability.
func run(log *slog.Logger, logBuf *admin.RingBuffer) error {
func run(log *slog.Logger, logBuf *admin.RingBuffer, levelVar *slog.LevelVar) error {
// bgCtx is a cancellable context shared by all background goroutines
// (event persister, event pruner, plugin loader, maintenance loop).
// It is cancelled early in the shutdown sequence so in-flight DB
@@ -78,6 +85,14 @@ func run(log *slog.Logger, logBuf *admin.RingBuffer) error {
return fmt.Errorf("loading config: %w", err)
}
// Apply the configured stdout log level. The ring buffer keeps capturing
// DEBUG regardless, so the admin panel's live log view is unaffected.
if lvl, ok := config.ParseLevel(cfg.Logging.Level); ok {
levelVar.Set(lvl)
} else {
log.Warn("unknown logging.level, keeping info", "value", cfg.Logging.Level)
}
// ── 2. Ensure data directory exists ────────────────────────────────────
if mkdirErr := os.MkdirAll(cfg.Server.DataDir, 0o750); mkdirErr != nil {
return fmt.Errorf("creating data dir %s: %w", cfg.Server.DataDir, mkdirErr)
@@ -366,7 +381,7 @@ func isAddrInUse(err error) bool {
}
// printBanner writes the startup banner to stderr (so it doesn't mix with
// JSON-structured log output on stdout).
// the structured log output on stdout).
func printBanner(cfg *config.Config, ver string, tls bool) {
scheme := "http"
if tls {
+3 -3
View File
@@ -46,7 +46,7 @@ func (s *BlockService) BlockUser(ctx context.Context, blockerID, targetID int64)
}
if err := s.st.BlockUser(ctx, blockerID, targetID); err != nil {
return fmt.Errorf("%w: failed to block user", ErrInternal)
return fmt.Errorf("%w: failed to block user: %v", ErrInternal, err)
}
slog.Info("user blocked", "blocker_id", blockerID, "target_id", targetID)
@@ -59,7 +59,7 @@ func (s *BlockService) UnblockUser(ctx context.Context, blockerID, targetID int6
return fmt.Errorf("%w: user_id must be positive", ErrBadRequest)
}
if err := s.st.UnblockUser(ctx, blockerID, targetID); err != nil {
return fmt.Errorf("%w: failed to unblock user", ErrInternal)
return fmt.Errorf("%w: failed to unblock user: %v", ErrInternal, err)
}
slog.Info("user unblocked", "blocker_id", blockerID, "target_id", targetID)
return nil
@@ -69,7 +69,7 @@ func (s *BlockService) UnblockUser(ctx context.Context, blockerID, targetID int6
func (s *BlockService) ListBlocked(ctx context.Context, blockerID int64) ([]int64, error) {
ids, err := s.st.ListBlockedUsers(ctx, blockerID)
if err != nil {
return nil, fmt.Errorf("%w: failed to list blocked users", ErrInternal)
return nil, fmt.Errorf("%w: failed to list blocked users: %v", ErrInternal, err)
}
if ids == nil {
ids = []int64{}
+3 -3
View File
@@ -55,7 +55,7 @@ func (s *DMService) CreateDM(ctx context.Context, userID, recipientID int64) (*C
blocked, err := s.st.IsEitherBlocked(ctx, userID, recipientID)
if err != nil {
return nil, fmt.Errorf("%w: failed to check block status", ErrInternal)
return nil, fmt.Errorf("%w: failed to check block status: %v", ErrInternal, err)
}
if blocked {
return nil, fmt.Errorf("%w: cannot create DM — user is blocked", ErrForbidden)
@@ -78,7 +78,7 @@ func (s *DMService) CreateDM(ctx context.Context, userID, recipientID int64) (*C
func (s *DMService) ListDMs(ctx context.Context, userID int64) ([]db.DMChannelInfo, error) {
dms, err := s.st.GetUserDMChannels(ctx, userID)
if err != nil {
return nil, fmt.Errorf("%w: failed to list DMs", ErrInternal)
return nil, fmt.Errorf("%w: failed to list DMs: %v", ErrInternal, err)
}
return dms, nil
}
@@ -95,7 +95,7 @@ func (s *DMService) CloseDM(ctx context.Context, userID, channelID int64) error
}
if err := s.st.CloseDM(ctx, userID, channelID); err != nil {
return fmt.Errorf("%w: failed to close DM", ErrInternal)
return fmt.Errorf("%w: failed to close DM: %v", ErrInternal, err)
}
slog.Debug("DM closed", "user_id", userID, "channel_id", channelID)
+4 -4
View File
@@ -50,12 +50,12 @@ func (s *InviteService) CreateInvite(ctx context.Context, createdBy int64, maxUs
code, err := s.st.CreateInvite(ctx, createdBy, maxUses, expiresAt)
if err != nil {
return nil, fmt.Errorf("%w: failed to create invite", ErrInternal)
return nil, fmt.Errorf("%w: failed to create invite: %v", ErrInternal, err)
}
invite, err := s.st.GetInvite(ctx, code)
if err != nil || invite == nil {
return nil, fmt.Errorf("%w: failed to retrieve invite", ErrInternal)
return nil, fmt.Errorf("%w: failed to retrieve invite: %v", ErrInternal, err)
}
return invite, nil
}
@@ -64,7 +64,7 @@ func (s *InviteService) CreateInvite(ctx context.Context, createdBy int64, maxUs
func (s *InviteService) ListInvites(ctx context.Context) ([]*db.Invite, error) {
invites, err := s.st.ListInvites(ctx)
if err != nil {
return nil, fmt.Errorf("%w: failed to list invites", ErrInternal)
return nil, fmt.Errorf("%w: failed to list invites: %v", ErrInternal, err)
}
return invites, nil
}
@@ -76,7 +76,7 @@ func (s *InviteService) RevokeInvite(ctx context.Context, code string) error {
return fmt.Errorf("%w: invite not found", ErrNotFound)
}
if err := s.st.RevokeInvite(ctx, code); err != nil {
return fmt.Errorf("%w: failed to revoke invite", ErrInternal)
return fmt.Errorf("%w: failed to revoke invite: %v", ErrInternal, err)
}
return nil
}
+8 -8
View File
@@ -559,7 +559,7 @@ func (s *MessageService) SearchMessages(ctx context.Context, userID int64, query
}
results, err := s.st.SearchMessages(ctx, query, channelID, limit)
if err != nil {
return nil, fmt.Errorf("%w: search failed", ErrInternal)
return nil, fmt.Errorf("%w: search failed: %v", ErrInternal, err)
}
return results, nil
}
@@ -575,7 +575,7 @@ func (s *MessageService) SearchMessages(ctx context.Context, userID int64, query
results, err := s.st.SearchMessagesInChannels(ctx, query, accessibleIDs, limit)
if err != nil {
return nil, fmt.Errorf("%w: search failed", ErrInternal)
return nil, fmt.Errorf("%w: search failed: %v", ErrInternal, err)
}
return results, nil
}
@@ -599,7 +599,7 @@ func (s *MessageService) GetPinnedMessages(ctx context.Context, userID, channelI
}
msgs, err := s.st.GetPinnedMessages(ctx, channelID, userID)
if err != nil {
return nil, fmt.Errorf("%w: failed to fetch pinned messages", ErrInternal)
return nil, fmt.Errorf("%w: failed to fetch pinned messages: %v", ErrInternal, err)
}
return msgs, nil
}
@@ -633,12 +633,12 @@ func (s *MessageService) SetMessagePinned(ctx context.Context, userID, channelID
func (s *MessageService) GetAccessibleChannelIDs(ctx context.Context, userID int64) ([]int64, error) {
channels, err := s.st.ListChannels(ctx)
if err != nil {
return nil, fmt.Errorf("%w: failed to list channels", ErrInternal)
return nil, fmt.Errorf("%w: failed to list channels: %v", ErrInternal, err)
}
role, err := s.perms.GetRoleForUser(ctx, userID)
if err != nil || role == nil {
return nil, fmt.Errorf("%w: failed to get role", ErrInternal)
return nil, fmt.Errorf("%w: failed to get role: %v", ErrInternal, err)
}
var overrides map[int64]db.ChannelOverride
@@ -646,7 +646,7 @@ func (s *MessageService) GetAccessibleChannelIDs(ctx context.Context, userID int
var overrideErr error
overrides, overrideErr = s.st.GetAllChannelPermissionsForRole(ctx, role.ID)
if overrideErr != nil {
return nil, fmt.Errorf("%w: failed to fetch channel overrides", ErrInternal)
return nil, fmt.Errorf("%w: failed to fetch channel overrides: %v", ErrInternal, overrideErr)
}
}
@@ -693,7 +693,7 @@ func (s *MessageService) checkSendPermission(ctx context.Context, userID, channe
if isDM {
ok, err := s.st.IsDMParticipant(ctx, userID, channelID)
if err != nil {
return fmt.Errorf("%w: failed to check DM participation", ErrInternal)
return fmt.Errorf("%w: failed to check DM participation: %v", ErrInternal, err)
}
if !ok {
return fmt.Errorf("%w: not a participant in this DM", ErrForbidden)
@@ -702,7 +702,7 @@ func (s *MessageService) checkSendPermission(ctx context.Context, userID, channe
if err == nil && recipient != nil {
blocked, blkErr := s.st.IsEitherBlocked(ctx, userID, recipient.ID)
if blkErr != nil {
return fmt.Errorf("%w: failed to check block status", ErrInternal)
return fmt.Errorf("%w: failed to check block status: %v", ErrInternal, blkErr)
}
if blocked {
return fmt.Errorf("%w: cannot send messages — user is blocked", ErrBlocked)
+2 -2
View File
@@ -96,7 +96,7 @@ func (s *ModerationService) BanUser(ctx context.Context, actorID, targetID int64
}
if err := s.st.BanUser(ctx, targetID, reason, expires); err != nil {
return fmt.Errorf("%w: failed to ban user", ErrInternal)
return fmt.Errorf("%w: failed to ban user: %v", ErrInternal, err)
}
// Audit rows must survive a request canceled after the ban committed.
@@ -125,7 +125,7 @@ func (s *ModerationService) UnbanUser(ctx context.Context, actorID, targetID int
}
if err := s.st.UnbanUser(ctx, targetID); err != nil {
return fmt.Errorf("%w: failed to unban user", ErrInternal)
return fmt.Errorf("%w: failed to unban user: %v", ErrInternal, err)
}
// Audit rows must survive a request canceled after the unban committed.
+5 -5
View File
@@ -38,11 +38,11 @@ func (s *UserService) UpdateProfile(ctx context.Context, userID int64, username
if db.IsUniqueConstraintError(err) {
return nil, fmt.Errorf("%w: username is already taken", ErrConflict)
}
return nil, fmt.Errorf("%w: failed to update profile", ErrInternal)
return nil, fmt.Errorf("%w: failed to update profile: %v", ErrInternal, err)
}
user, err := s.st.GetUserByID(ctx, userID)
if err != nil {
return nil, fmt.Errorf("%w: failed to fetch updated user", ErrInternal)
return nil, fmt.Errorf("%w: failed to fetch updated user: %v", ErrInternal, err)
}
// Audit rows must survive a request canceled after the write committed.
db.WriteAudit(context.WithoutCancel(ctx), s.st, userID, "profile_update", "user", userID,
@@ -82,7 +82,7 @@ type ChangePasswordResult struct {
// ChangePassword updates the user's password and revokes other sessions.
func (s *UserService) ChangePassword(ctx context.Context, userID int64, newPasswordHash string, keepSessionID int64) (ChangePasswordResult, error) {
if err := s.st.UpdateUserPassword(ctx, userID, newPasswordHash); err != nil {
return ChangePasswordResult{}, fmt.Errorf("%w: failed to update password", ErrInternal)
return ChangePasswordResult{}, fmt.Errorf("%w: failed to update password: %v", ErrInternal, err)
}
// The password is committed from here on: every path below reports
@@ -114,7 +114,7 @@ func (s *UserService) ChangePassword(ctx context.Context, userID int64, newPassw
func (s *UserService) ListSessions(ctx context.Context, userID int64) ([]db.Session, error) {
sessions, err := s.st.ListUserSessions(ctx, userID)
if err != nil {
return nil, fmt.Errorf("%w: failed to list sessions", ErrInternal)
return nil, fmt.Errorf("%w: failed to list sessions: %v", ErrInternal, err)
}
return sessions, nil
}
@@ -125,7 +125,7 @@ func (s *UserService) RevokeSession(ctx context.Context, userID, sessionID int64
if errors.Is(err, db.ErrNotFound) {
return fmt.Errorf("%w: session not found", ErrNotFound)
}
return fmt.Errorf("%w: failed to revoke session", ErrInternal)
return fmt.Errorf("%w: failed to revoke session: %v", ErrInternal, err)
}
// Audit rows must survive a request canceled after the delete committed.
db.WriteAudit(context.WithoutCancel(ctx), s.st, userID, "session_revoke", "session", sessionID, "session revoked")
+45
View File
@@ -0,0 +1,45 @@
// Package stackutil captures goroutine stack traces for panic logging in a
// form that is safe to persist and stream.
//
// runtime.Stack embeds function argument values as raw hex words. For
// arguments passed by value (e.g. a [32]byte room key or a [16]byte IV) that
// exposes the actual bytes — secret material such as E2EE keys, session
// tokens, or passwords that flowed through a panicking call. Because the
// server tees panic logs into the admin ring buffer and streams them over SSE,
// a single panic on a crypto or auth path could leak keys to any admin viewer.
//
// Capture avoids this by using runtime.Callers + CallersFrames, which yields
// only function names and source locations — never argument data.
package stackutil
import (
"runtime"
"strconv"
"strings"
)
// Capture returns a compact, argument-free stack trace for the calling
// goroutine: one "func" line followed by a "\tfile:line" line per frame. It is
// safe to log even when the panicking function held sensitive arguments.
func Capture() string {
pcs := make([]uintptr, 64)
n := runtime.Callers(2, pcs) // skip runtime.Callers and Capture itself
if n == 0 {
return ""
}
frames := runtime.CallersFrames(pcs[:n])
var b strings.Builder
for {
f, more := frames.Next()
b.WriteString(f.Function)
b.WriteString("\n\t")
b.WriteString(f.File)
b.WriteByte(':')
b.WriteString(strconv.Itoa(f.Line))
b.WriteByte('\n')
if !more {
break
}
}
return b.String()
}
+48
View File
@@ -0,0 +1,48 @@
package stackutil
import (
"strings"
"testing"
)
//go:noinline
func panicWithSecretArgs(key [32]byte, token string) {
// key is passed by value, so runtime.Stack would render its bytes as hex.
_ = key
_ = token
panic("boom")
}
// TestCaptureOmitsArguments is the security guard: Capture must never emit
// argument values. runtime.Stack renders by-value args as hex words ("0x..."),
// so asserting the output is free of hex verifies no argument bytes leaked,
// while still carrying the panicking function name and source location.
func TestCaptureOmitsArguments(t *testing.T) {
var key [32]byte
for i := range key {
key[i] = 0xAB
}
var stack string
func() {
defer func() {
if recover() != nil {
stack = Capture()
}
}()
panicWithSecretArgs(key, "super-secret-token")
}()
if stack == "" {
t.Fatal("expected a captured stack after recover")
}
if strings.Contains(stack, "0x") {
t.Errorf("captured stack contains hex argument words (possible secret leak):\n%s", stack)
}
if !strings.Contains(stack, "panicWithSecretArgs") {
t.Errorf("captured stack missing the panicking function name:\n%s", stack)
}
if !strings.Contains(stack, "stackutil_test.go:") {
t.Errorf("captured stack missing source location:\n%s", stack)
}
}
+4
View File
@@ -20,3 +20,7 @@ func Init(_ context.Context, cfg config.TelemetryConfig) (ShutdownFunc, error) {
SetGlobal(noopProvider{})
return func(context.Context) error { return nil }, nil
}
// TraceIDFromContext returns the active trace ID as a hex string, or "" when no
// span is active. The default build has no tracing, so it always returns "".
func TraceIDFromContext(_ context.Context) string { return "" }
+10
View File
@@ -178,6 +178,16 @@ func (p *otelProvider) HTTPMiddleware(next http.Handler) http.Handler {
// exporter registry.
func (p *otelProvider) PrometheusHandler() http.Handler { return p.promHandler }
// TraceIDFromContext returns the active trace ID as a hex string, or "" when no
// span is recording in ctx. Used to stamp log records with trace_id so logs
// correlate with traces.
func TraceIDFromContext(ctx context.Context) string {
if sc := trace.SpanContextFromContext(ctx); sc.HasTraceID() {
return sc.TraceID().String()
}
return ""
}
// ── Tracer / Span adapters ─────────────────────────────────────────────────
type otelTracer struct{ inner trace.Tracer }
+2 -4
View File
@@ -6,7 +6,6 @@ import (
"context"
"fmt"
"log/slog"
"runtime"
"sync"
"sync/atomic"
"time"
@@ -16,6 +15,7 @@ import (
"github.com/owncord/server/permissions"
"github.com/owncord/server/plugin"
"github.com/owncord/server/service"
"github.com/owncord/server/stackutil"
"github.com/owncord/server/syncutil"
)
@@ -276,12 +276,10 @@ func (h *Hub) Run() {
}
panicCount++
buf := make([]byte, 4096)
n := runtime.Stack(buf, false)
slog.Error("hub: panic recovered",
"panic", r,
"panic_count", panicCount,
"stack", string(buf[:n]))
"stack", stackutil.Capture())
if panicCount >= 3 {
slog.Error("hub: too many panics in 60s, stopping")
+5 -6
View File
@@ -4,7 +4,8 @@ import (
"context"
"fmt"
"log/slog"
"runtime"
"github.com/owncord/server/stackutil"
)
// handlerV2Entry pairs a V2 handler with its domain-specific dependency struct.
@@ -47,15 +48,13 @@ func (r *HandlerRegistry) DispatchV2(ctx context.Context, cmd Command, info Clie
}
defer func() {
if rec := recover(); rec != nil {
buf := make([]byte, 4096)
n := runtime.Stack(buf, false)
// TODO: stack trace may contain sensitive function arguments
// (e.g. encrypted keys). Consider scrubbing or limiting frames.
// stackutil.Capture omits argument values, which for E2EE
// handlers can include encrypted key material.
slog.Error("DispatchV2 panic recovered",
"type", cmd.Type(),
"user_id", info.UserID,
"panic", rec,
"stack", string(buf[:n]),
"stack", stackutil.Capture(),
)
result = Result{Error: ClientError{Code: ErrCodeInternal, Message: "internal error"}}
ok = true
+8
View File
@@ -503,6 +503,11 @@ func authenticateConn(parent context.Context, conn *websocket.Conn, database *db
sess, err := database.GetSessionByTokenHash(ctx, hash)
if err != nil || sess == nil {
_ = conn.Write(ctx, websocket.MessageText, buildAuthError("invalid token"))
if err != nil {
// DB outage, not a bad token — carry the cause so the caller's log
// distinguishes it from an ordinary invalid-token rejection.
return nil, "", 0, fmt.Errorf("auth: session lookup failed: %w", err)
}
return nil, "", 0, fmt.Errorf("auth: invalid session")
}
@@ -514,6 +519,9 @@ func authenticateConn(parent context.Context, conn *websocket.Conn, database *db
user, err := database.GetUserByID(ctx, sess.UserID)
if err != nil || user == nil {
_ = conn.Write(ctx, websocket.MessageText, buildAuthError("user not found"))
if err != nil {
return nil, "", 0, fmt.Errorf("auth: user lookup failed: %w", err)
}
return nil, "", 0, fmt.Errorf("auth: user not found")
}
+11 -2
View File
@@ -4,6 +4,7 @@ import (
"context"
"encoding/base64"
"fmt"
"log/slog"
"time"
)
@@ -226,10 +227,18 @@ func (h *Hub) sendToUserIfInVoiceChannel(voiceChannelID, targetUserID int64, msg
target, ok := h.clients[targetUserID]
if !ok {
return // target not connected — silently drop
// Undeliverable key offer can leave the peer unable to decrypt — the
// payload is dropped, but log (IDs only, never the encrypted key) so
// the failure is diagnosable rather than silent.
slog.Debug("e2ee: key offer dropped, target not connected",
"target_user_id", targetUserID, "voice_channel_id", voiceChannelID)
return
}
if target.getVoiceChID() != voiceChannelID {
return // target not in expected voice channel — silently drop
slog.Debug("e2ee: key offer dropped, target not in expected voice channel",
"target_user_id", targetUserID, "voice_channel_id", voiceChannelID,
"target_voice_channel_id", target.getVoiceChID())
return
}
target.sendMsg(msg)
}