Give a failed submission a code, and put the cause in the log

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

@@ -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

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

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:

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 <code>` — 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 |

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()
 

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 == "" {
+			a.fail(ctx, subID, "download",
-				msg = err.Error()
+				"Kappaleen lataaminen ei onnistunut. Yritä myöhemmin uudelleen.",
-			}
+				detail, err, "url", sourceURL)
-			a.setStatus(ctx, subID, "failed", msg)
-			slog.Warn("download failed", "ctx", "submissions", "submission", subID, "error", err)
 			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 == "" {
+		a.fail(ctx, subID, "convert",
-			msg = err.Error()
+			"Tiedostoa ei voitu muuntaa. Onko se varmasti äänitiedosto?",
-		}
+			detail, err)
-		a.setStatus(ctx, subID, "failed", msg)
-		slog.Warn("conversion failed", "ctx", "submissions", "submission", subID, "error", 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`,

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, "[email protected]")
+
+	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)
+	}
+}