From 1ea8f7a1f0fd9a4a95cdcf6ecb6c7c5a12a0469c Mon Sep 17 00:00:00 2001
From: Marc Koch <marc.koch@propeace.de>
Date: Fri, 21 Mar 2025 17:49:01 +0100
Subject: [PATCH] =?UTF-8?q?=F0=9F=94=8A=20improve=20logging=20messages?=
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

---
 src/adgroupsync/__main__.py |  2 +-
 src/adgroupsync/models.py   | 22 ++++++++++++++--------
 2 files changed, 15 insertions(+), 9 deletions(-)

diff --git a/src/adgroupsync/__main__.py b/src/adgroupsync/__main__.py
index 5dbd796..cfa94dc 100644
--- a/src/adgroupsync/__main__.py
+++ b/src/adgroupsync/__main__.py
@@ -280,7 +280,7 @@ def main():
 
             # Log the current run timestamp
             started_at = recent_run.started_at.strftime('%Y-%m-%d %H:%M:%S %Z')
-            logger.info(f"Setting previous run to: {started_at}")
+            logger.info(f"Setting recent run to: {started_at}")
 
     # Exit if the script is already running
     except ScriptAlreadyRunningError:
diff --git a/src/adgroupsync/models.py b/src/adgroupsync/models.py
index 43751a2..3d9e686 100644
--- a/src/adgroupsync/models.py
+++ b/src/adgroupsync/models.py
@@ -65,7 +65,7 @@ class RecentRun:
 
         # Update the values
         if recent_run:
-            toml['recent_run'] = recent_run
+            toml['recent-run'] = recent_run
         if is_running is not None:
             toml['is-running'] = is_running
 
@@ -94,7 +94,7 @@ class RecentRun:
                 .astimezone(self._timezone)
         else:
             raise ValueError(
-                f"Invalid recent_run '{recent_run}' in {self._file_path}.")
+                f"Invalid recent-run '{recent_run}' in {self._file_path}.")
 
     @property
     def datetime(self) -> dt | None:
@@ -167,7 +167,7 @@ class RecentRun:
 
         # If no exception occurred, set the recent run time to the current time
         if exc_type is None:
-            self.datetime = recent_run = self._started_at
+            recent_run = self._started_at
 
         self._sync_file(recent_run=recent_run, is_running=self._is_running)
 
@@ -316,22 +316,27 @@ class CiviCrm:
         :return: Number of failed requests
         """
         error_count = 0
+        self._error_bag = []
         failed_requests = {'groups': deque(), 'users': deque()}
 
         for name, requests in self._requests.items():
-            logger.info(f"Sending {len(requests)} {name}")
+            counter = 0
+            number_of_requests = len(requests)
+            logger.info(f"Sending {number_of_requests} {name}")
 
             while requests:
+                counter += 1
                 request = requests.popleft()
 
                 try:
                     result = api.api3(**request)
-                    logger.info(f"Result: {result}", extra={'result': result})
+                    logger.info(f"Result {counter}/{number_of_requests}: "
+                                f"{result}", extra={'result': result})
                     if result.get('is_error', False):
                         raise Exception(result.get('error_message'))
 
                 except Exception as e:
-                    self._error_bag.append({
+                    error = {
                         'name': name,
                         'request': {
                             'entity': request['entity'],
@@ -342,9 +347,10 @@ class CiviCrm:
                             'method': str(request['method']),
                         },
                         'error': str(e),
-                    })
+                    }
+                    self._error_bag.append(error)
                     logger.exception(f"Error sending request: {e}",
-                                     extra=request)
+                                     extra={'error': error})
                     failed_requests[name].append(request)
                     error_count += 1