helix-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From h...@apache.org
Subject [helix] branch master updated: Enhance logging for CallbackHandler and Zkclient (#1355)
Date Wed, 23 Sep 2020 21:46:19 GMT
This is an automated email from the ASF dual-hosted git repository.

hzlu pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/helix.git


The following commit(s) were added to refs/heads/master by this push:
     new 7028bf3  Enhance logging for CallbackHandler and Zkclient (#1355)
7028bf3 is described below

commit 7028bf36a45b2c03d92193ef69d74324171db73d
Author: kaisun2000 <52840222+kaisun2000@users.noreply.github.com>
AuthorDate: Wed Sep 23 14:46:09 2020 -0700

    Enhance logging for CallbackHandler and Zkclient (#1355)
    
    This commit adds a unique id to each method's logging to help the
    correlation and track the callback handler and zkClient's life cycle.
---
 .../apache/helix/manager/zk/CallbackHandler.java   |  93 +++++++++---------
 .../apache/helix/zookeeper/zkclient/ZkClient.java  | 107 +++++++++++----------
 2 files changed, 105 insertions(+), 95 deletions(-)

diff --git a/helix-core/src/main/java/org/apache/helix/manager/zk/CallbackHandler.java b/helix-core/src/main/java/org/apache/helix/manager/zk/CallbackHandler.java
index 5ec7e91..2e8726d 100644
--- a/helix-core/src/main/java/org/apache/helix/manager/zk/CallbackHandler.java
+++ b/helix-core/src/main/java/org/apache/helix/manager/zk/CallbackHandler.java
@@ -105,7 +105,9 @@ import static org.apache.helix.HelixConstants.ChangeType.TARGET_EXTERNAL_VIEW;
 @PreFetchChangedData(enabled = false)
 public class CallbackHandler implements IZkChildListener, IZkDataListener {
   private static Logger logger = LoggerFactory.getLogger(CallbackHandler.class);
+  private static final AtomicLong CALLBACK_HANDLER_UID = new AtomicLong();
 
+  private final long _uid;
   /**
    * define the next possible notification types
    */
@@ -145,8 +147,8 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
         "Singleton", "CallbackHandler-AsycSubscribe") {
       @Override
       protected void handleEvent(SubscribeChangeEvent event) {
-        logger.info("Resubscribe change listener to path: {}, for listener: {}, watchChild:
{}",
-            event.path, event.listener, event.watchChild);
+        logger.info("CallbackHandler {}, resubscribe change listener to path: {}, for listener:
{}, watchChild: {}",
+            event.handler._uid, event.path, event.listener, event.watchChild);
         try {
           if (event.handler.isReady()) {
             event.handler.subscribeForChanges(event.callbackType, event.path, event.watchChild);
@@ -225,6 +227,9 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
           + monitor.getChangeType().name());
     }
 
+    _uid = CALLBACK_HANDLER_UID.getAndIncrement();
+
+
     _manager = manager;
     _accessor = manager.getHelixDataAccessor();
     _zkClient = client;
@@ -354,10 +359,10 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
     // async mode only applicable to CALLBACK from ZK, During INIT and FINALIZE invoke the
     // callback's immediately.
     if (_batchModeEnabled && changeContext.getType() == NotificationContext.Type.CALLBACK)
{
-      logger.debug("Enqueuing callback");
+      logger.debug("Callbackhandler {}, Enqueuing callback", _uid );
       if (!isReady()) {
-        logger.info("CallbackHandler is not ready, ignore change callback from path: {},
for "
-            + "listener: {}", _path, _listener);
+        logger.info("CallbackHandler {} is not ready, ignore change callback from path: {},
for "
+            + "listener: {}", _uid, _path, _listener);
       } else {
         synchronized (this) {
           if (_batchCallbackProcessor != null) {
@@ -385,13 +390,13 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
     synchronized (_manager) {
       if (logger.isInfoEnabled()) {
         logger
-            .info("{} START:INVOKE {} listener: {} type: {}", Thread.currentThread().getId(),
_path,
-                _listener, type);
+            .info("{} START: CallbackHandler {}, INVOKE {} listener: {} type: {}", Thread.currentThread().getId(),
+                _uid, _path, _listener, type);
       }
 
       if (!_expectTypes.contains(type)) {
-        logger.warn("Callback handler received event in wrong order. Listener: {}, path:
{}, "
-            + "expected types: {}, but was {}", _listener, _path, _expectTypes, type);
+        logger.warn("Callback handler {} received event in wrong order. Listener: {}, path:
{}, "
+            + "expected types: {}, but was {}", _uid, _listener, _path, _expectTypes, type);
         return;
 
       }
@@ -511,13 +516,13 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
         ControllerChangeListener controllerChangelistener = (ControllerChangeListener) _listener;
         controllerChangelistener.onControllerChange(changeContext);
       } else {
-        logger.warn("Unknown change type: {}", _changeType);
+        logger.warn("Callbackhandler {}, Unknown change type: {}", _uid, _changeType);
       }
 
       long end = System.currentTimeMillis();
       if (logger.isInfoEnabled()) {
-        logger.info("{} END:INVOKE {} listener: {} type: {} Took: {}ms",
-            Thread.currentThread().getId(), _path, _listener, type, (end - start));
+        logger.info("{} END:INVOKE CallbackHandler {}, {} listener: {} type: {} Took: {}ms",
+            Thread.currentThread().getId(), _uid, _path, _listener, type, (end - start));
       }
       if (_monitor != null) {
         _monitor.increaseCallbackCounters(end - start);
@@ -537,8 +542,8 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
     if (callbackType == NotificationContext.Type.INIT
         || callbackType == NotificationContext.Type.CALLBACK) {
       if (logger.isDebugEnabled()) {
-        logger.debug("{} subscribes child-change. path: {} , listener: {}",
-            _manager.getInstanceName(), path, _listener );
+        logger.debug("CallbackHandler {}, {} subscribes child-change. path: {} , listener:
{}",
+            _uid, _manager.getInstanceName(), path, _listener );
       }
       // In the lifecycle of CallbackHandler, INIT is the first stage of registration of
watch.
       // For some usage case such as current state, the path can be created later. Thus we
would
@@ -549,14 +554,14 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
       // Note when path is removed, the CallbackHanler would remove itself from ZkHelixManager
too
       // to avoid leaking a CallbackHandler.
       ChildrenSubscribeResult childrenSubscribeResult = _zkClient.subscribeChildChanges(path,
this, callbackType != Type.INIT);
-      logger.debug("CallbackHandler {} subscribe data path {} result {}", this, path,
+      logger.debug("CallbackHandler {} subscribe data path {} result {}", _uid, path,
           childrenSubscribeResult.isInstalled());
       if (!childrenSubscribeResult.isInstalled()) {
-        logger.info("CallbackHandler {} subscribe data path {} failed!", this, path);
+        logger.info("CallbackHandler {} subscribe data path {} failed!", _uid, path);
       }
     } else if (callbackType == NotificationContext.Type.FINALIZE) {
-      logger.info("{} unsubscribe child-change. path: {}, listener: {}", _manager.getInstanceName(),
-          path, _listener);
+      logger.info("CallbackHandler{}, {} unsubscribe child-change. path: {}, listener: {}",
+          _uid ,_manager.getInstanceName(), path, _listener);
 
       _zkClient.unsubscribeChildChanges(path, this);
     }
@@ -566,17 +571,17 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
     if (callbackType == NotificationContext.Type.INIT
         || callbackType == NotificationContext.Type.CALLBACK) {
       if (logger.isDebugEnabled()) {
-        logger.debug("{} subscribe data-change. path: {}, listener: {}", _manager.getInstanceName(),
-            path, _listener);
+        logger.debug("CallbackHandler {}, {} subscribe data-change. path: {}, listener: {}",
+            _uid, _manager.getInstanceName(), path, _listener);
       }
       boolean subStatus = _zkClient.subscribeDataChanges(path, this, callbackType != Type.INIT);
-      logger.debug("CallbackHandler {} subscribe data path {} result {}", this, path, subStatus);
+      logger.debug("CallbackHandler {} subscribe data path {} result {}", _uid, path, subStatus);
       if (!subStatus) {
-        logger.info("CallbackHandler {} subscribe data path {} failed!", this, path);
+        logger.info("CallbackHandler {} subscribe data path {} failed!", _uid, path);
       }
     } else if (callbackType == NotificationContext.Type.FINALIZE) {
-      logger.info("{} unsubscribe data-change. path: {}, listener: {}",
-          _manager.getInstanceName(), path, _listener);
+      logger.info("CallbackHandler{}, {} unsubscribe data-change. path: {}, listener: {}",
+          _uid, _manager.getInstanceName(), path, _listener);
 
       _zkClient.unsubscribeDataChanges(path, this);
     }
@@ -592,22 +597,22 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
 
   private void subscribeForChanges(NotificationContext.Type callbackType, String path,
       boolean watchChild) {
-    logger.info("Subscribing changes listener to path: {}, type: {}, listener: {}", path,
-        callbackType, _listener);
+    logger.info("CallbackHandler {} Subscribing changes listener to path: {}, type: {}, listener:
{}",
+        _uid, path, callbackType, _listener);
 
     long start = System.currentTimeMillis();
     if (_eventTypes.contains(EventType.NodeDataChanged)
         || _eventTypes.contains(EventType.NodeCreated)
         || _eventTypes.contains(EventType.NodeDeleted)) {
-      logger.info("Subscribing data change listener to path: {}", path);
+      logger.info("CallbackHandler{} Subscribing data change listener to path: {}", _uid,
path);
       subscribeDataChange(path, callbackType);
     }
 
     if (_eventTypes.contains(EventType.NodeChildrenChanged)) {
-      logger.info("Subscribing child change listener to path: {}", path);
+      logger.info("CallbackHandler{}, Subscribing child change listener to path: {}", _uid,
path);
       subscribeChildChange(path, callbackType);
       if (watchChild) {
-        logger.info("Subscribing data change listener to all children for path: {}", path);
+        logger.info("CallbackHandler{}, Subscribing data change listener to all children
for path: {}", _uid, path);
 
         try {
           switch (_changeType) {
@@ -660,18 +665,18 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
           //TODO: avoid calling getChildren for path that does not exist
           if (_changeType == CUSTOMIZED_STATE_ROOT) {
             logger.warn(
-                "Failed to subscribe child/data change on path: {}, listener: {}. Instance
"
-                    + "does not support Customized State!", path, _listener);
+                "CallbackHandler {}, Failed to subscribe child/data change on path: {}, listener:
{}. Instance "
+                    + "does not support Customized State!", _uid, path, _listener);
           } else {
-            logger.warn("Failed to subscribe child/data change. path: {}, listener: {}",
path,
-                _listener, e);
+            logger.warn("CallbackHandler {}, Failed to subscribe child/data change. path:
{}, listener: {}",
+                _uid, path, _listener, e);
           }
         }
       }
     }
 
     long end = System.currentTimeMillis();
-    logger.info("Subscribing to path: {} took: {}", path, (end - start));
+    logger.info("CallbackHandler{}, Subscribing to path: {} took: {}", _uid, path, (end -
start));
   }
 
   public EventType[] getEventTypes() {
@@ -683,7 +688,7 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
    * exists
    */
   public void init() {
-    logger.info("initializing CallbackHandler: {}, content: {} ", this.toString(), getContent());
+    logger.info("initializing CallbackHandler: {}, content: {} ", _uid, getContent());
 
     if (_batchModeEnabled) {
       synchronized (this) {
@@ -712,7 +717,7 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
   @Override
   public void handleDataChange(String dataPath, Object data) {
     if (logger.isDebugEnabled()) {
-      logger.debug("Data change callback: paths changed: {}", dataPath);
+      logger.debug("Data change callbackhandler {}: paths changed: {}", _uid, dataPath);
     }
 
     try {
@@ -734,21 +739,20 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
   @Override
   public void handleDataDeleted(String dataPath) {
     if (logger.isDebugEnabled()) {
-      logger.debug("Data change callback: path deleted: {}", dataPath);
+      logger.debug("Data change callbackhandler {}: path deleted: {}", _uid, dataPath);
     }
 
     try {
       updateNotificationTime(System.nanoTime());
       if (dataPath != null && dataPath.startsWith(_path)) {
-        logger
-            .info("{} unsubscribe data-change. path: {}, listener: {}", _manager.getInstanceName(),
-                dataPath, _listener);
+        logger.info("CallbackHandler {}, {} unsubscribe data-change. path: {}, listener:
{}",
+            _uid, _manager.getInstanceName(), dataPath, _listener);
         _zkClient.unsubscribeDataChanges(dataPath, this);
 
         // only needed for bucketized parent, but OK if we don't have child-change
         // watch on the bucketized parent path
-        logger.info("{} unsubscribe child-change. path: {}, listener: {}",
-            _manager.getInstanceName(), dataPath, _listener);
+        logger.info("CallbackHandler {}, {} unsubscribe child-change. path: {}, listener:
{}",
+            _uid, _manager.getInstanceName(), dataPath, _listener);
         _zkClient.unsubscribeChildChanges(dataPath, this);
         // No need to invoke() since this event will handled by child-change on parent-node
       }
@@ -772,7 +776,8 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
         if (currentChilds == null && parentPath.equals(_path)) {
           // _path has been removed, remove this listener
           // removeListener will call handler.reset(), which in turn call invoke() on FINALIZE
type
-          _manager.removeListener(_propertyKey, _listener);
+          boolean rt = _manager.removeListener(_propertyKey, _listener);
+          logger.info("CallbackHandler {} removed with status {}", _uid, rt);
         } else {
           if (!isReady()) {
             // avoid leaking CallbackHandler
@@ -804,7 +809,7 @@ public class CallbackHandler implements IZkChildListener, IZkDataListener
{
   }
 
   void reset(boolean isShutdown) {
-    logger.info("Resetting CallbackHandler: {}. Is resetting for shutdown: {}.", this.toString(),
+    logger.info("Resetting CallbackHandler: {}. Is resetting for shutdown: {}.", _uid,
         isShutdown);
     try {
       _ready = false;
diff --git a/zookeeper-api/src/main/java/org/apache/helix/zookeeper/zkclient/ZkClient.java
b/zookeeper-api/src/main/java/org/apache/helix/zookeeper/zkclient/ZkClient.java
index 40332a3..180fcdd 100644
--- a/zookeeper-api/src/main/java/org/apache/helix/zookeeper/zkclient/ZkClient.java
+++ b/zookeeper-api/src/main/java/org/apache/helix/zookeeper/zkclient/ZkClient.java
@@ -96,7 +96,7 @@ public class ZkClient implements Watcher {
   private static final String SYNC_PATH = "/";
 
   private static AtomicLong UID = new AtomicLong(0);
-  private long _uid;
+  public final long _uid;
 
   private final IZkConnection _connection;
   private final long _operationRetryTimeoutInMillis;
@@ -220,7 +220,7 @@ public class ZkClient implements Watcher {
 
     _asyncCallRetryThread = new ZkAsyncRetryThread(zkConnection.getServers());
     _asyncCallRetryThread.start();
-    LOG.debug("ZkClient created with _uid {}, _asyncCallRetryThread id {}", _uid, _asyncCallRetryThread.getId());
+    LOG.debug("ZkClient created with uid {}, _asyncCallRetryThread id {}", _uid, _asyncCallRetryThread.getId());
 
     connect(connectionTimeout, this);
 
@@ -258,7 +258,7 @@ public class ZkClient implements Watcher {
     List<String> children = watchForChilds(path, skipWatchingNonExistNode);
     if (children == null && skipWatchingNonExistNode) {
       unsubscribeChildChanges(path, listener);
-      LOG.info("watchForChilds failed to install no-existing watch and add listener. Path:
{}", path);
+      LOG.info("zkclient{}, watchForChilds failed to install no-existing watch and add listener.
Path: {}", _uid, path);
       return new ChildrenSubscribeResult(children, false);
     }
 
@@ -288,8 +288,8 @@ public class ZkClient implements Watcher {
       listenerEntries.add(listenerEntry);
       if (prefetchEnabled) {
         if (LOG.isDebugEnabled()) {
-          LOG.debug("Subscribed data changes for " + path + ", listener: " + listener
-              + ", prefetch data: " + prefetchEnabled);
+          LOG.debug("zkclient {} subscribed data changes for {}, listener {}, prefetch data
{}",
+              _uid, path, listener, prefetchEnabled);
         }
       }
     }
@@ -298,12 +298,13 @@ public class ZkClient implements Watcher {
     if (!watchInstalled) {
       // Now let us remove this handler.
       unsubscribeDataChanges(path, listener);
-      LOG.info("watchForData failed to install no-existing path and thus add listener. Path:"
+ path);
+      LOG.info("zkclient {} watchForData failed to install no-existing path and thus add
listener. Path: {}",
+          _uid, path);
       return false;
     }
 
     if (LOG.isDebugEnabled()) {
-      LOG.debug("Subscribed data changes for " + path);
+      LOG.debug("zkclient {}, Subscribed data changes for {}", _uid, path);
     }
     return true;
   }
@@ -333,8 +334,8 @@ public class ZkClient implements Watcher {
         return preFetchInMethod.enabled();
       }
     } catch (NoSuchMethodException e) {
-      LOG.warn("No method " + callbackMethod.getName() + " defined in listener " + dataListener
-          .getClass().getCanonicalName());
+      LOG.warn("Zkclient {}, No method {} defined in listener {}",
+          _uid, callbackMethod.getName(), dataListener.getClass().getCanonicalName());
     }
 
     return true;
@@ -760,7 +761,7 @@ public class ZkClient implements Watcher {
     } finally {
       long endT = System.currentTimeMillis();
       if (LOG.isTraceEnabled()) {
-        LOG.trace("create, path: " + path + ", time: " + (endT - startT) + " ms");
+        LOG.trace("zkclient {} create, path {}, time {} ms", _uid, path, (endT - startT));
       }
     }
   }
@@ -962,7 +963,7 @@ public class ZkClient implements Watcher {
   public void process(WatchedEvent event) {
     long notificationTime = System.currentTimeMillis();
     if (LOG.isDebugEnabled()) {
-      LOG.debug("Received event: " + event);
+      LOG.debug("zkclient {}, Received event: {} ", _uid, event);
     }
     _zookeeperEventThread = Thread.currentThread();
 
@@ -974,7 +975,7 @@ public class ZkClient implements Watcher {
             || event.getType() == EventType.NodeCreated
             || event.getType() == EventType.NodeChildrenChanged;
     if (event.getType() == EventType.NodeDeleted) {
-      LOG.debug("Path {} is deleted", event.getPath());
+      LOG.debug("zkclient {}, Path {} is deleted", _uid, event.getPath());
     }
 
     getEventLock().lock();
@@ -982,8 +983,8 @@ public class ZkClient implements Watcher {
       // We might have to install child change event listener if a new node was created
       if (getShutdownTrigger()) {
         if (LOG.isDebugEnabled()) {
-          LOG.debug("ignoring event '{" + event.getType() + " | " + event.getPath()
-              + "}' since shutdown triggered");
+          LOG.debug("zkclient {} ignoring event {}|{} since shutdown triggered",
+              _uid, event.getType(), event.getPath());
         }
         return;
       }
@@ -1019,7 +1020,7 @@ public class ZkClient implements Watcher {
       recordStateChange(stateChanged, dataChanged, sessionExpired);
 
       if (LOG.isDebugEnabled()) {
-        LOG.debug("Leaving process event");
+        LOG.debug("zkclient {} Leaving process event", _uid);
       }
     }
   }
@@ -1080,7 +1081,7 @@ public class ZkClient implements Watcher {
     } finally {
       long endT = System.currentTimeMillis();
       if (LOG.isTraceEnabled()) {
-        LOG.trace("getChildren, path: " + path + ", time: " + (endT - startT) + " ms");
+        LOG.trace("zkclient {} getChildren, path {} time: {} ms", _uid, path, (endT - startT)
);
       }
     }
   }
@@ -1122,7 +1123,7 @@ public class ZkClient implements Watcher {
     } finally {
       long endT = System.currentTimeMillis();
       if (LOG.isTraceEnabled()) {
-        LOG.trace("exists, path: " + path + ", time: " + (endT - startT) + " ms");
+        LOG.trace("zkclient exists, path: {}, time: {} ms", _uid, path, (endT - startT));
       }
     }
   }
@@ -1145,7 +1146,7 @@ public class ZkClient implements Watcher {
     } finally {
       long endT = System.currentTimeMillis();
       if (LOG.isTraceEnabled()) {
-        LOG.trace("exists, path: " + path + ", time: " + (endT - startT) + " ms");
+        LOG.trace("zkclient exists, path: {}, time: {} ms", _uid, path, (endT - startT));
       }
     }
   }
@@ -1174,13 +1175,14 @@ public class ZkClient implements Watcher {
     } finally {
       long endT = System.currentTimeMillis();
       if (LOG.isTraceEnabled()) {
-        LOG.trace("getData (installWatchOnlyPathExist), path: " + path + ", time: " + (endT
- startT) + " ms");
+        LOG.trace("zkclient getData (installWatchOnlyPathExist), path: {}, time: {} ms",
+            _uid, path, (endT - startT));
       }
     }
   }
 
   protected void processStateChanged(WatchedEvent event) {
-    LOG.info("zookeeper state changed (" + event.getState() + ")");
+    LOG.info("zkclient {}, zookeeper state changed ( {} )", _uid, event.getState());
     setCurrentState(event.getState());
     if (getShutdownTrigger()) {
       return;
@@ -1243,7 +1245,8 @@ public class ZkClient implements Watcher {
       } catch (Exception e) {
         reconnectException = e;
         long waitInterval = retryStrategy.getNextWaitInterval(retryCount++);
-        LOG.warn("ZkClient reconnect on expiring failed. Will retry after {} ms", waitInterval,
e);
+        LOG.warn("ZkClient {}, reconnect on expiring failed. Will retry after {} ms",
+            _uid, waitInterval, e);
         try {
           Thread.sleep(waitInterval);
         } catch (InterruptedException ex) {
@@ -1253,8 +1256,8 @@ public class ZkClient implements Watcher {
       }
     }
 
-    LOG.info("Unable to re-establish connection. Notifying consumer of the following exception:
",
-        reconnectException);
+    LOG.info("Zkclient {} unable to re-establish connection. Notifying consumer of the following
exception:{}",
+        _uid, reconnectException);
     fireSessionEstablishmentError(reconnectException);
   }
 
@@ -1305,8 +1308,8 @@ public class ZkClient implements Watcher {
 
     KeeperException.Code code = KeeperException.Code.get(callbackHandler.getRc());
     if (code == KeeperException.Code.OK) {
-      LOG.info("sycnOnNewSession with sessionID {} async return code: {} and proceeds", sessionId,
-          code);
+      LOG.info("zkclient {}, sycnOnNewSession with sessionID {} async return code: {} and
proceeds",
+          _uid, sessionId, code);
       return true;
     }
 
@@ -1328,7 +1331,7 @@ public class ZkClient implements Watcher {
         @Override
         public void run() throws Exception {
           if (issueSync(zk) == false) {
-            LOG.warn("Failed to call sync() on new session {}", sessionId);
+            LOG.warn("zkclient{}, Failed to call sync() on new session {}", _uid, sessionId);
           }
         }
       });
@@ -1397,7 +1400,8 @@ public class ZkClient implements Watcher {
       deleteRecursively(path);
       return true;
     } catch (ZkClientException e) {
-      LOG.error("Failed to recursively delete path " + path, e);
+      LOG.error("zkcient {}, Failed to recursively delete path {}, exception {}",
+          _uid, path, e);
       return false;
     }
   }
@@ -1426,7 +1430,7 @@ public class ZkClient implements Watcher {
     try {
       delete(path);
     } catch (Exception e) {
-      LOG.error("Failed to delete " + path, e);
+      LOG.error("zkclient {}, Failed to delete {}, exception {}", _uid, path, e);
       throw new ZkClientException("Failed to delete " + path, e);
     }
   }
@@ -1435,7 +1439,7 @@ public class ZkClient implements Watcher {
     final String path = event.getPath();
     final boolean pathExists = event.getType() != EventType.NodeDeleted;
     if (EventType.NodeDeleted == event.getType()) {
-      LOG.debug("Event NodeDeleted: {}", event.getPath());
+      LOG.debug("zkclient{}, Event NodeDeleted: {}", _uid, event.getPath());
     }
 
     if (event.getType() == EventType.NodeChildrenChanged || event.getType() == EventType.NodeCreated
@@ -1491,13 +1495,13 @@ public class ZkClient implements Watcher {
               Object data = null;
               if (listener.isPrefetchData()) {
                 if (LOG.isDebugEnabled()) {
-                  LOG.debug("Prefetch data for path: {}", path);
+                  LOG.debug("zkclient {} Prefetch data for path: {}", _uid, path);
                 }
                 try {
                   // TODO: the data is redundantly read multiple times when multiple listeners
exist
                   data = readData(path, null, true);
                 } catch (ZkNoNodeException e) {
-                  LOG.warn("Prefetch data for path: {} failed.", path, e);
+                  LOG.warn("zkclient {} Prefetch data for path: {} failed.", _uid, path,
e);
                   listener.getDataListener().handleDataDeleted(path);
                   return;
                 }
@@ -1508,7 +1512,7 @@ public class ZkClient implements Watcher {
         });
       }
     } catch (Exception e) {
-      LOG.error("Failed to fire data changed event for path: {}", path, e);
+      LOG.error("zkclient {} Failed to fire data changed event for path: {}", _uid, path,
e);
     }
   }
 
@@ -1535,7 +1539,7 @@ public class ZkClient implements Watcher {
               try {
                 children = getChildren(path);
               } catch (ZkNoNodeException e) {
-                LOG.warn("Get children under path: {} failed.", path, e);
+                LOG.warn("zkclient {} Get children under path: {} failed.", _uid, path, e);
                 // Continue trigger the change handler
               }
             }
@@ -1544,7 +1548,7 @@ public class ZkClient implements Watcher {
         });
       }
     } catch (Exception e) {
-      LOG.error("Failed to fire child changed event. Unable to getChildren.", e);
+      LOG.error("zkclient {} Failed to fire child changed event. Unable to getChildren.",
_uid, e);
     }
   }
 
@@ -1552,7 +1556,7 @@ public class ZkClient implements Watcher {
       throws ZkInterruptedException {
     Date timeout = new Date(System.currentTimeMillis() + timeUnit.toMillis(time));
     if (LOG.isDebugEnabled()) {
-      LOG.debug("Waiting until znode '" + path + "' becomes available.");
+      LOG.debug("Waiting until znode {} becomes available.", _uid, path);
     }
     if (exists(path)) {
       return true;
@@ -1602,7 +1606,7 @@ public class ZkClient implements Watcher {
     validateCurrentThread();
     Date timeout = new Date(System.currentTimeMillis() + timeUnit.toMillis(time));
 
-    LOG.debug("Waiting for keeper state " + keeperState);
+    LOG.debug("zkclient {}, Waiting for keeper state {} ", _uid, keeperState);
     acquireEventLock();
     try {
       boolean stillWaiting = true;
@@ -1612,7 +1616,8 @@ public class ZkClient implements Watcher {
         }
         stillWaiting = getEventLock().getStateChangedCondition().awaitUntil(timeout);
       }
-      LOG.debug("State is " + (_currentState == null ? "CLOSED" : _currentState));
+      LOG.debug("zkclient {} State is {}",
+          _uid, (_currentState == null ? "CLOSED" : _currentState));
       return true;
     } catch (InterruptedException e) {
       throw new ZkInterruptedException(e);
@@ -1690,7 +1695,7 @@ public class ZkClient implements Watcher {
           throw ExceptionUtil.convertToRuntimeException(e);
         }
 
-        LOG.debug("Retrying operation, caused by {}", retryCauseCode);
+        LOG.debug("zkclient {}, Retrying operation, caused by {}", _uid,retryCauseCode);
         // before attempting a retry, check whether retry timeout has elapsed
         if (System.currentTimeMillis() - operationStartTime > _operationRetryTimeoutInMillis)
{
           throw new ZkTimeoutException("Operation cannot be retried because of retry timeout
("
@@ -1753,18 +1758,18 @@ public class ZkClient implements Watcher {
       } catch (ZkNoNodeException e) {
         success = false;
         if (LOG.isDebugEnabled()) {
-          LOG.debug("Failed to delete path " + path + ", znode does not exist!");
+          LOG.debug("zkclient {}, Failed to delete path {}, znode does not exist!", _uid,
path);
         }
       }
       record(path, null, startT, ZkClientMonitor.AccessType.WRITE);
     } catch (Exception e) {
       recordFailure(path, ZkClientMonitor.AccessType.WRITE);
-      LOG.warn("Failed to delete path " + path + "! " + e);
+      LOG.warn("zkclient {}, Failed to delete path {}! ", _uid, path, e);
       throw e;
     } finally {
       long endT = System.currentTimeMillis();
       if (LOG.isTraceEnabled()) {
-        LOG.trace("delete, path: " + path + ", time: " + (endT - startT) + " ms");
+        LOG.trace("zkclient {} delete, path: {}, time {} ms", _uid, path, (endT - startT));
       }
     }
     return success;
@@ -1840,7 +1845,7 @@ public class ZkClient implements Watcher {
     } finally {
       long endT = System.currentTimeMillis();
       if (LOG.isTraceEnabled()) {
-        LOG.trace("getData, path: " + path + ", time: " + (endT - startT) + " ms");
+        LOG.trace("zkclient {}, getData, path {}, time {} ms", _uid, path, (endT - startT));
       }
     }
   }
@@ -1917,7 +1922,7 @@ public class ZkClient implements Watcher {
     } finally {
       long endT = System.currentTimeMillis();
       if (LOG.isTraceEnabled()) {
-        LOG.trace("setData, path: " + path + ", time: " + (endT - startT) + " ms");
+        LOG.trace("zkclient {}, setData, path {}, time {} ms", _uid, path, (endT - startT));
       }
     }
   }
@@ -2049,7 +2054,7 @@ public class ZkClient implements Watcher {
       }
     } catch (ZkNoNodeException e) {
       // Do nothing, this is what we want as this is not going to leak watch in ZooKeeepr
server.
-      LOG.info("watchForData path not existing: " + path);
+      LOG.info("zkclient {}, watchForData path not existing: {} ", _uid, path);
       return false;
     }
     return true;
@@ -2104,8 +2109,8 @@ public class ZkClient implements Watcher {
           return getChildren(path, true);
         } catch (ZkNoNodeException e) {
           // ignore, the "exists" watch will listen for the parent node to appear
-          LOG.info("watchForChilds path not existing:{} skipWatchingNodeNoteExist: {}",
-              path, skipWatchingNonExistNode);
+          LOG.info("zkclient{} watchForChilds path not existing:{} skipWatchingNodeNoteExist:
{}",
+              _uid, path, skipWatchingNonExistNode);
         }
         return null;
       }
@@ -2154,11 +2159,11 @@ public class ZkClient implements Watcher {
       _eventThread = new ZkEventThread(zkConnection.getServers());
       _eventThread.start();
 
-      LOG.debug("ZkClient created with _uid {}, _eventThread {}", _uid, _eventThread.getId());
+      LOG.debug("ZkClient {},  _eventThread {}", _uid, _eventThread.getId());
 
       if (isManagingZkConnection()) {
         zkConnection.connect(watcher);
-        LOG.debug("Awaiting connection to Zookeeper server");
+        LOG.debug("zkclient{} Awaiting connection to Zookeeper server", _uid);
         if (!waitUntilConnected(maxMsToWaitUntilConnected, TimeUnit.MILLISECONDS)) {
           throw new ZkTimeoutException(
               "Unable to connect to zookeeper server within timeout: " + maxMsToWaitUntilConnected);
@@ -2212,7 +2217,7 @@ public class ZkClient implements Watcher {
   public void close() throws ZkInterruptedException {
     if (LOG.isTraceEnabled()) {
       StackTraceElement[] calls = Thread.currentThread().getStackTrace();
-      LOG.trace("closing a zkclient. callStack: " + Arrays.asList(calls));
+      LOG.trace("Closing a zkclient uid:{}, callStack: {} ", _uid, Arrays.asList(calls));
     }
     getEventLock().lock();
     IZkConnection connection = getConnection();
@@ -2228,7 +2233,7 @@ public class ZkClient implements Watcher {
       _eventThread.interrupt();
       _eventThread.join(2000);
       if (isManagingZkConnection()) {
-        LOG.info("Closing zkclient: " + ((ZkConnection) connection).getZookeeper());
+        LOG.info("Closing zkclient uid:{}, zk:{}", _uid, ((ZkConnection) connection).getZookeeper());
         connection.close();
       }
       _closed = true;
@@ -2265,7 +2270,7 @@ public class ZkClient implements Watcher {
       if (_monitor != null) {
         _monitor.unregister();
       }
-      LOG.info("Closed zkclient");
+      LOG.info("Closed zkclient with uid:{}", _uid);
     }
   }
 


Mime
View raw message