Release 2026.09.27.r002: clarify rsync dry runs and expand run diagnostics

2026-09-27 16:23:01 +02:00
parent 106f9c9387
commit 74a69b1580
13 changed files with 451 additions and 46 deletions
@@ -0,0 +1,97 @@
+package service
+
+import (
+	"fmt"
+	"strings"
+
+	"git.casaderoll.de/michael/urbm/internal/model"
+	"git.casaderoll.de/michael/urbm/internal/rsync"
+)
+
+func logRsyncSetup(run *model.Run, job model.Job) {
+	mode := "Kopierlauf – Änderungen am Ziel werden ausgeführt"
+	if job.Rsync.DryRun {
+		mode = "Testlauf – es werden keine Dateien geschrieben oder gelöscht"
+	}
+	appendLiveLog(run, "Rsync: "+mode)
+	for _, source := range job.Sources {
+		appendLiveLog(run, "Quelle: "+source.Path)
+	}
+	appendLiveLog(run, "Ziel: "+job.Rsync.Target)
+	overwrite := "vorhandene Dateien überspringen"
+	if job.Rsync.Overwrite {
+		overwrite = "abweichende vorhandene Dateien aktualisieren"
+	}
+	deletion := "aus"
+	if job.Rsync.Delete {
+		deletion = "an (zusätzliche Einträge im Ziel entfernen)"
+	}
+	comparison := "Dateigröße und Änderungszeit"
+	if job.Rsync.Checksum {
+		comparison = "Dateiinhalt per Prüfsumme (liest Dateien vollständig)"
+	}
+	appendLiveLog(run, "Vorhandene Dateien: "+overwrite+"; Löschen: "+deletion)
+	appendLiveLog(run, "Vergleich: "+comparison)
+	var preserve []string
+	for _, option := range []struct {
+		enabled bool
+		label   string
+	}{
+		{job.Rsync.PreserveTimes, "Zeitstempel"}, {job.Rsync.PreservePermissions, "Berechtigungen"},
+		{job.Rsync.PreserveOwner, "Besitzer"}, {job.Rsync.PreserveGroup, "Gruppe"},
+		{job.Rsync.PreserveLinks, "Symlinks"}, {job.Rsync.PreserveACLs, "ACLs"}, {job.Rsync.PreserveXattrs, "erweiterte Attribute"},
+	} {
+		if option.enabled {
+			preserve = append(preserve, option.label)
+		}
+	}
+	if len(preserve) > 0 {
+		appendLiveLog(run, "Übernehmen: "+strings.Join(preserve, ", "))
+	}
+	appendLiveLog(run, fmt.Sprintf("Ausschlussmuster: %d", len(job.Excludes)))
+	for index, pattern := range job.Excludes {
+		if index == 10 {
+			appendLiveLog(run, "Weitere Ausschlussmuster siehe Job-Konfiguration")
+			break
+		}
+		appendLiveLog(run, "Ausschluss: "+pattern)
+	}
+}
+
+func rsyncChangeLabel(code string) string {
+	if strings.HasPrefix(code, "*deleting") {
+		return "Löschen"
+	}
+	if len(code) != 11 {
+		return "Änderung"
+	}
+	if code[2:] == "+++++++++" {
+		return "Neu"
+	}
+	if code[0] == '.' {
+		return "Metadaten ändern"
+	}
+	return "Aktualisieren"
+}
+
+func applyRsyncSummary(run *model.Run, summary rsync.Summary) {
+	run.Status, run.Message = "success", "rsync completed"
+	run.BytesProcessed, run.FilesProcessed = summary.Bytes, summary.Files
+	run.EntriesDeleted = summary.Deleted
+	run.BytesAdded = summary.Bytes
+	if run.RsyncDryRun {
+		run.BytesAdded = 0
+		run.Message = "Rsync-Testlauf erfolgreich – keine Änderungen vorgenommen"
+	}
+	// Rsync's transferred-file count combines new and updated regular files.
+	run.FilesNew, run.FilesChanged = 0, 0
+}
+
+func logRsyncSummary(run *model.Run, summary rsync.Summary) {
+	if run.RsyncDryRun {
+		appendLiveLog(run, fmt.Sprintf("Testlauf: %d Dateien würden kopiert/aktualisiert (%s Dateiinhalt); %d Einträge würden gelöscht (inkl. Ordner/Symlinks)", summary.Files, formatBytes(summary.Bytes), summary.Deleted))
+		appendLiveLog(run, "Testlauf erfolgreich – keine Änderungen vorgenommen")
+	} else {
+		appendLiveLog(run, fmt.Sprintf("Rsync abgeschlossen: %d Dateien kopiert/aktualisiert (%s Dateiinhalt); %d Einträge gelöscht (inkl. Ordner/Symlinks)", summary.Files, formatBytes(summary.Bytes), summary.Deleted))
+	}
+}
@@ -0,0 +1,79 @@
+package service
+
+import (
+	"context"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+	"time"
+
+	"git.casaderoll.de/michael/urbm/internal/model"
+	"git.casaderoll.de/michael/urbm/internal/queue"
+	"git.casaderoll.de/michael/urbm/internal/rsync"
+)
+
+func TestRsyncSummaryDistinguishesDryRun(t *testing.T) {
+	for _, dry := range []bool{true, false} {
+		run := model.Run{TaskType: "rsync", RsyncDryRun: dry}
+		summary := rsync.Summary{Files: 1376, Deleted: 1214, Bytes: 1234567890}
+		applyRsyncSummary(&run, summary)
+		logRsyncSummary(&run, summary)
+		message := notificationMessage("Mirror", "", run, time.Now())
+		for _, expected := range []string{"1376", "1214", "1.1 GiB"} {
+			if !strings.Contains(message, expected) || !strings.Contains(strings.Join(run.LiveLog, "\n"), expected) {
+				t.Fatalf("missing %s: %s %v", expected, message, run.LiveLog)
+			}
+		}
+		if dry {
+			if run.BytesAdded != 0 || !strings.Contains(message, "würden") || !strings.Contains(message, "keine Änderungen vorgenommen") || strings.Contains(message, "⚠️") {
+				t.Fatal(message)
+			}
+		} else if run.BytesAdded != summary.Bytes || strings.Contains(message, "würden") {
+			t.Fatal(message)
+		}
+	}
+}
+
+func TestExecuteRsyncLogsSetupSamplesAndErrors(t *testing.T) {
+	for _, fail := range []bool{false, true} {
+		dir := t.TempDir()
+		source, target := filepath.Join(dir, "source"), filepath.Join(dir, "target")
+		for _, path := range []string{source, target} {
+			if err := os.Mkdir(path, 0700); err != nil {
+				t.Fatal(err)
+			}
+		}
+		binary := filepath.Join(dir, "rsync")
+		script := "#!/bin/sh\ncase \" $* \" in *' --dry-run '*) ;; *) exit 99;; esac\n"
+		if fail {
+			script += "echo 'test failure' >&2\nexit 23\n"
+		} else {
+			script += "i=0; while [ $i -lt 25 ]; do printf 'CHANGE|>f+++++++++|source/file%s\\n' \"$i\"; i=$((i+1)); done\nprintf '%s\\n' 'Number of regular files transferred: 25' 'Number of deleted files: 3 (reg: 3)' 'Total transferred file size: 123456 bytes'\n"
+		}
+		if err := os.WriteFile(binary, []byte(script), 0700); err != nil {
+			t.Fatal(err)
+		}
+		job := model.Job{ID: "mirror", Sources: []model.Source{{Path: source}}, Rsync: model.RsyncOptions{Target: target, DryRun: true, Overwrite: true, Delete: true, Checksum: true}}
+		s := &Service{config: model.Config{Jobs: []model.Job{job}}, rsync: &rsync.Runner{Binary: binary}, queue: queue.New(nil, nil)}
+		result := s.executeRsync(context.Background(), model.Run{ID: "run", JobID: job.ID, TaskType: "rsync"})
+		log := strings.Join(result.LiveLog, "\n")
+		for _, expected := range []string{"Testlauf", "Quelle: " + source, "Ziel: " + target, "Löschen: an", "Prüfsumme"} {
+			if !strings.Contains(log, expected) {
+				t.Fatalf("missing %s: %s", expected, log)
+			}
+		}
+		if fail {
+			if result.Status != "failed" || !strings.Contains(log, "test failure") {
+				t.Fatal(result)
+			}
+		} else {
+			if result.Status != "success" || result.BytesAdded != 0 || result.BytesProcessed != 123456 || result.EntriesDeleted != 3 {
+				t.Fatal(result)
+			}
+			if strings.Count(log, "Geplant: Neu") != 20 || !strings.Contains(log, "Weitere Einzeländerungen ausgeblendet") || !strings.Contains(log, "25 Dateien würden") {
+				t.Fatal(log)
+			}
+		}
+	}
+}
@@ -1135,13 +1135,20 @@ func (s *Service) executeRsync(ctx context.Context, run model.Run) (result model
 	if !ok {
 		return failed(run, "validation", "job no longer exists")
 	}
+	run.RsyncDryRun = job.Rsync.DryRun
 	defer func() { result = s.finishJob(run, job, result) }()
+	live := run
+	logRsyncSetup(&live, job)
+	defer func() {
+		if result.Status == "failed" || result.Status == "cancelled" {
+			appendLiveLog(&live, "Rsync abgebrochen/fehlgeschlagen: "+result.Message)
+		}
+		result.LiveLog = live.LiveLog
+	}()
+	s.updateActive(live)
 	if err := platform.ValidateRsyncPaths(job); err != nil {
 		return failedError(run, err)
 	}
-	live := run
-	appendLiveLog(&live, fmt.Sprintf("Rsync-Kopie wird vorbereitet: %d Quelle(n) nach %s", len(job.Sources), job.Rsync.Target))
-	s.updateActive(live)
 	for _, source := range job.Sources {
 		if _, err := os.Stat(source.Path); err != nil {
 			return failed(run, "source", "source unavailable: "+source.Path)
@@ -1154,7 +1161,7 @@ func (s *Service) executeRsync(ctx context.Context, run model.Run) (result model
 		return failed(run, "environment", "rsync target unavailable: "+err.Error())
 	}
 	if !job.Rsync.DryRun && !job.Rsync.SkipSpaceCheck {
-		appendLiveLog(&live, "Rsync-Vorabprüfung ermittelt den tatsächlich zu übertragenden Datenumfang")
+		appendLiveLog(&live, "Speicherplatz-Vorabprüfung: rsync vergleicht Quellen und Ziel ohne Änderungen; bei großen Verzeichnissen kann dies dauern")
 		s.updateActive(live)
 		estimate, err := s.rsync.Estimate(ctx, run.ID, job)
 		if err != nil {
@@ -1170,6 +1177,14 @@ func (s *Service) executeRsync(ctx context.Context, run model.Run) (result model
 			return failed(run, "environment", fmt.Sprintf("Rsync-Ziel hat nicht genügend freien Speicher: ungefähr %s für %d Dateien erforderlich, aber nur %s frei unter %s", formatBytes(estimate.Bytes), estimate.Files, formatBytes(available), job.Rsync.Target))
 		}
 	}
+	if job.Rsync.DryRun {
+		appendLiveLog(&live, "Speicherplatz-Vorabprüfung entfällt beim Testlauf")
+	} else if job.Rsync.SkipSpaceCheck {
+		appendLiveLog(&live, "Speicherplatz-Vorabprüfung laut Job-Einstellung übersprungen")
+	}
+	appendLiveLog(&live, "Rsync startet den Dateivergleich; Änderungen werden als Stichprobe protokolliert (max. 20 Einträge)")
+	s.updateActive(live)
+	changesLogged := 0
 	started := time.Now()
 	lastLoggedPercent := -10
 	summary, err := s.rsync.Run(ctx, run.ID, job, func(progress rsync.Progress) {
@@ -1184,28 +1199,37 @@ func (s *Service) executeRsync(ctx context.Context, run model.Run) (result model
 			}
 			percent := int(progress.Percent)
 			if percent >= lastLoggedPercent+10 {
-				appendLiveLog(&live, fmt.Sprintf("Rsync-Fortschritt: %.0f%%, %s übertragen", progress.Percent, formatBytes(progress.Bytes)))
+				if job.Rsync.DryRun {
+					appendLiveLog(&live, fmt.Sprintf("Testlauf-Fortschritt: %.0f%% (keine Übertragung)", progress.Percent))
+				} else {
+					appendLiveLog(&live, fmt.Sprintf("Rsync-Fortschritt: %.0f%%, %s übertragen", progress.Percent, formatBytes(progress.Bytes)))
+				}
 				lastLoggedPercent = percent - percent%10
 			}
 		}
 		if progress.CurrentFile != "" {
 			live.CurrentFile = progress.CurrentFile
+			if changesLogged < 20 {
+				prefix := "Änderung: "
+				if job.Rsync.DryRun {
+					prefix = "Geplant: "
+				}
+				appendLiveLog(&live, prefix+rsyncChangeLabel(progress.Change)+" · "+progress.CurrentFile)
+			} else if changesLogged == 20 {
+				appendLiveLog(&live, "Weitere Einzeländerungen ausgeblendet; die Zusammenfassung zählt alle Dateien und Löschungen")
+			}
+			changesLogged++
 		}
 		s.updateActive(live)
 	})
 	if err != nil {
-		appendLiveLog(&live, "Rsync-Kopie fehlgeschlagen: "+err.Error())
-		failedRun := failedError(run, err)
-		failedRun.LiveLog = live.LiveLog
-		return failedRun
+		return failedError(run, err)
 	}
-	run.Status, run.Message = "success", "rsync completed"
-	run.BytesAdded, run.BytesProcessed = summary.Bytes, summary.Bytes
-	run.FilesNew, run.FilesProcessed = summary.Files, summary.Files
+	applyRsyncSummary(&run, summary)
 	run.ProgressPercent, run.ProgressBytes, run.ProgressTotal = 100, summary.Bytes, summary.Bytes
 	run.ProgressFiles, run.ProgressFileTotal = summary.Files, summary.Files
 	run.BytesPerSecond, run.CurrentFile = live.BytesPerSecond, live.CurrentFile
-	appendLiveLog(&live, fmt.Sprintf("Rsync-Kopie abgeschlossen: %d Dateien, %s", summary.Files, formatBytes(summary.Bytes)))
+	logRsyncSummary(&live, summary)
 	run.LiveLog = live.LiveLog
 	return run
 }
@@ -1447,6 +1471,7 @@ func diffKindLabel(kind string) string {

 func (s *Service) updateActive(run model.Run) {
 	s.queue.UpdateActive(run.ID, func(active *model.Run) {
+		active.RsyncDryRun = run.RsyncDryRun
 		active.ProgressPercent, active.ProgressBytes, active.ProgressTotal = run.ProgressPercent, run.ProgressBytes, run.ProgressTotal
 		active.ProgressFiles, active.ProgressFileTotal = run.ProgressFiles, run.ProgressFileTotal
 		active.BytesPerSecond, active.SecondsRemaining = run.BytesPerSecond, run.SecondsRemaining
@@ -1592,6 +1617,9 @@ func notificationMessage(name, repository string, run model.Run, now time.Time)
 	if status == "" {
 		status = run.Status
 	}
+	if run.TaskType == "rsync" && run.RsyncDryRun && run.Status == "success" {
+		status = "Testlauf erfolgreich – keine Änderungen vorgenommen"
+	}
 	summaryTitle := map[string]string{"backup": "📊 Backup-Zusammenfassung", "rsync": "📊 Rsync-Zusammenfassung", "restore": "📊 Restore-Zusammenfassung", "prune": "🧹 Prune-Zusammenfassung", "check": "🔎 Prüfungs-Zusammenfassung"}[run.TaskType]
 	if summaryTitle == "" {
 		summaryTitle = "📊 URBM-Zusammenfassung"
@@ -1615,19 +1643,29 @@ func notificationMessage(name, repository string, run model.Run, now time.Time)
 			lines = append(lines, "", "⏱️ Dauer: "+formatDuration(duration))
 		}
 	}
-	if (run.TaskType == "backup" || run.TaskType == "rsync") && (run.Status == "success" || run.Status == "warning") {
+	if run.TaskType == "backup" && (run.Status == "success" || run.Status == "warning") {
 		lines = append(lines,
 			fmt.Sprintf("📂 Dateien: %d verarbeitet", run.FilesProcessed),
 			"💾 Verarbeitet: "+formatBytes(run.BytesProcessed),
 		)
-		if run.TaskType == "backup" {
+		lines = append(lines,
+			fmt.Sprintf("➕ Neu: %d Dateien", run.FilesNew),
+			fmt.Sprintf("✏️ Geändert: %d Dateien", run.FilesChanged),
+			"📤 Neu gespeichert: "+formatBytes(run.BytesAdded),
+		)
+	}
+	if run.TaskType == "rsync" && (run.Status == "success" || run.Status == "warning") {
+		if run.RsyncDryRun {
 			lines = append(lines,
-				fmt.Sprintf("➕ Neu: %d Dateien", run.FilesNew),
-				fmt.Sprintf("✏️ Geändert: %d Dateien", run.FilesChanged),
-				"📤 Neu gespeichert: "+formatBytes(run.BytesAdded),
-			)
+				"🧪 Testlauf – keine Änderungen vorgenommen",
+				fmt.Sprintf("📂 Dateien würden kopiert/aktualisiert: %d", run.FilesProcessed),
+				"💾 Geplanter Dateiinhalt: "+formatBytes(run.BytesProcessed),
+				fmt.Sprintf("🗑️ Einträge würden gelöscht (inkl. Ordner/Symlinks): %d", run.EntriesDeleted))
 		} else {
-			lines = append(lines, "📤 Kopiert: "+formatBytes(run.BytesAdded))
+			lines = append(lines,
+				fmt.Sprintf("📂 Dateien kopiert/aktualisiert: %d", run.FilesProcessed),
+				"📤 Kopierter Dateiinhalt: "+formatBytes(run.BytesAdded),
+				fmt.Sprintf("🗑️ Einträge gelöscht (inkl. Ordner/Symlinks): %d", run.EntriesDeleted))
 		}
 	}
 	if run.TaskType == "backup" && run.RetentionAfter > 0 {
@@ -1646,7 +1684,7 @@ func notificationMessage(name, repository string, run model.Run, now time.Time)
 		)
 	}
 	lines = append(lines, "", "🔐 Ziel: "+notificationTargetLabel(run.TaskType), statusIcon(run.Status)+" Status: "+status)
-	if run.Message != "" && run.Message != run.TaskType+" completed" {
+	if run.Message != "" && run.Message != run.TaskType+" completed" && !(run.RsyncDryRun && run.Status == "success") {
 		lines = append(lines, "⚠️ Details: "+run.Message)
 	}
 	return strings.Join(lines, "\n")