Add structured logging and better error handling

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

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

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

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

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

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

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
 }
 

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

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