lehnert.cloud/ad-ds-simple-file-server
1
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

better backup script

Browse Source
This commit is contained in:
Ludwig Lehnert
2026-07-17 13:23:00 +00:00
parent fb7a69d24c
commit 39968c5be8
6 changed files with 608 additions and 24 deletions
Download Patch File Download Diff File Expand all files Collapse all files

3
.env.example
View File

@@ -24,3 +24,6 @@ FSLOGIX_GROUP_SID=S-1-5-21-1111111111-2222222222-3333333333-513
# BACKUP_RETENTION_WEEKLY=2
# BACKUP_RETENTION_MONTHLY=2
# BACKUP_RETENTION_YEARLY=1
# BACKUP_LOG_FILE=/var/log/backup.log
# BACKUP_PROGRESS=auto
# BACKUP_PROGRESS_INTERVAL_SECONDS=10

9
README.md
View File

@@ -121,6 +121,9 @@ Kerberos requires close time alignment.
- optional `BACKUP_RETENTION_WEEKLY` (default `2`)
- optional `BACKUP_RETENTION_MONTHLY` (default `2`)
- optional `BACKUP_RETENTION_YEARLY` (default `1`)
- optional `BACKUP_LOG_FILE` (default `/var/log/backup.log`)
- optional `BACKUP_PROGRESS` (`auto`, `always`, or `never`; default `auto`)
- optional `BACKUP_PROGRESS_INTERVAL_SECONDS` (default `10`)
Optional:
- `SAMBA_HOSTNAME` (defaults to `adsambafsrv`)
@@ -198,6 +201,9 @@ Kerberos requires close time alignment.
- `BACKUP_RETENTION_MONTHLY=2`
- `BACKUP_RETENTION_WEEKLY=2`
- `BACKUP_RETENTION_DAILY=3`
- The backup script writes directly to `BACKUP_LOG_FILE` (default: `/var/log/backup.log`). Cron does not redirect backup output into the logfile.
- Upload progress is logged per file every `BACKUP_PROGRESS_INTERVAL_SECONDS` seconds and again when a file reaches 100%.
- `BACKUP_PROGRESS=auto` shows an interactive progress bar only for TTY/manual runs. Use `always` to force it or `never` to suppress the bar. File progress is still logged.
- Retention logic:
- daily: newest N snapshots
- weekly: newest N snapshots created on week start (Monday)
@@ -220,6 +226,9 @@ Kerberos requires close time alignment.
BACKUP_RETENTION_WEEKLY=2
BACKUP_RETENTION_MONTHLY=2
BACKUP_RETENTION_YEARLY=1
BACKUP_LOG_FILE=/var/log/backup.log
BACKUP_PROGRESS=auto
BACKUP_PROGRESS_INTERVAL_SECONDS=10
```
## Useful Commands

444
app/backup_to_destination.py
View File

@@ -7,13 +7,33 @@ import re
import subprocess
import sys
import tempfile
import time
from dataclasses import dataclass
from typing import Dict, List, Optional, Set, Tuple
from typing import Callable, Dict, List, Optional, Set, TextIO, Tuple
from urllib.parse import SplitResult, unquote, urlsplit
LOCK_PATH = "/state/backup.lock"
DEFAULT_BACKUP_LOG_FILE = "/var/log/backup.log"
DEFAULT_PROGRESS_MODE = "auto"
DEFAULT_PROGRESS_INTERVAL_SECONDS = 10
PROGRESS_BAR_WIDTH = 28
MAX_CAPTURED_OUTPUT_LINES = 50
MAX_CAPTURED_OUTPUT_RECORD_LENGTH = 1000
SNAPSHOT_NAME_RE = re.compile(r"^\d{8}T\d{6}Z$")
ANSI_ESCAPE_RE = re.compile(r"\x1b\[[0-?]*[ -/]*[@-~]")
RCLONE_FILE_PROGRESS_RE = re.compile(
r"^\s*\*\s+(?P<file>.+?):\s+(?P<percent>\d+(?:\.\d+)?)%\s*(?P<detail>.*)$"
)
RSYNC_FILE_PROGRESS_RE = re.compile(
r"^\s*[\d,.]+[A-Za-z]?\s+(?P<percent>\d+(?:\.\d+)?)%\s+(?P<detail>.+)$"
)
RSYNC_IGNORED_RECORD_PREFIXES = (
"sending incremental file list",
"receiving incremental file list",
"sent ",
"total size is ",
)
BACKUP_SOURCES: List[Tuple[str, str]] = [
("/data/private", "data/private"),
@@ -67,8 +87,73 @@ class Snapshot:
timestamp: dt.datetime
def log(message: str) -> None:
print(f"[backup] {message}", flush=True)
@dataclass(frozen=True)
class FileProgress:
file_path: str
percent: float
detail: str
class BackupLogger:
def __init__(
self,
*,
console_stream: TextIO = sys.stdout,
error_stream: TextIO = sys.stderr,
):
self.console_stream = console_stream
self.error_stream = error_stream
self.log_path: Optional[str] = None
self._handle: Optional[TextIO] = None
def configure(self, log_path: str) -> None:
self.close()
self.log_path = log_path
if not log_path:
return
log_dir = os.path.dirname(log_path)
try:
if log_dir:
os.makedirs(log_dir, exist_ok=True)
self._handle = open(log_path, "a", encoding="utf-8")
except OSError as exc:
self._handle = None
print(
f"[backup] WARNING: unable to open log file {log_path}: {exc}",
file=self.error_stream,
flush=True,
)
def close(self) -> None:
if self._handle is None:
return
self._handle.close()
self._handle = None
def log(self, message: str, *, console: bool = True) -> None:
line = f"[backup] {message}"
if console:
print(line, file=self.console_stream, flush=True)
if self._handle is not None:
timestamp = dt.datetime.now(dt.timezone.utc).isoformat(timespec="seconds")
self._handle.write(f"{timestamp} {line}\n")
self._handle.flush()
LOGGER = BackupLogger()
def configure_logging() -> None:
LOGGER.configure(os.getenv("BACKUP_LOG_FILE", DEFAULT_BACKUP_LOG_FILE).strip())
def close_logging() -> None:
LOGGER.close()
def log(message: str, *, console: bool = True) -> None:
LOGGER.log(message, console=console)
def run_command(
@@ -91,6 +176,256 @@ def run_command(
return result
def parse_progress_mode() -> str:
raw_value = os.getenv("BACKUP_PROGRESS", DEFAULT_PROGRESS_MODE).strip().lower()
if raw_value in {"auto", "always", "never"}:
return raw_value
log(f"Invalid BACKUP_PROGRESS='{raw_value}', using default {DEFAULT_PROGRESS_MODE}")
return DEFAULT_PROGRESS_MODE
def should_show_progress_bar(mode: str, stream: TextIO = sys.stderr) -> bool:
if mode == "always":
return True
if mode == "never":
return False
return bool(stream.isatty())
def format_percent(percent: float) -> str:
if percent.is_integer():
return str(int(percent))
return f"{percent:.1f}".rstrip("0").rstrip(".")
def clamp_percent(percent: float) -> float:
return max(0.0, min(100.0, percent))
def shorten_middle(value: str, max_length: int) -> str:
if len(value) <= max_length:
return value
if max_length <= 3:
return value[:max_length]
left = (max_length - 3) // 2
right = max_length - 3 - left
return f"{value[:left]}...{value[-right:]}"
def clean_output_record(record: str) -> str:
return ANSI_ESCAPE_RE.sub("", record).strip()
def truncate_output_record(record: str) -> str:
if len(record) <= MAX_CAPTURED_OUTPUT_RECORD_LENGTH:
return record
return f"{record[:MAX_CAPTURED_OUTPUT_RECORD_LENGTH]}..."
def parse_rclone_progress_record(record: str) -> Optional[FileProgress]:
match = RCLONE_FILE_PROGRESS_RE.match(record)
if not match:
return None
return FileProgress(
file_path=match.group("file").strip(),
percent=clamp_percent(float(match.group("percent"))),
detail=match.group("detail").strip(),
)
def rsync_file_candidate(record: str) -> Optional[str]:
stripped = record.strip()
if not stripped:
return None
lower = stripped.lower()
if any(lower.startswith(prefix) for prefix in RSYNC_IGNORED_RECORD_PREFIXES):
return None
if lower.startswith("deleting "):
return None
if stripped.endswith("/"):
return None
if RSYNC_FILE_PROGRESS_RE.match(stripped):
return None
return stripped
def parse_rsync_progress_record(
record: str, current_file: Optional[str]
) -> Optional[FileProgress]:
if not current_file:
return None
match = RSYNC_FILE_PROGRESS_RE.match(record)
if not match:
return None
return FileProgress(
file_path=current_file,
percent=clamp_percent(float(match.group("percent"))),
detail=match.group("detail").strip(),
)
class OutputRecordSplitter:
def __init__(self) -> None:
self._buffer = ""
def feed(self, chunk: str) -> List[str]:
records: List[str] = []
for char in chunk:
if char in {"\r", "\n"}:
record = clean_output_record(self._buffer)
self._buffer = ""
if record:
records.append(record)
continue
self._buffer += char
return records
def close(self) -> List[str]:
record = clean_output_record(self._buffer)
self._buffer = ""
if not record:
return []
return [record]
class SyncProgressReporter:
def __init__(
self,
backend_name: str,
source_path: str,
destination_path: str,
*,
interval_seconds: int,
interactive: bool,
stream: TextIO = sys.stderr,
now: Callable[[], float] = time.monotonic,
log_func: Callable[..., None] = log,
):
self.backend_name = backend_name
self.source_path = source_path
self.destination_path = destination_path
self.interval_seconds = interval_seconds
self.interactive = interactive
self.stream = stream
self.now = now
self.log_func = log_func
self.current_rsync_file: Optional[str] = None
self._last_log_at: Dict[str, float] = {}
self._last_logged_percent: Dict[str, float] = {}
self._last_bar_length = 0
def observe(self, record: str) -> None:
progress: Optional[FileProgress]
if self.backend_name == "rclone":
progress = parse_rclone_progress_record(record)
else:
progress = parse_rsync_progress_record(record, self.current_rsync_file)
if progress is None:
candidate = rsync_file_candidate(record)
if candidate is not None:
self.current_rsync_file = candidate
return
if progress is None:
return
self._render_bar(progress)
self._log_progress(progress)
def finish(self) -> None:
if not self.interactive or self._last_bar_length == 0:
return
self.stream.write("\r" + (" " * self._last_bar_length) + "\r")
self.stream.flush()
self._last_bar_length = 0
def _log_progress(self, progress: FileProgress) -> None:
now = self.now()
key = progress.file_path
last_log_at = self._last_log_at.get(key)
last_logged_percent = self._last_logged_percent.get(key)
is_final = progress.percent >= 100.0
if (
last_log_at is not None
and now - last_log_at < self.interval_seconds
and not (is_final and last_logged_percent != 100.0)
):
return
detail = f" ({progress.detail})" if progress.detail else ""
self.log_func(
"Upload progress "
f"{self.source_path} -> {self.destination_path}: "
f"{progress.file_path} {format_percent(progress.percent)}%{detail}",
console=not self.interactive,
)
self._last_log_at[key] = now
self._last_logged_percent[key] = progress.percent
def _render_bar(self, progress: FileProgress) -> None:
if not self.interactive:
return
filled = int(PROGRESS_BAR_WIDTH * (progress.percent / 100.0))
bar = "#" * filled + "-" * (PROGRESS_BAR_WIDTH - filled)
file_path = shorten_middle(progress.file_path, 44)
source_path = shorten_middle(self.source_path, 24)
line = (
f"[backup] {source_path}: {file_path} "
f"[{bar}] {format_percent(progress.percent)}%"
)
if len(line) >= self._last_bar_length:
padding = ""
else:
padding = " " * (self._last_bar_length - len(line))
self.stream.write(f"\r{line}{padding}")
self.stream.flush()
self._last_bar_length = len(line)
def run_streaming_command(
command: List[str],
*,
progress: SyncProgressReporter,
env: Optional[Dict[str, str]] = None,
) -> subprocess.CompletedProcess:
process = subprocess.Popen(
command,
stdout=subprocess.PIPE,
stderr=subprocess.STDOUT,
text=True,
bufsize=1,
env=env,
)
splitter = OutputRecordSplitter()
captured_records: List[str] = []
try:
if process.stdout is not None:
while True:
chunk = process.stdout.read(1)
if chunk == "":
if process.poll() is not None:
break
continue
for record in splitter.feed(chunk):
captured_records.append(truncate_output_record(record))
captured_records = captured_records[-MAX_CAPTURED_OUTPUT_LINES:]
progress.observe(record)
for record in splitter.close():
captured_records.append(truncate_output_record(record))
captured_records = captured_records[-MAX_CAPTURED_OUTPUT_LINES:]
progress.observe(record)
returncode = process.wait()
finally:
progress.finish()
stdout = "\n".join(captured_records)
if returncode != 0:
output = stdout.strip() or f"exit code {returncode}"
raise RuntimeError(f"Command failed ({command[0]}): {output}")
return subprocess.CompletedProcess(command, returncode, stdout=stdout, stderr="")
def parse_destination(raw_url: str) -> Destination:
parts = urlsplit(raw_url)
scheme = parts.scheme.lower()
@@ -399,16 +734,38 @@ class RcloneBackend:
return join_path(self._snapshots_root(), snapshot_name)
def sync_source(
self, snapshot_name: str, source_path: str, destination_path: str
self,
snapshot_name: str,
source_path: str,
destination_path: str,
*,
progress_interval_seconds: int,
interactive_progress: bool,
) -> None:
remote_path = join_path(self._snapshot_root(snapshot_name), destination_path)
self._run(
progress = SyncProgressReporter(
"rclone",
source_path,
destination_path,
interval_seconds=progress_interval_seconds,
interactive=interactive_progress,
)
run_streaming_command(
[
"rclone",
"sync",
f"{source_path}/",
f"backup:{remote_path}",
"--create-empty-src-dirs",
]
"--progress",
"--stats",
f"{progress_interval_seconds}s",
"--log-level",
"INFO",
"--config",
self.config_path,
],
progress=progress,
)
def write_marker(self, snapshot_name: str) -> None:
@@ -494,14 +851,36 @@ class RsyncBackend:
return f"{self.remote_base}/{trimmed}"
def sync_source(
self, snapshot_name: str, source_path: str, destination_path: str
self,
snapshot_name: str,
source_path: str,
destination_path: str,
*,
progress_interval_seconds: int,
interactive_progress: bool,
) -> None:
target = self._remote_path(
join_path(f"snapshots/{snapshot_name}", destination_path)
)
run_command(
["rsync", "-a", "--delete", f"{source_path}/", f"{target}/"],
progress = SyncProgressReporter(
"rsync",
source_path,
destination_path,
interval_seconds=progress_interval_seconds,
interactive=interactive_progress,
)
run_streaming_command(
[
"rsync",
"-a",
"--delete",
"--progress",
"--outbuf=L",
f"{source_path}/",
f"{target}/",
],
env=self.command_env,
progress=progress,
)
def write_marker(self, snapshot_name: str) -> None:
@@ -621,6 +1000,15 @@ def run_backup() -> int:
log("No backup sources are available, skipping backup")
return 0
progress_interval_seconds = parse_int_env(
"BACKUP_PROGRESS_INTERVAL_SECONDS",
DEFAULT_PROGRESS_INTERVAL_SECONDS,
minimum=1,
maximum=None,
)
progress_mode = parse_progress_mode()
interactive_progress = should_show_progress_bar(progress_mode)
destination = parse_destination(destination_url)
backend = build_backend(destination)
try:
@@ -632,7 +1020,13 @@ def run_backup() -> int:
for source_path, destination_path in sources:
log(f"Syncing {source_path}")
backend.sync_source(snapshot_name, source_path, destination_path)
backend.sync_source(
snapshot_name,
source_path,
destination_path,
progress_interval_seconds=progress_interval_seconds,
interactive_progress=interactive_progress,
)
backend.write_marker(snapshot_name)
@@ -670,20 +1064,24 @@ def with_lock() -> int:
def main() -> int:
backup_hour = parse_int_env(
"BACKUP_START_HOUR",
DEFAULT_BACKUP_START_HOUR,
minimum=0,
maximum=23,
)
if backup_hour != DEFAULT_BACKUP_START_HOUR:
log(f"Configured backup start hour is {backup_hour}:00")
configure_logging()
try:
return with_lock()
except Exception as exc: # pylint: disable=broad-except
log(f"ERROR: {exc}")
return 1
backup_hour = parse_int_env(
"BACKUP_START_HOUR",
DEFAULT_BACKUP_START_HOUR,
minimum=0,
maximum=23,
)
if backup_hour != DEFAULT_BACKUP_START_HOUR:
log(f"Configured backup start hour is {backup_hour}:00")
try:
return with_lock()
except Exception as exc: # pylint: disable=broad-except
log(f"ERROR: {exc}")
return 1
finally:
close_logging()
if __name__ == "__main__":

11
app/init.sh
View File

@@ -214,6 +214,15 @@ write_runtime_env_file() {
if [[ -n "${BACKUP_RETENTION_YEARLY:-}" ]]; then
printf 'export BACKUP_RETENTION_YEARLY=%q\n' "$BACKUP_RETENTION_YEARLY"
fi
if [[ -n "${BACKUP_LOG_FILE:-}" ]]; then
printf 'export BACKUP_LOG_FILE=%q\n' "$BACKUP_LOG_FILE"
fi
if [[ -n "${BACKUP_PROGRESS:-}" ]]; then
printf 'export BACKUP_PROGRESS=%q\n' "$BACKUP_PROGRESS"
fi
if [[ -n "${BACKUP_PROGRESS_INTERVAL_SECONDS:-}" ]]; then
printf 'export BACKUP_PROGRESS_INTERVAL_SECONDS=%q\n' "$BACKUP_PROGRESS_INTERVAL_SECONDS"
fi
if [[ -n "${JOIN_USER:-}" ]]; then
printf 'export JOIN_USER=%q\n' "$JOIN_USER"
fi
@@ -288,7 +297,7 @@ EOF
if [[ -n "${BACKUP_DESTINATION:-}" ]]; then
cat >> /etc/cron.d/reconcile-shares <<EOF
0 ${BACKUP_START_HOUR} * * * root source /app/runtime.env && /usr/bin/python3 /app/backup_to_destination.py >> /var/log/backup.log 2>&1
0 ${BACKUP_START_HOUR} * * * root source /app/runtime.env && /usr/bin/python3 /app/backup_to_destination.py
EOF
fi

3
setup
View File

@@ -325,6 +325,9 @@ NETBIOS_NAME=${netbios_name}
# BACKUP_RETENTION_WEEKLY=2
# BACKUP_RETENTION_MONTHLY=2
# BACKUP_RETENTION_YEARLY=1
# BACKUP_LOG_FILE=/var/log/backup.log
# BACKUP_PROGRESS=auto
# BACKUP_PROGRESS_INTERVAL_SECONDS=10
EOF
chmod 600 "$ENV_FILE"

162
tests/test_backup_to_destination.py Normal file
View File

@@ -0,0 +1,162 @@
import io
import os
import tempfile
import unittest
from unittest import mock
from app import backup_to_destination as backup
class BackupLoggerTests(unittest.TestCase):
def test_logger_writes_console_and_timestamped_file(self):
console = io.StringIO()
errors = io.StringIO()
with tempfile.TemporaryDirectory() as tmpdir:
log_path = os.path.join(tmpdir, "backup.log")
logger = backup.BackupLogger(console_stream=console, error_stream=errors)
logger.configure(log_path)
logger.log("hello")
logger.close()
self.assertEqual(console.getvalue(), "[backup] hello\n")
self.assertEqual(errors.getvalue(), "")
with open(log_path, encoding="utf-8") as handle:
contents = handle.read()
self.assertRegex(
contents,
r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\+00:00 \[backup\] hello\n$",
)
class ProgressConfigTests(unittest.TestCase):
def test_parse_progress_mode_accepts_known_values(self):
with mock.patch.dict(os.environ, {"BACKUP_PROGRESS": "ALWAYS"}):
self.assertEqual(backup.parse_progress_mode(), "always")
def test_parse_progress_mode_defaults_invalid_values(self):
with mock.patch.dict(os.environ, {"BACKUP_PROGRESS": "loud"}):
with mock.patch.object(backup, "log") as log:
self.assertEqual(backup.parse_progress_mode(), "auto")
log.assert_called_once()
def test_should_show_progress_bar_honors_mode_and_tty(self):
class Stream:
def __init__(self, is_tty):
self.is_tty = is_tty
def isatty(self):
return self.is_tty
self.assertTrue(backup.should_show_progress_bar("always", Stream(False)))
self.assertFalse(backup.should_show_progress_bar("never", Stream(True)))
self.assertTrue(backup.should_show_progress_bar("auto", Stream(True)))
self.assertFalse(backup.should_show_progress_bar("auto", Stream(False)))
class ProgressParsingTests(unittest.TestCase):
def test_splitter_handles_carriage_returns_newlines_and_ansi(self):
splitter = backup.OutputRecordSplitter()
self.assertEqual(splitter.feed("\x1b[2Kone\rtwo\n\nthree"), ["one", "two"])
self.assertEqual(splitter.close(), ["three"])
def test_parse_rclone_file_progress(self):
progress = backup.parse_rclone_progress_record(
" * data/private/file.txt: 42.5% /10Mi, 2Mi/s, ETA 4s"
)
self.assertEqual(progress.file_path, "data/private/file.txt")
self.assertEqual(progress.percent, 42.5)
self.assertEqual(progress.detail, "/10Mi, 2Mi/s, ETA 4s")
def test_parse_rsync_file_progress_uses_current_file(self):
progress = backup.parse_rsync_progress_record(
" 1,024 50% 1.00MB/s 0:00:01", "dir/file.bin"
)
self.assertEqual(progress.file_path, "dir/file.bin")
self.assertEqual(progress.percent, 50.0)
self.assertEqual(progress.detail, "1.00MB/s 0:00:01")
def test_reporter_throttles_progress_but_logs_final_event(self):
clock = [0.0]
logs = []
reporter = backup.SyncProgressReporter(
"rsync",
"/src",
"data/private",
interval_seconds=10,
interactive=True,
stream=io.StringIO(),
now=lambda: clock[0],
log_func=lambda message, console=True: logs.append((message, console)),
)
reporter.observe("dir/file.bin")
reporter.observe(" 10 10% 1.00MB/s 0:00:09")
clock[0] = 5.0
reporter.observe(" 20 20% 1.00MB/s 0:00:08")
clock[0] = 10.0
reporter.observe(" 30 30% 1.00MB/s 0:00:07")
clock[0] = 11.0
reporter.observe(" 100 100% 1.00MB/s 0:00:00")
self.assertEqual(len(logs), 3)
self.assertIn("dir/file.bin 10%", logs[0][0])
self.assertIn("dir/file.bin 30%", logs[1][0])
self.assertIn("dir/file.bin 100%", logs[2][0])
self.assertEqual([console for _, console in logs], [False, False, False])
class BackendProgressCommandTests(unittest.TestCase):
def test_rclone_sync_uses_progress_flags(self):
destination = backup.parse_destination("sftp://user@example.com/backups")
backend = backup.RcloneBackend(destination)
try:
with mock.patch.object(backup, "run_streaming_command") as run_streaming:
backend.sync_source(
"20260101T000000Z",
"/src",
"data/private",
progress_interval_seconds=7,
interactive_progress=False,
)
command = run_streaming.call_args.args[0]
self.assertIn("--progress", command)
self.assertIn("--stats", command)
self.assertIn("7s", command)
self.assertIn("--log-level", command)
self.assertIn("INFO", command)
self.assertIn("--config", command)
self.assertEqual(
run_streaming.call_args.kwargs["progress"].backend_name, "rclone"
)
finally:
backend.close()
def test_rsync_sync_uses_progress_flags(self):
destination = backup.parse_destination("rsync://user@example.com/module/path")
backend = backup.RsyncBackend(destination)
with mock.patch.object(backup, "run_streaming_command") as run_streaming:
backend.sync_source(
"20260101T000000Z",
"/src",
"data/private",
progress_interval_seconds=7,
interactive_progress=False,
)
command = run_streaming.call_args.args[0]
self.assertIn("--progress", command)
self.assertIn("--outbuf=L", command)
self.assertEqual(
run_streaming.call_args.kwargs["progress"].backend_name, "rsync"
)
self.assertIs(run_streaming.call_args.kwargs["env"], backend.command_env)
if __name__ == "__main__":
unittest.main()