From fd5b4d212c2f90cd5803dba35da8a532a0f19904 Mon Sep 17 00:00:00 2001 From: Esa Kataja Date: Sat, 5 Sep 2026 14:56:12 +0300 Subject: [PATCH] Give a failed submission a code, and put the cause in the log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A download that died on an HTTP 403 told the submitter "HTTP Error 403: Forbidden" and told the log "error: exit status 1". The tool's stderr went into status_msg and nowhere else, so the one person who could act on it saw nothing. Exactly backwards. Failures now go through a.fail: the submitter gets a sentence and an eight character code, the log gets that code, the stage, the submission, the source URL and the stderr tail. Quote the code, grep the log, find the line. Every record carries file:line now, and LOG_LEVEL sets the threshold — failures are logged at error, so no level hides them. --- .env.example | 4 ++++ README.md | 1 + docker-compose.yml | 1 + docs/deployment.md | 3 ++- src/main.go | 17 ++++++++++++++++- src/submit.go | 47 +++++++++++++++++++++++++++++++++------------- src/submit_test.go | 36 +++++++++++++++++++++++++++++++++++ 7 files changed, 94 insertions(+), 15 deletions(-) diff --git a/.env.example b/.env.example index 86da3af..ac1de31 100644 --- a/.env.example +++ b/.env.example @@ -9,6 +9,10 @@ ADMIN_NAME=Ylläpito # Set to false only for local development over plain HTTP. SECURE_COOKIES=true +# debug, info, warn or error. debug adds the per-request noise; failures are logged at error +# regardless, with the same code the submitter is shown. +LOG_LEVEL=info + # Public address of the site. Used to build pasteable invite links on the admin page. # Unset falls back to a relative link, which is fine locally. PUBLIC_URL=https://levyraati.example.com diff --git a/README.md b/README.md index f44ab95..b1b5b8b 100644 --- a/README.md +++ b/README.md @@ -76,6 +76,7 @@ in as that account and mint invites for everyone else. The two variables are rea | `ADDR` | `:8080` | The only listener | | `STORAGE_DIR` | `./storage` | Audio, avatars, in-flight conversions | | `SECURE_COOKIES` | `true` | Set `false` for local development over plain HTTP | +| `LOG_LEVEL` | `info` | `debug`, `info`, `warn` or `error`. An unparseable value falls back to `info` | | `PUBLIC_URL` | — | Public address of the site, e.g. `https://levyraati.example.com`. Used to build invite links on the admin page; unset gives relative links | ### Local development diff --git a/docker-compose.yml b/docker-compose.yml index 9549e64..8026e83 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -11,6 +11,7 @@ services: ADMIN_NAME: ${ADMIN_NAME:-Ylläpito} ADDR: ":8080" SECURE_COOKIES: ${SECURE_COOKIES:-true} + LOG_LEVEL: ${LOG_LEVEL:-info} PUBLIC_URL: ${PUBLIC_URL:-} # The SQLite file sits in here beside the audio, so this one mount is the whole backup. volumes: diff --git a/docs/deployment.md b/docs/deployment.md index 7f79fa1..9ffece9 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -269,6 +269,7 @@ bounded by the two conversion slots. | Uploads fail near 50 MB | The reverse proxy's body limit, not the app's | | Invite links are relative | `PUBLIC_URL` unset | | Everything 500s after a restore | `-wal`/`-shm` sidecars from the replaced database were left in place | -| Submissions all fail at download | yt-dlp is stale; rebuild and publish the image | +| Submissions all fail at download | yt-dlp is stale, or YouTube is refusing this server's IP; rebuild and publish the image first. `docker compose logs app \| grep '"stage":"download"'` shows yt-dlp's own stderr under `detail` | +| A submitter reports a *virhekoodi* | `docker compose logs app \| grep ` — one line, with the stage, the submission id, the URL and the tool's stderr | | `/admin` returns 404 while logged in | That account has no `is_admin`. Set it in the database; nothing in the UI grants it | | Setting `ADMIN_PASSWORD` again changes nothing | Seeding only fires on an empty `users` table. Reset the hash in the database instead | diff --git a/src/main.go b/src/main.go index 73c6bbe..88b58a0 100644 --- a/src/main.go +++ b/src/main.go @@ -91,8 +91,23 @@ func affected(res sql.Result) int64 { return n } +// LOG_LEVEL is debug, info, warn or error. slog parses those itself, so an unreadable value falls +// back to info rather than refusing to boot over a logging setting. +func logLevel() slog.Level { + var l slog.Level + if err := l.UnmarshalText([]byte(env("LOG_LEVEL", "info"))); err != nil { + return slog.LevelInfo + } + return l +} + func main() { - slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, nil))) + // AddSource puts file:line on every record, so a log line found by its error code leads + // straight to the branch that wrote it. + slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ + AddSource: true, + Level: logLevel(), + }))) slog.Info("starting", "ctx", "startup", "version", version) cfg := loadConfig() diff --git a/src/submit.go b/src/submit.go index 081317f..fa9cbdf 100644 --- a/src/submit.go +++ b/src/submit.go @@ -2,7 +2,9 @@ package main import ( "context" + "crypto/rand" "database/sql" + "encoding/hex" "errors" "fmt" "io" @@ -326,13 +328,11 @@ func (a *app) process(subID int64, sourceURL, src string) { if sourceURL != "" { a.setStatus(ctx, subID, "downloading", "") - msg, err := downloadYouTube(ctx, sourceURL, a.tmpPath(subID, ".%(ext)s")) + detail, err := downloadYouTube(ctx, sourceURL, a.tmpPath(subID, ".%(ext)s")) if err != nil { - if msg == "" { - msg = err.Error() - } - a.setStatus(ctx, subID, "failed", msg) - slog.Warn("download failed", "ctx", "submissions", "submission", subID, "error", err) + a.fail(ctx, subID, "download", + "Kappaleen lataaminen ei onnistunut. Yritä myöhemmin uudelleen.", + detail, err, "url", sourceURL) return } // yt-dlp names the file after whatever container YouTube served. @@ -344,7 +344,9 @@ func (a *app) process(subID int64, sourceURL, src string) { } } if src == "" { - a.setStatus(ctx, subID, "failed", "lataus ei tuottanut tiedostoa") + a.fail(ctx, subID, "download", + "Kappaleen lataaminen ei onnistunut. Yritä myöhemmin uudelleen.", + "yt-dlp exited cleanly but produced no file", nil, "url", sourceURL) return } if _, err := a.db.ExecContext(ctx, @@ -356,14 +358,12 @@ func (a *app) process(subID int64, sourceURL, src string) { a.setStatus(ctx, subID, "converting", "") out := a.tmpPath(subID, ".ogg") - msg, err := convertToOpus(ctx, src, out) + detail, err := convertToOpus(ctx, src, out) if err != nil { os.Remove(out) - if msg == "" { - msg = err.Error() - } - a.setStatus(ctx, subID, "failed", msg) - slog.Warn("conversion failed", "ctx", "submissions", "submission", subID, "error", err) + a.fail(ctx, subID, "convert", + "Tiedostoa ei voitu muuntaa. Onko se varmasti äänitiedosto?", + detail, err) return } // The original is discarded as soon as the Opus exists. @@ -393,6 +393,27 @@ func (a *app) process(subID int64, sourceURL, src string) { a.autoFetchLyrics(ctx, subID, title, artist, seconds) } +// Short enough to read out over chat, long enough not to collide in a log worth grepping. +func traceID() string { + b := make([]byte, 4) + rand.Read(b) + return hex.EncodeToString(b) +} + +// fail is the only way a submission is marked failed. The submitter gets a sentence they can act +// on plus a code; the log line gets that same code and everything that identifies the cause — +// including the tool's own stderr, which used to go to the submitter and nowhere else. A download +// that died on an HTTP 403 left "error: exit status 1" in the log and nothing else. +func (a *app) fail(ctx context.Context, subID int64, stage, userMsg, detail string, err error, extra ...any) { + code := traceID() + args := []any{ + "ctx", "submissions", "code", code, "stage", stage, "submission", subID, + "detail", detail, "error", err, + } + slog.Error("submission failed", append(args, extra...)...) + a.setStatus(ctx, subID, "failed", fmt.Sprintf("%s (virhekoodi %s)", userMsg, code)) +} + func (a *app) setStatus(ctx context.Context, subID int64, status, msg string) { if _, err := a.db.ExecContext(ctx, `update submissions set status = $2, status_msg = nullif($3, '') where id = $1`, diff --git a/src/submit_test.go b/src/submit_test.go index 617981b..895e8ed 100644 --- a/src/submit_test.go +++ b/src/submit_test.go @@ -8,6 +8,8 @@ import ( "os" "os/exec" "path/filepath" + "regexp" + "strings" "testing" ) @@ -220,3 +222,37 @@ func TestRestartRecovery(t *testing.T) { t.Fatal("swept submission carries no explanation") } } + +// The submitter must get a code they can quote, and must not get yt-dlp's stderr. The code is the +// only thing tying their screenshot to the log line that says what actually broke. +func TestFailGivesTraceableCodeNotToolOutput(t *testing.T) { + a := testApp(t) + ctx := context.Background() + uid := a.seedMember(t, "esa@example.com") + + var subID int64 + if err := a.db.QueryRowContext(ctx, + `insert into submissions (user_id, status) values ($1, 'downloading') returning id`, + uid).Scan(&subID); err != nil { + t.Fatal(err) + } + + const secret = "HTTP Error 403: Forbidden" + a.fail(ctx, subID, "download", "Kappaleen lataaminen ei onnistunut.", secret, + fmt.Errorf("exit status 1"), "url", "https://youtu.be/x") + + var status, msg string + if err := a.db.QueryRowContext(ctx, + `select status, status_msg from submissions where id = $1`, subID).Scan(&status, &msg); err != nil { + t.Fatal(err) + } + if status != "failed" { + t.Fatalf("status = %q, want failed", status) + } + if strings.Contains(msg, secret) { + t.Fatalf("tool stderr leaked to the submitter: %q", msg) + } + if !regexp.MustCompile(`\(virhekoodi [0-9a-f]{8}\)$`).MatchString(msg) { + t.Fatalf("no traceable code in %q", msg) + } +}