From 11653785ea4c9486fb787775507b99bf2e5437ae Mon Sep 17 00:00:00 2001
From: Dan Helfman <witten@torsion.org>
Date: Mon, 19 Jun 2023 22:05:40 -0700
Subject: [PATCH] Add debugging instrumentation to help diagnose #713.

---
 borgmatic/borg/check.py | 23 ++++++++++++++++++++---
 1 file changed, 20 insertions(+), 3 deletions(-)

diff --git a/borgmatic/borg/check.py b/borgmatic/borg/check.py
index 0c417aca..2b5899f8 100644
--- a/borgmatic/borg/check.py
+++ b/borgmatic/borg/check.py
@@ -8,7 +8,7 @@ import os
 import pathlib
 
 from borgmatic.borg import environment, extract, feature, flags, rinfo, state
-from borgmatic.execute import DO_NOT_CAPTURE, execute_command
+from borgmatic.execute import DO_NOT_CAPTURE, execute_command, execute_command_and_capture_output
 
 DEFAULT_CHECKS = (
     {'name': 'repository', 'frequency': '1 month'},
@@ -336,23 +336,40 @@ def upgrade_check_times(location_config, borg_repository_id):
 
       ~/.borgmatic/checks/1234567890/archives/all
     '''
+    logger.debug(f"#713: upgrade_check_times(location_config={location_config}, borg_repository_id='{borg_repository_id}')")
+
     for check_type in ('archives', 'data'):
+        logger.debug(f"#713: check_type = '{check_type}'")
         new_path = make_check_time_path(location_config, borg_repository_id, check_type, 'all')
+        logger.debug(f"#713: new_path = '{new_path}'")
         old_path = os.path.dirname(new_path)
+        logger.debug(f"#713: old_path = '{old_path}'")
         temporary_path = f'{old_path}.temp'
+        logger.debug(f"#713: temporary_path = '{temporary_path}'")
+
+        logger.debug(f"\n#713: file listing:")
+        logger.debug(execute_command_and_capture_output(['ls', '-alR', f'{os.path.dirname(old_path)}'], capture_stderr=True, shell=True))
+        logger.debug(f"#713: os.path.isfile(old_path) = {os.path.isfile(old_path)}")
+        logger.debug(f"#713: os.path.isfile(temporary_path) = {os.path.isfile(temporary_path)}")
 
         if not os.path.isfile(old_path) and not os.path.isfile(temporary_path):
+            logger.debug("#713: returning early")
             return
 
         logger.debug(f'Upgrading archives check time from {old_path} to {new_path}')
 
         try:
             os.rename(old_path, temporary_path)
-        except FileNotFoundError:
-            pass
+        except FileNotFoundError as error:
+            logger.debug(f"#713: FileNotFoundError: {error}")
 
+        logger.debug("#713: mkdir old path")
         os.mkdir(old_path)
+        logger.debug("#713: rename temporary path to new path")
         os.rename(temporary_path, new_path)
+        logger.debug("#713: end of loop")
+
+    logger.debug("#713: returning")
 
 
 def check_archives(