diff --git a/.env.example b/.env.example index a8c749a..ad570a3 100755 --- a/.env.example +++ b/.env.example @@ -8,6 +8,8 @@ SESSION_TTL_HOURS=12 TRUST_PROXY_HEADERS=true LISTEN_ADDR=:8080 +LOG_LEVEL=info +LOG_FORMAT=text DOWNLOAD_DIR=/data/downloads DOWNLOAD_HOST_DIR=./data/downloads diff --git a/README.md b/README.md index 4aec011..a695713 100755 --- a/README.md +++ b/README.md @@ -64,7 +64,14 @@ Every first level folder inside these roots is a move destination: | `DOWNLOAD_DIR` | `/data/downloads` | Temporary download directory | | `MIN_FREE_GB` | `10` | Initial value: free space that must always remain | | `MAX_CONCURRENT_DOWNLOADS` | `2` | Initial value: parallel downloads, others wait in queue | +| `CONNECTIONS_PER_DOWNLOAD` | `4` | Initial value: parallel connections for one download when the server allows ranges | | `ALLOWED_PORTS` | `80,443` | Initial value: allowed remote ports, `*` for any | +| `LOG_LEVEL` | `info` | `debug`, `info`, `warn` or `error`. `debug` also logs every polling request | +| `LOG_FORMAT` | `text` | `text` or `json` | + +## Logging + +Logs go to stdout (`docker compose logs -f`). Every request gets an `X-Request-ID`. When the server hits an internal error, the page shows a reference ID and the log line for that request carries the same `request_id`, so the two can be matched. Download, extraction and move steps are logged with a short `download` ID. ## Web Settings diff --git a/internal/config/config.go b/internal/config/config.go index bdac0bb..7a92bf4 100755 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -23,6 +23,8 @@ type Settings struct { TrustProxyHeaders bool DownloadDir string LibraryRoots []string + LogLevel string + LogFormat string Defaults preferences.Preferences } @@ -36,6 +38,8 @@ func Load() (Settings, error) { SessionTTL: time.Duration(reader.integer("SESSION_TTL_HOURS", 12)) * time.Hour, TrustProxyHeaders: reader.boolean("TRUST_PROXY_HEADERS", false), DownloadDir: filepath.Clean(reader.text("DOWNLOAD_DIR", "/data/downloads")), + LogLevel: reader.text("LOG_LEVEL", "info"), + LogFormat: reader.text("LOG_FORMAT", "text"), Defaults: preferences.Preferences{ MaxConcurrentDownloads: reader.integer("MAX_CONCURRENT_DOWNLOADS", 2), ConnectionsPerDownload: reader.integer("CONNECTIONS_PER_DOWNLOAD", 4), diff --git a/internal/explain/explain.go b/internal/explain/explain.go new file mode 100644 index 0000000..94c08f4 --- /dev/null +++ b/internal/explain/explain.go @@ -0,0 +1,88 @@ +package explain + +import ( + "crypto/tls" + "crypto/x509" + "errors" + "fmt" + "io" + "io/fs" + "net" + "syscall" + + "ddc/internal/guard" +) + +var keptAsIs = []error{ + guard.ErrBlockedAddress, + guard.ErrBlockedPort, + guard.ErrTooManyRedirects, + guard.ErrUnsupportedScheme, +} + +func Error(err error) string { + if err == nil { + return "" + } + for _, known := range keptAsIs { + if errors.Is(err, known) { + return capitalize(known.Error()) + } + } + if message := networkMessage(err); message != "" { + return message + } + if message := fileSystemMessage(err); message != "" { + return message + } + return capitalize(err.Error()) +} + +func networkMessage(err error) string { + var dnsError *net.DNSError + var certificateError *tls.CertificateVerificationError + var unknownAuthority x509.UnknownAuthorityError + var hostnameError x509.HostnameError + var timeoutError net.Error + + switch { + case errors.As(err, &dnsError): + return fmt.Sprintf("Could not find the server %q. Check the link.", dnsError.Name) + case errors.As(err, &certificateError), errors.As(err, &unknownAuthority), errors.As(err, &hostnameError): + return "The server's security certificate is not valid." + case errors.Is(err, syscall.ECONNREFUSED): + return "The server refused the connection." + case errors.Is(err, syscall.ECONNRESET), errors.Is(err, io.ErrUnexpectedEOF): + return "The server closed the connection before the file was complete. Use Retry to continue." + case errors.Is(err, syscall.ENETUNREACH), errors.Is(err, syscall.EHOSTUNREACH): + return "The server could not be reached from this network." + case errors.As(err, &timeoutError) && timeoutError.Timeout(): + return "The server took too long to respond." + default: + return "" + } +} + +func fileSystemMessage(err error) string { + switch { + case errors.Is(err, syscall.ENOSPC): + return "The disk is full." + case errors.Is(err, fs.ErrPermission): + return "The server does not have permission to write there. Check the folder owner and permissions." + case errors.Is(err, syscall.EROFS): + return "The destination is on a read-only file system." + default: + return "" + } +} + +func capitalize(message string) string { + if message == "" { + return message + } + first := message[0] + if first >= 'a' && first <= 'z' { + return string(first-'a'+'A') + message[1:] + } + return message +} diff --git a/internal/fetch/downloader.go b/internal/fetch/downloader.go index 7e8d7e9..2d6ea75 100755 --- a/internal/fetch/downloader.go +++ b/internal/fetch/downloader.go @@ -3,6 +3,7 @@ package fetch import ( "context" "errors" + "log/slog" "net/http" "os" "path/filepath" @@ -34,6 +35,14 @@ type Request struct { State *State Progress Progress Checkpoint func(State) + Logger *slog.Logger +} + +func (request Request) logger() *slog.Logger { + if request.Logger != nil { + return request.Logger + } + return slog.Default() } type Downloader struct { @@ -90,11 +99,19 @@ func (downloader *Downloader) Download(ctx context.Context, request Request) (st } func (downloader *Downloader) prepare(ctx context.Context, source *remoteFile, request Request, partPath string) (State, *http.Response, error) { - if request.State != nil && request.State.valid() && fileExists(partPath) { - state := *request.State - source.validator = state.Validator - source.totalBytes = state.TotalBytes - return state, nil, nil + if request.State != nil { + if request.State.valid() && fileExists(partPath) { + state := *request.State + source.validator = state.Validator + source.totalBytes = state.TotalBytes + request.logger().Info("resuming from saved progress", + "bytes_done", state.DoneBytes(), + "bytes_total", state.TotalBytes, + "parts", len(state.Segments), + ) + return state, nil, nil + } + request.logger().Warn("saved progress is unusable, starting over", "part_file_exists", fileExists(partPath)) } probe, err := downloader.open(ctx, source, 0, 0) @@ -113,6 +130,13 @@ func (downloader *Downloader) prepare(ctx context.Context, source *remoteFile, r TotalBytes: source.totalBytes, Segments: planSegments(source.totalBytes, connections), } + request.logger().Info("connected to server", + "file", state.FileName, + "bytes_total", state.TotalBytes, + "supports_ranges", probe.Header.Get("Accept-Ranges") == "bytes", + "has_validator", state.Validator != "", + "parts", len(state.Segments), + ) return state, probe, nil } diff --git a/internal/fetch/session.go b/internal/fetch/session.go index 89a4df1..dae4bb7 100644 --- a/internal/fetch/session.go +++ b/internal/fetch/session.go @@ -123,6 +123,8 @@ func (session *session) saveCheckpoint() { return } state := session.snapshot() - session.file.Sync() + if err := session.file.Sync(); err != nil { + session.request.logger().Warn("could not flush partial file to disk", "error", err) + } session.request.Checkpoint(state) } diff --git a/internal/fetch/worker.go b/internal/fetch/worker.go index be6a919..acd1b0b 100644 --- a/internal/fetch/worker.go +++ b/internal/fetch/worker.go @@ -68,11 +68,26 @@ func (worker *segmentWorker) record(count int64) error { func (worker *segmentWorker) reconnect(ctx context.Context, cause error) (*http.Response, error) { progress := worker.session.request.Progress + logger := worker.session.request.logger().With("part_start", worker.segment.start) for { worker.failedAttempts++ - if ctx.Err() != nil || !isRetryable(cause) || worker.failedAttempts > maxRetriesWithoutProgress { + if ctx.Err() != nil { return nil, cause } + if !isRetryable(cause) { + logger.Debug("error cannot be retried", "error", cause) + return nil, cause + } + if worker.failedAttempts > maxRetriesWithoutProgress { + logger.Error("giving up after repeated connection failures", "attempts", maxRetriesWithoutProgress, "error", cause) + return nil, fmt.Errorf("gave up after %d reconnect attempts: %w", maxRetriesWithoutProgress, cause) + } + + logger.Warn("connection lost, reconnecting", + "attempt", worker.failedAttempts, + "position", worker.segment.position(), + "error", cause, + ) progress.SetNotice(fmt.Sprintf("Connection lost, reconnecting (attempt %d of %d)", worker.failedAttempts, maxRetriesWithoutProgress)) if err := waitBeforeRetry(ctx, worker.failedAttempts); err != nil { return nil, err @@ -80,6 +95,7 @@ func (worker *segmentWorker) reconnect(ctx context.Context, cause error) (*http. response, err := worker.open(ctx) if err == nil { + logger.Info("reconnected", "position", worker.segment.position()) progress.SetNotice("") return response, nil } diff --git a/internal/jobs/download.go b/internal/jobs/download.go index cd18376..11bd3ec 100644 --- a/internal/jobs/download.go +++ b/internal/jobs/download.go @@ -4,7 +4,9 @@ import ( "context" "errors" "path/filepath" + "time" + "ddc/internal/explain" "ddc/internal/extract" "ddc/internal/fetch" ) @@ -17,6 +19,7 @@ func (manager *Manager) Pause(id string) error { if !job.pause() { return ErrJobBusy } + job.logger().Info("pause requested") return nil } @@ -28,6 +31,7 @@ func (manager *Manager) Resume(id string) error { if !job.begin(StatusQueued, StatusPaused, StatusFailed) { return ErrJobBusy } + job.logger().Info("download resumed", "has_saved_progress", job.currentDownloadState() != nil) job.saveRecord() manager.launchDownload(job) return nil @@ -44,17 +48,17 @@ func (manager *Manager) Reorder(id, direction string) error { if job.currentStatus() != StatusQueued || !manager.slots.reorder(id, direction) { return ErrJobBusy } + job.logger().Debug("queue position changed", "direction", direction, "position", manager.slots.position(id)) return nil } func (manager *Manager) launchDownload(job *Job) { runContext, cancelRun := job.startRun() manager.slots.enqueue(job.id) - go func() { - defer job.workers.Done() + manager.runInBackground(job, "download", func() { defer cancelRun(nil) manager.download(job, runContext) - }() + }) } func (manager *Manager) download(job *Job, runContext context.Context) { @@ -65,18 +69,25 @@ func (manager *Manager) download(job *Job, runContext context.Context) { defer manager.slots.release() job.setStatus(StatusDownloading, "") + started := time.Now() + job.logger().Info("download started", "url", job.displayURL) filePath, err := manager.downloader.Download(runContext, manager.fetchRequest(job)) if err != nil { manager.handleDownloadError(job, runContext, err) return } job.markDownloaded(filepath.Base(filePath)) + job.logger().Info("download finished", + "file", filepath.Base(filePath), + "bytes", job.bytesDone.Load(), + "duration", time.Since(started).Round(time.Second).String(), + ) if job.autoExtract && extract.IsArchive(filePath) { job.setStatus(StatusExtracting, "") destination, err := manager.extractArchive(job, filePath) if err != nil { - manager.finishWithError(job, StatusReady, "Extraction failed: ", err) + manager.failExtraction(job, err) job.saveRecord() return } @@ -98,6 +109,7 @@ func (manager *Manager) fetchRequest(job *Job) fetch.Request { Connections: current.ConnectionsPerDownload, State: job.currentDownloadState(), Progress: job, + Logger: job.logger(), Checkpoint: func(state fetch.State) { job.setDownloadState(&state) job.saveRecord() @@ -109,14 +121,22 @@ func (manager *Manager) handleDownloadError(job *Job, runContext context.Context switch { case errors.Is(context.Cause(runContext), errPaused): job.setStatus(StatusPaused, "") + job.logger().Info("download paused", "bytes_done", job.bytesDone.Load()) case job.jobContext.Err() != nil: job.setStatus(StatusCancelled, "") + job.logger().Info("download stopped", "bytes_done", job.bytesDone.Load()) return default: if errors.Is(err, fetch.ErrSourceChanged) || errors.Is(err, fetch.ErrResumeUnsupported) { job.setDownloadState(nil) } - job.setStatus(StatusFailed, err.Error()) + job.setStatus(StatusFailed, explain.Error(err)) + job.logger().Error("download failed", + "url", job.displayURL, + "bytes_done", job.bytesDone.Load(), + "bytes_total", job.bytesTotal.Load(), + "error", err, + ) } job.saveRecord() } diff --git a/internal/jobs/extraction.go b/internal/jobs/extraction.go index 051aa50..7956187 100644 --- a/internal/jobs/extraction.go +++ b/internal/jobs/extraction.go @@ -4,8 +4,10 @@ import ( "errors" "os" "path/filepath" + "time" "ddc/internal/diskspace" + "ddc/internal/explain" "ddc/internal/extract" "ddc/internal/files" ) @@ -32,14 +34,13 @@ func (manager *Manager) Extract(id, relativePath string) error { if !job.begin(StatusExtracting, StatusReady) { return ErrJobBusy } - go func() { - defer job.workers.Done() + manager.runInBackground(job, "extraction", func() { if _, err := manager.extractArchive(job, archivePath); err != nil { - manager.finishWithError(job, StatusReady, "Extraction failed: ", err) + manager.failExtraction(job, err) return } job.setStatus(StatusReady, "") - }() + }) return nil } @@ -58,16 +59,27 @@ func (manager *Manager) extractArchive(job *Job, archivePath string) (string, er limits := extract.Limits{MaxBytes: limit, MaxEntries: maxArchiveEntries} job.resetProgress() + started := time.Now() + job.logger().Info("extraction started", "archive", filepath.Base(archivePath)) if err := extract.Archive(job.jobContext, archivePath, destination, limits, job); err != nil { return "", err } - return destination, os.Remove(archivePath) + job.logger().Info("extraction finished", + "archive", filepath.Base(archivePath), + "folder", filepath.Base(destination), + "duration", time.Since(started).Round(time.Second).String(), + ) + if err := os.Remove(archivePath); err != nil { + job.logger().Warn("could not remove archive after extraction", "archive", archivePath, "error", err) + } + return destination, nil } -func (manager *Manager) finishWithError(job *Job, status Status, prefix string, err error) { +func (manager *Manager) failExtraction(job *Job, err error) { if job.jobContext.Err() != nil { job.setStatus(StatusCancelled, "") return } - job.setStatus(status, prefix+err.Error()) + job.logger().Error("extraction failed", "error", err) + job.setStatus(StatusReady, "Extraction failed: "+explain.Error(err)) } diff --git a/internal/jobs/history.go b/internal/jobs/history.go index b83e69f..396edab 100644 --- a/internal/jobs/history.go +++ b/internal/jobs/history.go @@ -1,7 +1,6 @@ package jobs import ( - "log" "time" "ddc/internal/history" @@ -28,6 +27,6 @@ func (manager *Manager) recordHistory(job *Job, destination string, movedNames [ MovedAt: time.Now(), } if err := manager.history.Add(entry); err != nil { - log.Printf("could not save history: %v", err) + job.logger().Error("could not save history", "error", err) } } diff --git a/internal/jobs/manager.go b/internal/jobs/manager.go index fe46dbd..75b063e 100755 --- a/internal/jobs/manager.go +++ b/internal/jobs/manager.go @@ -6,6 +6,7 @@ import ( "encoding/hex" "errors" "fmt" + "log/slog" "os" "path" "path/filepath" @@ -76,6 +77,12 @@ func (manager *Manager) UpdatePreferences(next preferences.Preferences) error { return err } manager.policy.SetAllowedPorts(next.AllowedPorts) + slog.Debug("preferences saved", + "parallel_downloads", next.MaxConcurrentDownloads, + "connections_per_download", next.ConnectionsPerDownload, + "min_free_gb", next.MinFreeGB, + "download_paths", len(next.DownloadPaths), + ) return nil } @@ -137,6 +144,11 @@ func (manager *Manager) Create(request CreateRequest) (Snapshot, error) { manager.store(job) job.saveRecord() + job.logger().Info("download added", + "url", job.displayURL, + "file_name", requestedName, + "target", job.snapshot().MoveTarget, + ) manager.launchDownload(job) return job.snapshot(), nil } @@ -186,7 +198,12 @@ func (manager *Manager) Delete(id string) error { delete(manager.jobs, id) manager.mutex.Unlock() - return os.RemoveAll(job.directory) + if err := os.RemoveAll(job.directory); err != nil { + job.logger().Error("could not remove download files", "directory", job.directory, "error", err) + return err + } + job.logger().Info("download removed") + return nil } func (manager *Manager) Shutdown(ctx context.Context) { @@ -208,6 +225,7 @@ func (manager *Manager) Shutdown(ctx context.Context) { select { case <-finished: case <-ctx.Done(): + slog.Warn("stopped waiting for downloads to save progress", "error", ctx.Err()) } } diff --git a/internal/jobs/move.go b/internal/jobs/move.go index e455a33..d75e81d 100755 --- a/internal/jobs/move.go +++ b/internal/jobs/move.go @@ -5,7 +5,9 @@ import ( "fmt" "os" "path/filepath" + "time" + "ddc/internal/explain" "ddc/internal/files" ) @@ -50,10 +52,9 @@ func (manager *Manager) Move(id string, request MoveRequest) error { if !job.begin(StatusMoving, StatusReady) { return ErrJobBusy } - go func() { - defer job.workers.Done() + manager.runInBackground(job, "move", func() { manager.moveFiles(job, sources, destination, request.Cleanup) - }() + }) return nil } @@ -109,13 +110,26 @@ func (manager *Manager) moveFiles(job *Job, sources []string, destination string movedNames := make([]string, 0, len(sources)) defer func() { manager.recordHistory(job, destination, movedNames) }() + started := time.Now() for _, source := range sources { if err := files.MoveInto(source, destination, manager.reservedBytes(), job.Add); err != nil { - job.setStatus(StatusReady, "Move failed: "+err.Error()) + job.logger().Error("move failed", + "item", filepath.Base(source), + "destination", destination, + "moved_before_failure", len(movedNames), + "error", err, + ) + job.setStatus(StatusReady, "Move failed: "+explain.Error(err)) return } movedNames = append(movedNames, filepath.Base(source)) } + job.logger().Info("move finished", + "items", len(movedNames), + "bytes", totalBytes, + "destination", destination, + "duration", time.Since(started).Round(time.Second).String(), + ) message := fmt.Sprintf("Moved %d item(s) to %s", len(sources), destination) if !cleanup { @@ -123,7 +137,8 @@ func (manager *Manager) moveFiles(job *Job, sources []string, destination string return } if err := os.RemoveAll(job.directory); err != nil { - message += ", cleanup failed: " + err.Error() + job.logger().Warn("could not remove temporary files after move", "directory", job.directory, "error", err) + message += ", cleanup failed: " + explain.Error(err) } job.setStatus(StatusCompleted, message) } diff --git a/internal/jobs/record.go b/internal/jobs/record.go index b8b49cc..17549f9 100644 --- a/internal/jobs/record.go +++ b/internal/jobs/record.go @@ -2,7 +2,7 @@ package jobs import ( "encoding/json" - "log" + "log/slog" "os" "path/filepath" "time" @@ -69,23 +69,28 @@ func phaseFor(status Status, downloaded bool) string { func (job *Job) saveRecord() { data, err := json.MarshalIndent(job.record(), "", " ") if err != nil { - log.Printf("could not encode download %s: %v", job.id, err) + job.logger().Error("could not encode download state", "error", err) return } job.recordMutex.Lock() defer job.recordMutex.Unlock() if err := files.WriteAtomically(filepath.Join(job.directory, files.JobFileName), data); err != nil && !os.IsNotExist(err) { - log.Printf("could not save download %s: %v", job.id, err) + job.logger().Error("could not save download state", "error", err) } } func readRecord(directory string) (jobRecord, bool) { - data, err := os.ReadFile(filepath.Join(directory, files.JobFileName)) + recordPath := filepath.Join(directory, files.JobFileName) + data, err := os.ReadFile(recordPath) if err != nil { + if !os.IsNotExist(err) { + slog.Warn("could not read saved download state", "path", recordPath, "error", err) + } return jobRecord{}, false } var record jobRecord if err := json.Unmarshal(data, &record); err != nil { + slog.Warn("saved download state is damaged, treating the download as finished", "path", recordPath, "error", err) return jobRecord{}, false } return record, true diff --git a/internal/jobs/restore.go b/internal/jobs/restore.go index fc0cf9c..98deccb 100755 --- a/internal/jobs/restore.go +++ b/internal/jobs/restore.go @@ -2,6 +2,7 @@ package jobs import ( "io/fs" + "log/slog" "os" "path/filepath" "regexp" @@ -20,12 +21,14 @@ func (manager *Manager) RestoreExisting() error { } var queuedJobs []*Job + restoredCount := 0 for _, entry := range entries { if !entry.IsDir() || !jobIDPattern.MatchString(entry.Name()) { continue } job := manager.restoreJob(entry) manager.store(job) + restoredCount++ if job.status == StatusQueued { queuedJobs = append(queuedJobs, job) } @@ -38,6 +41,7 @@ func (manager *Manager) RestoreExisting() error { job.workers.Add(1) manager.launchDownload(job) } + slog.Info("restored downloads", "total", restoredCount, "resuming", len(queuedJobs)) return nil } diff --git a/internal/jobs/safety.go b/internal/jobs/safety.go new file mode 100644 index 0000000..733ff5b --- /dev/null +++ b/internal/jobs/safety.go @@ -0,0 +1,42 @@ +package jobs + +import ( + "log/slog" + "runtime/debug" +) + +const shortIDLength = 8 + +func (job *Job) logger() *slog.Logger { + return slog.With("download", job.id[:min(len(job.id), shortIDLength)]) +} + +func (job *Job) isDownloaded() bool { + job.mutex.Lock() + defer job.mutex.Unlock() + return job.downloaded +} + +func (manager *Manager) runInBackground(job *Job, task string, work func()) { + go func() { + defer job.workers.Done() + defer func() { + recovered := recover() + if recovered == nil { + return + } + job.logger().Error("background task crashed", + "task", task, + "panic", recovered, + "stack", string(debug.Stack()), + ) + status := StatusFailed + if job.isDownloaded() { + status = StatusReady + } + job.setStatus(status, "Internal error during "+task+". The server log has the details.") + job.saveRecord() + }() + work() + }() +} diff --git a/internal/jobs/target.go b/internal/jobs/target.go index 437a337..91a3626 100644 --- a/internal/jobs/target.go +++ b/internal/jobs/target.go @@ -6,6 +6,7 @@ import ( "path/filepath" "strings" + "ddc/internal/explain" "ddc/internal/files" "ddc/internal/libraries" "ddc/internal/preferences" @@ -82,6 +83,7 @@ func (manager *Manager) moveToTarget(job *Job) { } names, err := topLevelNames(job.directory) if err == nil { + job.logger().Info("moving to chosen folder", "destination", job.target.displayPath(), "items", len(names)) err = manager.Move(job.id, MoveRequest{ Paths: names, Destination: job.target.destination, @@ -90,7 +92,8 @@ func (manager *Manager) moveToTarget(job *Job) { }) } if err != nil { - job.setStatus(StatusReady, "Move failed: "+err.Error()) + job.logger().Error("automatic move failed", "destination", job.target.displayPath(), "error", err) + job.setStatus(StatusReady, "Move failed: "+explain.Error(err)) } } diff --git a/internal/logging/logging.go b/internal/logging/logging.go new file mode 100644 index 0000000..0c57361 --- /dev/null +++ b/internal/logging/logging.go @@ -0,0 +1,33 @@ +package logging + +import ( + "fmt" + "log/slog" + "os" + "strings" +) + +func Setup(level, format string) error { + var parsedLevel slog.Level + if err := parsedLevel.UnmarshalText([]byte(level)); err != nil { + return fmt.Errorf("LOG_LEVEL must be debug, info, warn or error: %w", err) + } + options := &slog.HandlerOptions{Level: parsedLevel} + + var handler slog.Handler + switch strings.ToLower(format) { + case "text": + handler = slog.NewTextHandler(os.Stdout, options) + case "json": + handler = slog.NewJSONHandler(os.Stdout, options) + default: + return fmt.Errorf("LOG_FORMAT must be text or json, got %q", format) + } + slog.SetDefault(slog.New(handler)) + return nil +} + +func Fatal(message string, err error, attributes ...any) { + slog.Error(message, append(attributes, "error", err)...) + os.Exit(1) +} diff --git a/internal/server/auth_handlers.go b/internal/server/auth_handlers.go index a947509..ab5b254 100755 --- a/internal/server/auth_handlers.go +++ b/internal/server/auth_handlers.go @@ -1,6 +1,8 @@ package server import ( + "fmt" + "log/slog" "net" "net/http" "strings" @@ -20,17 +22,18 @@ type sessionResponse struct { func (server *Server) handleLogin(writer http.ResponseWriter, request *http.Request) { client := server.clientAddress(request) if !server.limiter.Allowed(client) { + slog.Warn("login blocked after too many failures", "client", client, "request_id", requestIDFrom(request)) writeError(writer, http.StatusTooManyRequests, "too many failed attempts, try again later") return } var body loginRequest - if err := decodeJSON(request, &body); err != nil { - writeError(writer, http.StatusBadRequest, "invalid request body") + if !decodeBody(writer, request, &body) { return } if !auth.CredentialsMatch(server.settings.Username, server.settings.Password, body.Username, body.Password) { server.limiter.RecordFailure(client) + slog.Warn("login failed", "client", client, "username", body.Username, "request_id", requestIDFrom(request)) writeError(writer, http.StatusUnauthorized, "invalid username or password") return } @@ -38,9 +41,10 @@ func (server *Server) handleLogin(writer http.ResponseWriter, request *http.Requ server.limiter.Reset(client) token, err := server.sessions.Create() if err != nil { - writeError(writer, http.StatusInternalServerError, "could not create session") + writeFailure(writer, request, fmt.Errorf("could not create session: %w", err)) return } + slog.Info("login succeeded", "client", client, "request_id", requestIDFrom(request)) http.SetCookie(writer, server.sessionCookie(token, int(server.settings.SessionTTL.Seconds()))) writeJSON(writer, http.StatusOK, sessionResponse{Authenticated: true}) } diff --git a/internal/server/control_handlers.go b/internal/server/control_handlers.go index befce4d..a1ca00b 100644 --- a/internal/server/control_handlers.go +++ b/internal/server/control_handlers.go @@ -2,9 +2,13 @@ package server import "net/http" +type reorderRequest struct { + Direction string `json:"direction"` +} + func (server *Server) handlePause(writer http.ResponseWriter, request *http.Request) { if err := server.manager.Pause(request.PathValue("id")); err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writeJSON(writer, http.StatusAccepted, startedResponse{Started: true}) @@ -12,24 +16,19 @@ func (server *Server) handlePause(writer http.ResponseWriter, request *http.Requ func (server *Server) handleResume(writer http.ResponseWriter, request *http.Request) { if err := server.manager.Resume(request.PathValue("id")); err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writeJSON(writer, http.StatusAccepted, startedResponse{Started: true}) } -type reorderRequest struct { - Direction string `json:"direction"` -} - func (server *Server) handleReorder(writer http.ResponseWriter, request *http.Request) { var body reorderRequest - if err := decodeJSON(request, &body); err != nil { - writeError(writer, http.StatusBadRequest, "invalid request body") + if !decodeBody(writer, request, &body) { return } if err := server.manager.Reorder(request.PathValue("id"), body.Direction); err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writeJSON(writer, http.StatusOK, startedResponse{Started: true}) @@ -39,9 +38,9 @@ func (server *Server) handleHistory(writer http.ResponseWriter, _ *http.Request) writeJSON(writer, http.StatusOK, server.manager.History()) } -func (server *Server) handleClearHistory(writer http.ResponseWriter, _ *http.Request) { +func (server *Server) handleClearHistory(writer http.ResponseWriter, request *http.Request) { if err := server.manager.ClearHistory(); err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writer.WriteHeader(http.StatusNoContent) diff --git a/internal/server/job_handlers.go b/internal/server/job_handlers.go index 1c839e2..39d1840 100755 --- a/internal/server/job_handlers.go +++ b/internal/server/job_handlers.go @@ -23,10 +23,10 @@ func (server *Server) handleLibraries(writer http.ResponseWriter, _ *http.Reques writeJSON(writer, http.StatusOK, server.manager.Destinations()) } -func (server *Server) handleDisk(writer http.ResponseWriter, _ *http.Request) { +func (server *Server) handleDisk(writer http.ResponseWriter, request *http.Request) { available, err := server.manager.AvailableBytes() if err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writeJSON(writer, http.StatusOK, diskResponse{AvailableBytes: available, ReservedBytes: server.manager.Preferences().MinFreeBytes()}) @@ -38,13 +38,12 @@ func (server *Server) handleListJobs(writer http.ResponseWriter, _ *http.Request func (server *Server) handleCreateJob(writer http.ResponseWriter, request *http.Request) { var body jobs.CreateRequest - if err := decodeJSON(request, &body); err != nil { - writeError(writer, http.StatusBadRequest, "invalid request body") + if !decodeBody(writer, request, &body) { return } snapshot, err := server.manager.Create(body) if err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writeJSON(writer, http.StatusCreated, snapshot) @@ -53,7 +52,7 @@ func (server *Server) handleCreateJob(writer http.ResponseWriter, request *http. func (server *Server) handleJobFiles(writer http.ResponseWriter, request *http.Request) { tree, err := server.manager.Files(request.PathValue("id")) if err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writeJSON(writer, http.StatusOK, tree) @@ -61,12 +60,11 @@ func (server *Server) handleJobFiles(writer http.ResponseWriter, request *http.R func (server *Server) handleExtract(writer http.ResponseWriter, request *http.Request) { var body extractRequest - if err := decodeJSON(request, &body); err != nil { - writeError(writer, http.StatusBadRequest, "invalid request body") + if !decodeBody(writer, request, &body) { return } if err := server.manager.Extract(request.PathValue("id"), body.Path); err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writeJSON(writer, http.StatusAccepted, startedResponse{Started: true}) @@ -74,12 +72,11 @@ func (server *Server) handleExtract(writer http.ResponseWriter, request *http.Re func (server *Server) handleMove(writer http.ResponseWriter, request *http.Request) { var body jobs.MoveRequest - if err := decodeJSON(request, &body); err != nil { - writeError(writer, http.StatusBadRequest, "invalid request body") + if !decodeBody(writer, request, &body) { return } if err := server.manager.Move(request.PathValue("id"), body); err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writeJSON(writer, http.StatusAccepted, startedResponse{Started: true}) @@ -87,7 +84,7 @@ func (server *Server) handleMove(writer http.ResponseWriter, request *http.Reque func (server *Server) handleDeleteJob(writer http.ResponseWriter, request *http.Request) { if err := server.manager.Delete(request.PathValue("id")); err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } writer.WriteHeader(http.StatusNoContent) diff --git a/internal/server/observe.go b/internal/server/observe.go new file mode 100644 index 0000000..e29bdfe --- /dev/null +++ b/internal/server/observe.go @@ -0,0 +1,115 @@ +package server + +import ( + "context" + "crypto/rand" + "encoding/hex" + "log/slog" + "net/http" + "runtime/debug" + "time" +) + +type contextKey int + +const requestIDKey contextKey = iota + +type statusRecorder struct { + http.ResponseWriter + status int +} + +func (recorder *statusRecorder) WriteHeader(status int) { + if recorder.status == 0 { + recorder.status = status + } + recorder.ResponseWriter.WriteHeader(status) +} + +func (recorder *statusRecorder) Write(data []byte) (int, error) { + if recorder.status == 0 { + recorder.status = http.StatusOK + } + return recorder.ResponseWriter.Write(data) +} + +func (recorder *statusRecorder) Unwrap() http.ResponseWriter { + return recorder.ResponseWriter +} + +func (server *Server) observe(next http.Handler) http.Handler { + return http.HandlerFunc(func(writer http.ResponseWriter, request *http.Request) { + started := time.Now() + requestID := newRequestID() + writer.Header().Set("X-Request-ID", requestID) + request = request.WithContext(context.WithValue(request.Context(), requestIDKey, requestID)) + recorder := &statusRecorder{ResponseWriter: writer} + + defer func() { + if recovered := recover(); recovered != nil { + if recovered == http.ErrAbortHandler { + panic(recovered) + } + slog.Error("request handler crashed", + "request_id", requestID, + "method", request.Method, + "path", request.URL.Path, + "panic", recovered, + "stack", string(debug.Stack()), + ) + if recorder.status == 0 { + writeError(recorder, http.StatusInternalServerError, internalErrorMessage(requestID)) + } + } + server.logRequest(request, recorder.status, time.Since(started)) + }() + + next.ServeHTTP(recorder, request) + }) +} + +func (server *Server) logRequest(request *http.Request, status int, duration time.Duration) { + if status == 0 { + status = http.StatusOK + } + slog.Log(request.Context(), requestLogLevel(request.Method, status), "request", + "request_id", requestIDFrom(request), + "method", request.Method, + "path", request.URL.Path, + "status", status, + "duration_ms", duration.Milliseconds(), + "client", server.clientAddress(request), + ) +} + +func requestLogLevel(method string, status int) slog.Level { + switch { + case status >= http.StatusInternalServerError: + return slog.LevelError + case status >= http.StatusBadRequest && status != http.StatusUnauthorized: + return slog.LevelWarn + case method != http.MethodGet && method != http.MethodHead: + return slog.LevelInfo + default: + return slog.LevelDebug + } +} + +func requestIDFrom(request *http.Request) string { + if requestID, ok := request.Context().Value(requestIDKey).(string); ok { + return requestID + } + return "" +} + +func newRequestID() string { + buffer := make([]byte, 6) + if _, err := rand.Read(buffer); err != nil { + return "unknown" + } + return hex.EncodeToString(buffer) +} + +func internalErrorMessage(requestID string) string { + return "Something went wrong on the server (reference " + requestID + "). The server log has the details." +} diff --git a/internal/server/respond.go b/internal/server/respond.go index ddda2a3..223bb68 100755 --- a/internal/server/respond.go +++ b/internal/server/respond.go @@ -3,6 +3,7 @@ package server import ( "encoding/json" "errors" + "log/slog" "net/http" "ddc/internal/diskspace" @@ -11,24 +12,55 @@ import ( "ddc/internal/preferences" ) +type errorResponse struct { + Error string `json:"error"` + RequestID string `json:"requestId,omitempty"` +} + func writeJSON(writer http.ResponseWriter, status int, payload any) { writer.Header().Set("Content-Type", "application/json; charset=utf-8") writer.WriteHeader(status) - json.NewEncoder(writer).Encode(payload) + if err := json.NewEncoder(writer).Encode(payload); err != nil { + slog.Debug("could not write response", "error", err) + } } func writeError(writer http.ResponseWriter, status int, message string) { - writeJSON(writer, status, map[string]string{"error": message}) + writeJSON(writer, status, errorResponse{Error: message, RequestID: writer.Header().Get("X-Request-ID")}) } -func writeFailure(writer http.ResponseWriter, err error) { - writeError(writer, statusFor(err), err.Error()) +func writeFailure(writer http.ResponseWriter, request *http.Request, err error) { + status := statusFor(err) + if status != http.StatusInternalServerError { + writeError(writer, status, err.Error()) + return + } + + requestID := requestIDFrom(request) + slog.Error("request failed", + "request_id", requestID, + "method", request.Method, + "path", request.URL.Path, + "error", err, + ) + writeError(writer, status, internalErrorMessage(requestID)) } -func decodeJSON(request *http.Request, target any) error { +func decodeBody(writer http.ResponseWriter, request *http.Request, target any) bool { decoder := json.NewDecoder(request.Body) decoder.DisallowUnknownFields() - return decoder.Decode(target) + err := decoder.Decode(target) + if err == nil { + return true + } + + var tooLarge *http.MaxBytesError + if errors.As(err, &tooLarge) { + writeError(writer, http.StatusRequestEntityTooLarge, "request body is too large") + return false + } + writeError(writer, http.StatusBadRequest, "invalid request body: "+err.Error()) + return false } func statusFor(err error) int { diff --git a/internal/server/server.go b/internal/server/server.go index 00b1298..c77a5a7 100755 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -59,7 +59,7 @@ func (server *Server) routes() http.Handler { root.Handle("/api/", server.requireSession(api)) root.Handle("/", staticHandler()) - return securityHeaders(protectStateChanges(root)) + return server.observe(securityHeaders(protectStateChanges(root))) } func staticHandler() http.Handler { diff --git a/internal/server/settings_handlers.go b/internal/server/settings_handlers.go index 1386db8..61f8e46 100644 --- a/internal/server/settings_handlers.go +++ b/internal/server/settings_handlers.go @@ -1,6 +1,7 @@ package server import ( + "log/slog" "net/http" "ddc/internal/preferences" @@ -18,14 +19,14 @@ func (server *Server) handleGetSettings(writer http.ResponseWriter, _ *http.Requ func (server *Server) handleUpdateSettings(writer http.ResponseWriter, request *http.Request) { var body preferences.Preferences - if err := decodeJSON(request, &body); err != nil { - writeError(writer, http.StatusBadRequest, "invalid request body") + if !decodeBody(writer, request, &body) { return } if err := server.manager.UpdatePreferences(body); err != nil { - writeFailure(writer, err) + writeFailure(writer, request, err) return } + slog.Info("settings updated", "request_id", requestIDFrom(request)) writeJSON(writer, http.StatusOK, server.settingsSnapshot()) } diff --git a/main.go b/main.go index 17040f5..a156c1a 100755 --- a/main.go +++ b/main.go @@ -3,7 +3,8 @@ package main import ( "context" "errors" - "log" + "fmt" + "log/slog" "net/http" "os" "os/signal" @@ -15,6 +16,7 @@ import ( "ddc/internal/config" "ddc/internal/history" "ddc/internal/jobs" + "ddc/internal/logging" "ddc/internal/preferences" "ddc/internal/server" ) @@ -22,45 +24,41 @@ import ( const ( settingsFileName = ".settings.json" historyFileName = ".history.json" + shutdownTimeout = 10 * time.Second ) func main() { settings, err := config.Load() if err != nil { - log.Fatalf("configuration error: %v", err) + logging.Fatal("configuration error", err) + } + if err := logging.Setup(settings.LogLevel, settings.LogFormat); err != nil { + logging.Fatal("logging configuration error", err) } - if err := os.MkdirAll(settings.DownloadDir, 0o755); err != nil { - log.Fatalf("download directory error: %v", err) - } - resolvedDownloadDir, err := filepath.EvalSymlinks(settings.DownloadDir) - if err != nil { - log.Fatalf("download directory error: %v", err) - } - settings.DownloadDir = resolvedDownloadDir - if err := ensureWritable(settings.DownloadDir); err != nil { - log.Fatalf("download directory %s is not writable by uid %d gid %d: %v", settings.DownloadDir, os.Getuid(), os.Getgid(), err) + if err := prepareDownloadDir(&settings); err != nil { + logging.Fatal("download directory error", err, "path", settings.DownloadDir) } store, err := preferences.Open(filepath.Join(settings.DownloadDir, settingsFileName), settings.Defaults) if err != nil { - log.Fatalf("settings error: %v", err) + logging.Fatal("could not load settings", err) } - historyStore, err := history.Open(filepath.Join(settings.DownloadDir, historyFileName)) if err != nil { - log.Fatalf("history error: %v", err) + logging.Fatal("could not load history", err) } manager := jobs.NewManager(settings, store, historyStore) if err := manager.RestoreExisting(); err != nil { - log.Printf("could not restore existing downloads: %v", err) + slog.Error("could not restore existing downloads", "error", err) } sessions := auth.NewSessionStore(settings.SessionTTL) httpServer := &http.Server{ Addr: settings.ListenAddr, Handler: server.New(settings, sessions, manager), + ErrorLog: slog.NewLogLogger(slog.Default().Handler(), slog.LevelWarn), ReadHeaderTimeout: 10 * time.Second, ReadTimeout: 30 * time.Second, WriteTimeout: 60 * time.Second, @@ -71,20 +69,41 @@ func main() { defer stopListening() go func() { - log.Printf("listening on %s", settings.ListenAddr) + slog.Info("server started", + "listen", settings.ListenAddr, + "download_dir", settings.DownloadDir, + "library_roots", settings.LibraryRoots, + "log_level", settings.LogLevel, + ) if err := httpServer.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) { - log.Fatalf("server error: %v", err) + logging.Fatal("server stopped unexpectedly", err) } }() <-shutdownSignal.Done() - log.Printf("shutting down") - shutdownContext, cancel := context.WithTimeout(context.Background(), 10*time.Second) + slog.Info("shutting down, saving download progress") + shutdownContext, cancel := context.WithTimeout(context.Background(), shutdownTimeout) defer cancel() manager.Shutdown(shutdownContext) if err := httpServer.Shutdown(shutdownContext); err != nil { - log.Printf("shutdown error: %v", err) + slog.Error("shutdown did not finish cleanly", "error", err) } + slog.Info("stopped") +} + +func prepareDownloadDir(settings *config.Settings) error { + if err := os.MkdirAll(settings.DownloadDir, 0o755); err != nil { + return err + } + resolved, err := filepath.EvalSymlinks(settings.DownloadDir) + if err != nil { + return err + } + settings.DownloadDir = resolved + if err := ensureWritable(resolved); err != nil { + return fmt.Errorf("not writable by uid %d gid %d: %w", os.Getuid(), os.Getgid(), err) + } + return nil } func ensureWritable(directory string) error { diff --git a/web/static/index.html b/web/static/index.html index 13875fb..dca6bbd 100755 --- a/web/static/index.html +++ b/web/static/index.html @@ -42,6 +42,8 @@ +
+