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

@@ -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
 

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.