From cad742d9525cb4d0a630d4ca4c15037ea29e811e Mon Sep 17 00:00:00 2001 From: Davanum Srinivas Date: Thu, 11 Sep 2014 19:00:54 -0400 Subject: [PATCH] Clarify logging in lockutils The old logging statements in lockutils made for some confusing log entries where it would appear a given lock was acquired multiple times by different threads at the same time. See referenced bug for details. In order to alleviate that confusion, this change does a few things: 1) Adds an explicit "acquired" message inside the lock so it is clear when the lock was actually acquired. 2) Moves the release message inside the semaphore so there's no chance of it being logged out of order. 3) Removes the "Got semaphore" message and splits it into two separate messages depending on whether the semaphore was found in the weakref dictionary. Making it clear which code path was followed should help with future debugging. This is the Nova port of oslo-incubator change If863c9d3896bc786f3c9c46196ebb0766e57d863 Change-Id: I530befb42a963a40e7d5bf8d4d81fc097e1cb309 Partial-Bug: #1367941 --- nova/openstack/common/lockutils.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/nova/openstack/common/lockutils.py b/nova/openstack/common/lockutils.py index 1d022d54c4..29827dd532 100644 --- a/nova/openstack/common/lockutils.py +++ b/nova/openstack/common/lockutils.py @@ -199,11 +199,12 @@ def internal_lock(name): with _semaphores_lock: try: sem = _semaphores[name] + LOG.debug('Using existing semaphore "%s"', name) except KeyError: sem = threading.Semaphore() _semaphores[name] = sem + LOG.debug('Created new semaphore "%s"', name) - LOG.debug('Got semaphore "%(lock)s"', {'lock': name}) return sem @@ -225,13 +226,14 @@ def lock(name, lock_file_prefix=None, external=False, lock_path=None): """ int_lock = internal_lock(name) with int_lock: + LOG.debug('Acquired semaphore "%(lock)s"', {'lock': name}) if external and not CONF.disable_process_locking: ext_lock = external_lock(name, lock_file_prefix, lock_path) with ext_lock: yield ext_lock else: yield int_lock - LOG.debug('Released semaphore "%(lock)s"', {'lock': name}) + LOG.debug('Releasing semaphore "%(lock)s"', {'lock': name}) def synchronized(name, lock_file_prefix=None, external=False, lock_path=None):