rgw: when exclusive lock fails due existing lock, log add'l info

This is being added to better understand lock-contention issues in
running systems. Here are two sample log output lines:

  2019-02-04 14:22:31.228 7f06abb59700 20 <cls>
  /somedir/ceph/src/cls/lock/cls_lock.cc:221: could not exclusive-lock
  object, already locked by [{name:client.4139,
  addr:v1:127.0.0.1:0/2034495868, exp:2019-02-04 14:24:31.0.22272s}]

  2019-02-04 14:22:37.219 7f06abb59700 20 <cls>
  /somedir/ceph/src/cls/lock/cls_lock.cc:221: could not exclusive-lock
  object, already locked by [{name:client.4147,
  addr:v1:127.0.0.1:0/141966515, exp:never}]

Fixes: http://tracker.ceph.com/issues/38171
Signed-off-by: J. Eric Ivancich <ivancich@redhat.com>
(cherry picked from commit af5c1ed2c0d4687417ce14d342335fa97718f46c)

diff --git a/src/cls/lock/cls_lock.cc b/src/cls/lock/cls_lock.cc
index 1dab0dd72aca1ab6ab5e6eadceb6308cd45e65eb..3f4b84e395a56e98ec3db4b9f9df77dc294a2ae5 100644 (file)
--- a/src/cls/lock/cls_lock.cc
+++ b/src/cls/lock/cls_lock.cc
@@ -10,6 +10,7 @@
 
 #include <errno.h>
 #include <map>
+#include <sstream>
 
 #include "include/types.h"
 #include "include/utime.h"
@@ -197,7 +198,27 @@ static int lock_obj(cls_method_context_t hctx,
 
   if (!lockers.empty()) {
     if (exclusive) {
-      CLS_LOG(20, "could not exclusive-lock object, already locked");
+      std::stringstream locker_list;
+      bool first = true;
+      // there could be multiple lockers if they are all shared
+      for (const auto& l : lockers) {
+       if (first) {
+         first = false;
+       } else {
+         locker_list << ", ";
+       }
+       locker_list << "{name:" << l.first.locker <<
+         ", addr:" << l.second.addr <<
+         ", exp:";
+       const auto& exp = l.second.expiration;
+       if (exp.is_zero()) {
+         locker_list << "never}";
+       } else {
+         locker_list << exp.to_real_time() << "}";
+       }
+      }
+      CLS_LOG(20, "could not exclusive-lock object, already locked by [%s]",
+             locker_list.str().c_str());
       return -EBUSY;
     }
 

diff --git a/src/test/cls_lock/test_cls_lock.cc b/src/test/cls_lock/test_cls_lock.cc
index 37d10a19cbcf4f0b5914e568422d76e7d62c7c03..8c67d6aa5896453308f492f18b0d848d0cff10e4 100644 (file)
--- a/src/test/cls_lock/test_cls_lock.cc
+++ b/src/test/cls_lock/test_cls_lock.cc
@@ -85,6 +85,9 @@ TEST(ClsLock, TestMultiLocking) {
   ASSERT_EQ(0, ioctx.write(oid, bl, bl.length(), 0));
 
   Lock l(lock_name);
+  // we set the duration, so the log output contains a locker with a
+  // non-zero expiration time
+  l.set_duration(utime_t(120, 0));
 
   /* test lock object */