Keep log file of failed downloads + add exceptions to the log (#182)

* copy log file to the temp dir before removing project directory if
download fails

* address review

* codestyle

* add active waiting test

* log errors when project download fails (refs #156)

* write traceback to the log
check that traceback present in the log in test

* formatting

* address review

Author: alexbruy

mergin/client_pull.py

@@ -16,6 +16,7 @@
 import shutil
 import tempfile
 import typing
+import traceback
 
 import concurrent.futures
 
@@ -55,6 +56,7 @@ def __init__(
         self.mp = mp  # MerginProject instance
         self.is_cancelled = False
         self.project_info = project_info  # parsed JSON with project info returned from the server
+        self.failure_log_file = None  # log file, copied from the project directory if download fails
 
     def dump(self):
         print("--- JOB ---", self.total_size, "bytes")
@@ -99,12 +101,25 @@ def _cleanup_failed_download(directory, mergin_project=None):
     If a download job fails, there will be the newly created directory left behind with some
     temporary files in it. We want to remove it because a new download would fail because
     the directory already exists.
+
+    Returns path to the client log file or None if log file does not exist.
     """
     # First try to get the Mergin Maps project logger and remove its handlers to allow the log file deletion
     if mergin_project is not None:
         mergin_project.remove_logging_handler()
 
+    # keep log file as it might contain useful debug info
+    log_file = os.path.join(directory, ".mergin", "client-log.txt")
+    dest_path = None
+
+    if os.path.exists(log_file):
+        tmp_file = tempfile.NamedTemporaryFile(prefix="mergin-", suffix=".txt", delete=False)
+        tmp_file.close()
+        dest_path = tmp_file.name
+        shutil.copyfile(log_file, dest_path)
+
     shutil.rmtree(directory)
+    return dest_path
 
 
 def download_project_async(mc, project_path, directory, project_version=None):
@@ -184,7 +199,11 @@ def download_project_is_running(job):
     """
     for future in job.futures:
         if future.done() and future.exception() is not None:
-            _cleanup_failed_download(job.directory, job.mp)
+            job.mp.log.error(
+                "Error while downloading project: " + "".join(traceback.format_exception(future.exception()))
+            )
+            job.mp.log.info("--- download aborted")
+            job.failure_log_file = _cleanup_failed_download(job.directory, job.mp)
             raise future.exception()
         if future.running():
             return True
@@ -206,7 +225,11 @@ def download_project_finalize(job):
     # make sure any exceptions from threads are not lost
     for future in job.futures:
         if future.exception() is not None:
-            _cleanup_failed_download(job.directory, job.mp)
+            job.mp.log.error(
+                "Error while downloading project: " + "".join(traceback.format_exception(future.exception()))
+            )
+            job.mp.log.info("--- download aborted")
+            job.failure_log_file = _cleanup_failed_download(job.directory, job.mp)
             raise future.exception()
 
     job.mp.log.info("--- download finished")

mergin/test/test_client.py

@@ -9,10 +9,18 @@
 import pytz
 import sqlite3
 import glob
+import time
 
 from .. import InvalidProject
 from ..client import MerginClient, ClientError, MerginProject, LoginError, decode_token_data, TokenError, ServerType
 from ..client_push import push_project_async, push_project_cancel
+from ..client_pull import (
+    download_project_async,
+    download_project_wait,
+    download_project_finalize,
+    download_project_is_running,
+    download_project_cancel,
+)
 from ..utils import (
     generate_checksum,
     get_versions_with_file_changes,
@@ -2214,3 +2222,44 @@ def test_download_files(mc: MerginClient):
 
     with pytest.raises(ClientError, match=f"No \\[non_existing\\.file\\] exists at version v3"):
         mc.download_files(project_dir, [f_updated, "non_existing.file"], version="v3")
+
+
+def test_download_failure(mc):
+    test_project = "test_download_failure"
+    project = API_USER + "/" + test_project
+    project_dir = os.path.join(TMP_DIR, test_project)
+    download_dir = os.path.join(TMP_DIR, "download", test_project)
+
+    cleanup(mc, project, [project_dir, download_dir])
+    # prepare local project
+    shutil.copytree(TEST_DATA_DIR, project_dir)
+
+    # create remote project
+    mc.create_project_and_push(test_project, directory=project_dir)
+
+    # download project async
+    with pytest.raises(IsADirectoryError):
+        job = download_project_async(mc, project, download_dir)
+        os.makedirs(os.path.join(download_dir, "base.gpkg.0"))
+        download_project_wait(job)
+        download_project_finalize(job)
+
+    assert job.failure_log_file is not None
+    with open(job.failure_log_file, "r", encoding="utf-8") as f:
+        content = f.read()
+        assert "Traceback" in content
+
+    # active waiting
+    remove_folders([download_dir])
+    job = download_project_async(mc, project, download_dir)
+    os.makedirs(os.path.join(download_dir, "base.gpkg.0"))
+    with pytest.raises(IsADirectoryError):
+        while True:
+            assert download_project_is_running(job)
+
+    download_project_cancel(job)  # to clean up things
+
+    assert job.failure_log_file is not None
+    with open(job.failure_log_file, "r", encoding="utf-8") as f:
+        content = f.read()
+        assert "Traceback" in content