From 9800d58cb3e7315a1941629c3dd961cfa3b63f25 Mon Sep 17 00:00:00 2001
From: Gorka Eguileor <geguileo@redhat.com>
Date: Wed, 22 Jun 2022 18:47:53 +0200
Subject: Log when waiting to acquire lock

We currently have no log entry when we start trying to acquire a lock.

In general this is ok, but there are cases where it can be problematic,
for example if we have a deadlock situation or if a lock takes a very
long time to be acquired.

In those scenarios looking at the logs we would see the operation
proceed normally and suddenly go completely silent without knowing that
it's waiting for a lock to be freed.

This patch adds a debug log message right before trying to acquire the
lock so we can detect those situations.

Change-Id: I1354dfb98b0927ae167802ecc4ab1d34f6b4d720
---
 oslo_concurrency/lockutils.py                               | 8 ++++++--
 releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml | 5 +++++
 2 files changed, 11 insertions(+), 2 deletions(-)
 create mode 100644 releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml

diff --git a/oslo_concurrency/lockutils.py b/oslo_concurrency/lockutils.py
index c75d3a3..4b085c4 100644
--- a/oslo_concurrency/lockutils.py
+++ b/oslo_concurrency/lockutils.py
@@ -289,6 +289,8 @@ def lock(name, lock_file_prefix=None, external=False, lock_path=None,
     else:
         int_lock = internal_lock(name, semaphores=semaphores,
                                  blocking=blocking)
+    if do_log:
+        LOG.debug('Acquiring lock "%s"', name)
     with int_lock:
         if do_log:
             LOG.debug('Acquired lock "%(lock)s"', {'lock': name})
@@ -378,7 +380,9 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None,
             t1 = timeutils.now()
             t2 = None
             gotten = True
+            f_name = reflection.get_callable_name(f)
             try:
+                LOG.debug('Acquiring lock "%s" by "%s"', name, f_name)
                 with lock(name, lock_file_prefix, external, lock_path,
                           do_log=False, semaphores=semaphores, delay=delay,
                           fair=fair, blocking=blocking):
@@ -386,7 +390,7 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None,
                     LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: '
                               'waited %(wait_secs)0.3fs',
                               {'name': name,
-                               'function': reflection.get_callable_name(f),
+                               'function': f_name,
                                'wait_secs': (t2 - t1)})
                     return f(*args, **kwargs)
             except AcquireLockFailedException:
@@ -401,7 +405,7 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None,
                           ' held %(held_secs)s',
                           {'name': name,
                            'gotten': 'released' if gotten else 'unacquired',
-                           'function': reflection.get_callable_name(f),
+                           'function': f_name,
                            'held_secs': held_secs})
         return inner
 
diff --git a/releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml b/releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml
new file mode 100644
index 0000000..12fd7e6
--- /dev/null
+++ b/releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml
@@ -0,0 +1,5 @@
+---
+features:
+  - |
+    Log before trying to acquire a lock to help detect deadlocks and long waits
+    to acquire locks.
-- 
cgit v1.2.1