From 194fc16707d0acf870871bd9e6b2d886b8330271 Mon Sep 17 00:00:00 2001
From: Scott Gasch <scott@gasch.org>
Date: Wed, 19 Oct 2022 14:23:39 -0700
Subject: [PATCH] Make sure lockfile always sets locktime.  Use locktime in
 cron.py to optionally create a record of lockfile contention for future
 analysis.

---
 examples/cron/cron.py         | 24 ++++++++++++++++++++++--
 src/pyutils/files/lockfile.py |  4 ++--
 2 files changed, 24 insertions(+), 4 deletions(-)

diff --git a/examples/cron/cron.py b/examples/cron/cron.py
index 2a06770..958aa61 100755
--- a/examples/cron/cron.py
+++ b/examples/cron/cron.py
@@ -26,6 +26,12 @@ cfg.add_argument(
     metavar='LOCKFILE_PATH',
     help='Path to the lockfile to use to ensure that two instances of a command do not execute contemporaneously.',
 )
+cfg.add_argument(
+    '--lockfile_audit_record',
+    default=None,
+    metavar='LOCKFILE_AUDIT_RECORD_FILENAME',
+    help='Path to a record of when the logfile was held/released and for what reason',
+)
 cfg.add_argument(
     '--timeout',
     type=str,
@@ -147,8 +153,22 @@ def main() -> int:
                 do_signal_cleanup=True,
                 override_command=' '.join(config.config['command']),
                 expiration_timestamp=lockfile_expiration,
-            ):
-                return run_command(timeout, timestamp_file)
+            ) as lf:
+                record = config.config['lockfile_audit_record']
+                cmd = ' '.join(config.config['command'])
+                if record:
+                    with open(record, 'a') as wf:
+                        print(
+                            f'{lockfile_path}, ACQUIRE, {lf.locktime}, {cmd}', file=wf
+                        )
+                retval = run_command(timeout, timestamp_file)
+                if record:
+                    with open(record, 'a') as wf:
+                        print(
+                            f'{lockfile_path}, RELEASE, {datetime.datetime.now().timestamp()}, {cmd}',
+                            file=wf,
+                        )
+                return retval
         except lockfile.LockFileException as e:
             logger.exception(e)
             msg = f'Failed to acquire {lockfile_path}, giving up.'
diff --git a/src/pyutils/files/lockfile.py b/src/pyutils/files/lockfile.py
index 0febca6..c7b4841 100644
--- a/src/pyutils/files/lockfile.py
+++ b/src/pyutils/files/lockfile.py
@@ -91,7 +91,7 @@ class LockFile(contextlib.AbstractContextManager):
         """
         self.is_locked: bool = False
         self.lockfile: str = lockfile_path
-        self.locktime: Optional[int] = None
+        self.locktime: Optional[float] = None
         self.override_command: Optional[str] = override_command
         if do_signal_cleanup:
             signal.signal(signal.SIGINT, self._signal)
@@ -122,6 +122,7 @@ class LockFile(contextlib.AbstractContextManager):
                 contents = self._get_lockfile_contents()
                 logger.debug(contents)
                 f.write(contents)
+            self.locktime = datetime.datetime.now().timestamp()
             logger.debug('Success; I own %s.', self.lockfile)
             self.is_locked = True
             return True
@@ -174,7 +175,6 @@ class LockFile(contextlib.AbstractContextManager):
 
     def __enter__(self):
         if self.acquire_with_retries():
-            self.locktime = datetime.datetime.now().timestamp()
             return self
         msg = f"Couldn't acquire {self.lockfile}; giving up."
         logger.warning(msg)
-- 
2.46.0