Skip to content

Commit

Permalink
improved logging; rsync progress
Browse files Browse the repository at this point in the history
  • Loading branch information
@eimrek
eimrek committed Feb 14, 2024
1 parent 7db646f commit aaf77eb
Show file tree
Hide file tree
Showing 3 changed files with 65 additions and 49 deletions.
80 changes: 47 additions & 33 deletions disk_objectstore/backup_utils.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,8 +15,7 @@

from disk_objectstore.container import Container

logging.basicConfig(format="%(levelname)s:%(message)s")
backup_logger = logging.getLogger(__name__)
LOGGER = logging.getLogger(__name__)


class BackupError(Exception):
Expand Down Expand Up @@ -49,13 +48,11 @@ class BackupManager:
def __init__(
self,
dest: str,
logger: logging.Logger,
keep: int = 1,
rsync_exe: Optional[str] = None,
) -> None:
self.dest = dest
self.keep = keep
self.logger = logger
self.remote, self.path = split_remote_and_path(dest)
self.rsync_exe = rsync_exe if rsync_exe is not None else "rsync"

Expand Down Expand Up @@ -83,11 +80,11 @@ def __init__(

def check_if_remote_accessible(self):
"""Check if remote host is accessible via ssh"""
self.logger.info(f"Checking if '{self.remote}' is accessible...")
LOGGER.info("Checking if '%s' is accessible...", self.remote)
success = self.run_cmd(["exit"])[0]
if not success:
raise BackupError(f"Remote '{self.remote}' is not accessible!")
self.logger.info("Success! '%s' is accessible!", self.remote)
LOGGER.info("Success! '%s' is accessible!", self.remote)

def check_path_exists(self, path: Path) -> bool:
cmd = ["[", "-e", str(path), "]"]
Expand All @@ -106,10 +103,12 @@ def run_cmd(

res = subprocess.run(all_args, capture_output=True, text=True, check=False)

self.logger.debug(
f"Command: {all_args}\n"
f" Exit Code: {res.returncode}\n"
f" stdout/stderr: {res.stdout}\n{res.stderr}"
LOGGER.debug(
"Command: %s\n Exit Code: %d\n stdout/stderr: %s\n%s",
str(all_args),
res.returncode,
res.stdout,
res.stderr,
)

success = res.returncode == 0
Expand Down Expand Up @@ -137,10 +136,16 @@ def call_rsync( # pylint: disable=too-many-arguments
:param dest_trailing_slash:
Add a trailing slash to the destination path. This makes rsync interpret the
destination as a folder and create it if it doesn't exists.
"""

all_args = [self.rsync_exe, "-azh", "-vv", "--no-whole-file"]
all_args = [
self.rsync_exe,
"-azh",
"--no-whole-file",
"--info=progress2,stats1",
]
if LOGGER.isEnabledFor(logging.DEBUG):
all_args += ["-vv"]
if extra_args:
all_args += extra_args
if link_dest:
Expand All @@ -163,16 +168,22 @@ def call_rsync( # pylint: disable=too-many-arguments
else:
all_args += [f"{self.remote}:{dest_str}"]

res = subprocess.run(all_args, capture_output=True, text=True, check=False)
cmd_str = " ".join(all_args)
LOGGER.info("Running '%s'", cmd_str)

self.logger.debug(
"Command: %s\n Exit Code: %s\n stdout/stderr: %s\n%s",
str(all_args),
res.returncode,
res.stdout,
res.stderr,
capture_output = True
if LOGGER.isEnabledFor(logging.INFO):
capture_output = False

res = subprocess.run(
all_args, capture_output=capture_output, text=True, check=False
)

info_text = f"rsync completed. Exit Code: {res.returncode}"
if capture_output:
info_text += f"\nstdout/stderr: {res.stdout}\n{res.stderr}"
LOGGER.info(info_text)

if res.returncode != 0:
raise BackupError(f"rsync failed for: {str(src)} to {str(dest)}")

Expand Down Expand Up @@ -214,9 +225,9 @@ def delete_old_backups(self):
for folder in to_delete:
success = self.run_cmd(["rm", "-rf", folder])[0]
if success:
self.logger.info(f"Deleted old backup: {folder}")
LOGGER.info("Deleted old backup: %s", folder)
else:
self.logger.warning("Warning: couldn't delete old backup: %s", folder)
LOGGER.warning("Warning: couldn't delete old backup: %s", folder)

def backup_auto_folders(self, backup_func: Callable) -> None:
"""Create a backup, managing live and previous backup folders automatically
Expand All @@ -237,11 +248,11 @@ def backup_auto_folders(self, backup_func: Callable) -> None:
last_folder = self.get_last_backup_folder()

if last_folder:
self.logger.info(
f"Last backup is '{str(last_folder)}', using it for rsync --link-dest."
LOGGER.info(
"Last backup is '%s', using it for rsync --link-dest.", str(last_folder)
)
else:
self.logger.info("Couldn't find a previous backup to increment from.")
LOGGER.info("Couldn't find a previous backup to increment from.")

backup_func(
live_folder,
Expand All @@ -263,20 +274,23 @@ def backup_auto_folders(self, backup_func: Callable) -> None:
f"Failed to move '{str(live_folder)}' to '{str(self.path / folder_name)}'"
)

self.logger.info(
f"Backup moved from '{str(live_folder)}' to '{str(self.path / folder_name)}'."
LOGGER.info(
"Backup moved from '%s' to '%s'.",
str(live_folder),
str(self.path / folder_name),
)

symlink_name = "last-backup"
success = self.run_cmd(
["ln", "-sfn", str(folder_name), str(self.path / symlink_name)]
)[0]
if not success:
self.logger.warning(
f"Couldn't create symlink '{symlink_name}'. Perhaps the filesystem doesn't support it."
LOGGER.warning(
"Couldn't create symlink '%s'. Perhaps the filesystem doesn't support it.",
symlink_name,
)
else:
self.logger.info(f"Added symlink '{symlink_name}' to '{folder_name}'.")
LOGGER.info("Added symlink '%s' to '%s'.", symlink_name, folder_name)

self.delete_old_backups()

Expand Down Expand Up @@ -321,7 +335,7 @@ def backup_container(
prev_backup_loose = prev_backup / loose_path_rel if prev_backup else None

manager.call_rsync(loose_path, path, link_dest=prev_backup_loose)
manager.logger.info(f"Transferred {str(loose_path)} to {str(path)}")
LOGGER.info("Transferred %s to %s", str(loose_path), str(path))

# step 2: back up sqlite db

Expand All @@ -331,18 +345,18 @@ def backup_container(
_sqlite_backup(sqlite_path, sqlite_temp_loc)

if sqlite_temp_loc.is_file():
manager.logger.info(f"Dumped the SQLite database to {str(sqlite_temp_loc)}")
LOGGER.info("Dumped the SQLite database to %s", str(sqlite_temp_loc))
else:
raise BackupError(f"'{str(sqlite_temp_loc)}' failed to be created.")

# step 3: transfer the SQLITE database file
manager.call_rsync(sqlite_temp_loc, path, link_dest=prev_backup)
manager.logger.info(f"Transferred SQLite database to {str(path)}")
LOGGER.info("Transferred SQLite database to %s", str(path))

# step 4: transfer the packed files
packs_path_rel = packs_path.relative_to(container_root_path)
manager.call_rsync(packs_path, path, link_dest=prev_backup)
manager.logger.info(f"Transferred {str(packs_path)} to {str(path)}")
LOGGER.info("Transferred %s to %s", str(packs_path), str(path))

# step 5: transfer anything else in the container folder
manager.call_rsync(
Expand Down
10 changes: 6 additions & 4 deletions disk_objectstore/cli.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -233,18 +233,20 @@ def backup(
non-UNIX environments.
"""

logging.basicConfig(format="%(levelname)s:%(message)s")
logger = logging.getLogger("disk_objectstore.backup_utils")

if verbosity == "silent":
backup_utils.backup_logger.setLevel(logging.ERROR)
logger.setLevel(logging.ERROR)
elif verbosity == "info":
backup_utils.backup_logger.setLevel(logging.INFO)
logger.setLevel(logging.INFO)
elif verbosity == "debug":
backup_utils.backup_logger.setLevel(logging.DEBUG)
logger.setLevel(logging.DEBUG)

with dostore.container as container:
try:
backup_manager = backup_utils.BackupManager(
dest,
backup_utils.backup_logger,
keep=keep,
rsync_exe=rsync_exe,
)
Expand Down
24 changes: 12 additions & 12 deletions tests/test_backup.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,43 +25,43 @@ def test_invalid_destination():
"""Test invalid destination with two colons."""
dest = "localhost:/tmp/test:"
with pytest.raises(ValueError, match="Invalid destination format"):
BackupManager(dest, backup_utils.backup_logger)
BackupManager(dest)


def test_inaccessible_remote():
"""Test a remote destination of random characters that will not be accessible."""
dest = f"_{_random_string()}:/tmp/test"
with pytest.raises(BackupError, match="is not accessible"):
BackupManager(dest, backup_utils.backup_logger)
BackupManager(dest)


def test_negative_keep():
"""Test a negative keep value."""
dest = "/tmp/test"
with pytest.raises(ValueError, match="keep variable can't be negative"):
BackupManager(dest, backup_utils.backup_logger, keep=-1)
BackupManager(dest, keep=-1)


def test_inaccessible_exe():
"""Test case where rsync is not accessible."""
dest = "/tmp/test"
rsync_exe = f"_{_random_string()}"
with pytest.raises(ValueError, match=f"{rsync_exe} not accessible."):
BackupManager(dest, backup_utils.backup_logger, rsync_exe=rsync_exe)
BackupManager(dest, rsync_exe=rsync_exe)


def test_inaccessible_path():
"""Test case where path is not accessible."""
dest = f"/_{_random_string()}" # I assume there will be a permission error for this path
with pytest.raises(ValueError, match=f"Couldn't access/create '{dest}'"):
BackupManager(dest, backup_utils.backup_logger)
BackupManager(dest)


def test_rsync_failure():
"""Test case where rsync fails."""
dest = "/tmp/test"
with pytest.raises(BackupError, match="rsync failed"):
manager = BackupManager(dest, backup_utils.backup_logger)
manager = BackupManager(dest)
# pick a src that doesn't exists
manager.call_rsync(Path(f"/_{_random_string()}"), Path(dest))

Expand All @@ -71,7 +71,7 @@ def test_rsync_dest_trailing_slash(temp_dir):
dest1 = Path(temp_dir) / "dest1"
dest2 = Path(temp_dir) / "dest2"
# manager will create dest1 folder
manager = BackupManager(str(dest1), backup_utils.backup_logger)
manager = BackupManager(str(dest1))
# dest_trailing_slash=True will create dest2
manager.call_rsync(dest1, dest2, dest_trailing_slash=True)
assert dest2.exists()
Expand All @@ -81,7 +81,7 @@ def test_existing_backups_failure():
"""Test case where existing backups fail to be determined."""
dest = "/tmp/test"
with pytest.raises(BackupError, match="Existing backups determination failed"):
manager = BackupManager(dest, backup_utils.backup_logger)
manager = BackupManager(dest)
# override the path to something that will fail
manager.path = f"/_{_random_string()}"
manager.get_existing_backup_folders()
Expand All @@ -108,7 +108,7 @@ def mock_sqlite_backup(src, dst): # pylint: disable=unused-argument

dest = Path(temp_dir) / "backup"
with pytest.raises(BackupError, match="'.*' failed to be created."):
manager = BackupManager(str(dest), backup_utils.backup_logger)
manager = BackupManager(str(dest))
manager.backup_auto_folders(
lambda path, prev: backup_utils.backup_container(
manager, temp_container, path, prev
Expand Down Expand Up @@ -145,7 +145,7 @@ def mock_run_cmd(self, args):

dest = Path(temp_dir) / "backup"
with pytest.raises(BackupError, match="Failed to move"):
manager = BackupManager(str(dest), backup_utils.backup_logger)
manager = BackupManager(str(dest))
manager.backup_auto_folders(
lambda path, prev: backup_utils.backup_container(
manager, temp_container, path, prev
Expand Down Expand Up @@ -181,7 +181,7 @@ def mock_run_cmd(self, args):
temp_container.add_object(f"test-{idx}".encode())

dest = Path(temp_dir) / "backup"
manager = BackupManager(str(dest), backup_utils.backup_logger)
manager = BackupManager(str(dest))
manager.backup_auto_folders(
lambda path, prev: backup_utils.backup_container(
manager, temp_container, path, prev
Expand Down Expand Up @@ -219,7 +219,7 @@ def mock_run_cmd(self, args):
temp_container.add_object(f"test-{idx}".encode())

dest = Path(temp_dir) / "backup"
manager = BackupManager(str(dest), backup_utils.backup_logger, keep=0)
manager = BackupManager(str(dest), keep=0)
for _ in range(2):
manager.backup_auto_folders(
lambda path, prev: backup_utils.backup_container(
Expand Down

0 comments on commit aaf77eb

Please sign in to comment.