You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@helix.apache.org by hz...@apache.org on 2020/09/23 21:46:19 UTC
[helix] branch master updated: Enhance logging for CallbackHandler
and Zkclient (#1355)
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 <52...@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);
}
}