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) + } +}