This is an automated email from the ASF dual-hosted git repository. ctubbsii pushed a commit to branch main in repository https://gitbox.apache.org/repos/asf/accumulo.git
The following commit(s) were added to refs/heads/main by this push: new a76401788a Add details to ZooKeeper watcher logs (#2615) a76401788a is described below commit a76401788a5b0fdeb38cb4e29abdbfbb11a27faf Author: Christopher Tubbs <ctubb...@apache.org> AuthorDate: Mon Apr 11 17:18:50 2022 -0400 Add details to ZooKeeper watcher logs (#2615) Add more details to the log messages produced while processing ZooKeeper WatchedEvents. Also, try to standardize some messages by adding the event at the end, after whatever core message is conveyed. Most of the time, we won't see these messages, but it definitely helps to have greater insight into what event triggered the situation, rather than picking out and printing only certain details from the WatchedEvent. --- .../accumulo/fate/zookeeper/ServiceLock.java | 31 +++++++++++----------- .../apache/accumulo/fate/zookeeper/ZooCache.java | 12 ++++----- .../apache/accumulo/fate/zookeeper/ZooSession.java | 2 +- .../delegation/ZooAuthenticationKeyWatcher.java | 24 ++++++++--------- .../accumulo/server/tables/TableManager.java | 4 +-- .../server/zookeeper/DistributedWorkQueue.java | 11 ++++---- 6 files changed, 42 insertions(+), 42 deletions(-) diff --git a/core/src/main/java/org/apache/accumulo/fate/zookeeper/ServiceLock.java b/core/src/main/java/org/apache/accumulo/fate/zookeeper/ServiceLock.java index 40ed6f6d5c..7aaafef712 100644 --- a/core/src/main/java/org/apache/accumulo/fate/zookeeper/ServiceLock.java +++ b/core/src/main/java/org/apache/accumulo/fate/zookeeper/ServiceLock.java @@ -311,22 +311,19 @@ public class ServiceLock implements Watcher { @Override public void process(WatchedEvent event) { if (LOG.isTraceEnabled()) { - LOG.trace("[{}] Processing event:", vmLockPrefix); - LOG.trace("- type {}", event.getType()); - LOG.trace("- path {}", event.getPath()); - LOG.trace("- state {}", event.getState()); + LOG.trace("[{}] Processing {}", vmLockPrefix, event); } boolean renew = true; if (event.getType() == EventType.NodeDeleted && event.getPath().equals(nodeToWatch)) { - LOG.debug("[{}] Detected deletion of prior node {}, attempting to acquire lock", - vmLockPrefix, nodeToWatch); + LOG.debug("[{}] Detected deletion of prior node {}, attempting to acquire lock; {}", + vmLockPrefix, nodeToWatch, event); synchronized (ServiceLock.this) { try { if (createdNodeName != null) { determineLockOwnership(createdEphemeralNode, lw); } else if (LOG.isDebugEnabled()) { - LOG.debug("[{}] While waiting for another lock {}, {} was deleted", vmLockPrefix, - nodeToWatch, createdEphemeralNode); + LOG.debug("[{}] While waiting for another lock {}, {} was deleted; {}", + vmLockPrefix, nodeToWatch, createdEphemeralNode, event); } } catch (Exception e) { if (lockNodeName == null) { @@ -342,8 +339,9 @@ public class ServiceLock implements Watcher { || event.getState() == KeeperState.Disconnected) { synchronized (ServiceLock.this) { if (lockNodeName == null) { - LOG.info("Zookeeper Session expired / disconnected"); - lw.failedToAcquireLock(new Exception("Zookeeper Session expired / disconnected")); + LOG.info("Zookeeper Session expired / disconnected; {}", event); + lw.failedToAcquireLock( + new Exception("Zookeeper Session expired / disconnected; " + event)); } } renew = false; @@ -361,7 +359,8 @@ public class ServiceLock implements Watcher { LOG.debug("[{}] Renewed watch on prior node {}", vmLockPrefix, nodeToWatch); } } catch (KeeperException | InterruptedException e) { - lw.failedToAcquireLock(new Exception("Failed to renew watch on other manager node")); + lw.failedToAcquireLock( + new Exception("Failed to renew watch on other manager node", e)); } } } @@ -466,16 +465,16 @@ public class ServiceLock implements Watcher { synchronized (ServiceLock.this) { if (lockNodeName != null && event.getType() == EventType.NodeDeleted && event.getPath().equals(path + "/" + lockNodeName)) { - LOG.debug("[{}] {} was deleted", vmLockPrefix, lockNodeName); + LOG.debug("[{}] {} was deleted; {}", vmLockPrefix, lockNodeName, event); lostLock(LockLossReason.LOCK_DELETED); } else if (createdNodeName != null && event.getType() == EventType.NodeDeleted && event.getPath().equals(path + "/" + createdNodeName)) { - LOG.debug("[{}] {} was deleted", vmLockPrefix, createdNodeName); + LOG.debug("[{}] {} was deleted; {}", vmLockPrefix, createdNodeName, event); failedToAcquireLock(); } else if (event.getState() != KeeperState.Disconnected && event.getState() != KeeperState.Expired && (lockNodeName != null || createdNodeName != null)) { - LOG.debug("Unexpected event watching lock node {} {}", event, pathForWatcher); + LOG.debug("Unexpected event watching lock node {}; {}", pathForWatcher, event); try { Stat stat2 = zooKeeper.exists(pathForWatcher, this); if (stat2 == null) { @@ -491,7 +490,7 @@ public class ServiceLock implements Watcher { } } catch (Exception e) { lockWatcher.unableToMonitorLockNode(e); - LOG.error("Failed to stat lock node: {} ", pathForWatcher, e); + LOG.error("Failed to stat lock node: {}; {}", pathForWatcher, event, e); } } @@ -603,7 +602,7 @@ public class ServiceLock implements Watcher { @Override public synchronized void process(WatchedEvent event) { if (LOG.isDebugEnabled()) { - LOG.debug("event {} {} {}", event.getPath(), event.getType(), event.getState()); + LOG.debug("{}", event); } watchingParent = false; diff --git a/core/src/main/java/org/apache/accumulo/fate/zookeeper/ZooCache.java b/core/src/main/java/org/apache/accumulo/fate/zookeeper/ZooCache.java index ace2b02905..4fc17feb33 100644 --- a/core/src/main/java/org/apache/accumulo/fate/zookeeper/ZooCache.java +++ b/core/src/main/java/org/apache/accumulo/fate/zookeeper/ZooCache.java @@ -171,26 +171,26 @@ public class ZooCache { // These are ignored, because they are generated by SingletonManager closing // ZooKeepers for ZooSession, and SingletonManager is already responsible for clearing // caches via the registered ZooCacheFactory singleton - log.trace("Zoo keeper connection closed, ignoring"); + log.trace("ZooKeeper connection closed, ignoring; {}", event); break; case Disconnected: - log.trace("Zoo keeper connection disconnected, clearing cache"); + log.trace("ZooKeeper connection disconnected, clearing cache; {}", event); clear(); break; case SyncConnected: - log.trace("Zoo keeper connection established, ignoring"); + log.trace("ZooKeeper connection established, ignoring; {}", event); break; case Expired: - log.trace("Zoo keeper connection expired, clearing cache"); + log.trace("ZooKeeper connection expired, clearing cache; {}", event); clear(); break; default: - log.warn("Unhandled: {}", event); + log.warn("Unhandled {}", event); break; } break; default: - log.warn("Unhandled: {}", event); + log.warn("Unhandled {}", event); break; } diff --git a/core/src/main/java/org/apache/accumulo/fate/zookeeper/ZooSession.java b/core/src/main/java/org/apache/accumulo/fate/zookeeper/ZooSession.java index 76f608ab5c..c6dea78771 100644 --- a/core/src/main/java/org/apache/accumulo/fate/zookeeper/ZooSession.java +++ b/core/src/main/java/org/apache/accumulo/fate/zookeeper/ZooSession.java @@ -95,7 +95,7 @@ public class ZooSession { @Override public void process(WatchedEvent event) { if (event.getState() == KeeperState.Expired) { - log.debug("Session expired, state of current session : {}", event.getState()); + log.debug("Session expired; {}", event); } } diff --git a/server/base/src/main/java/org/apache/accumulo/server/security/delegation/ZooAuthenticationKeyWatcher.java b/server/base/src/main/java/org/apache/accumulo/server/security/delegation/ZooAuthenticationKeyWatcher.java index 1cf140e2db..4e911ff03e 100644 --- a/server/base/src/main/java/org/apache/accumulo/server/security/delegation/ZooAuthenticationKeyWatcher.java +++ b/server/base/src/main/java/org/apache/accumulo/server/security/delegation/ZooAuthenticationKeyWatcher.java @@ -59,19 +59,19 @@ public class ZooAuthenticationKeyWatcher implements Watcher { case Disconnected: // Intentional fall through of case case Expired: // ZooReader is handling the Expiration of the original ZooKeeper object for // us - log.debug("ZooKeeper connection disconnected, clearing secret manager"); + log.debug("ZooKeeper connection disconnected, clearing secret manager; {}", event); secretManager.removeAllKeys(); break; case SyncConnected: - log.debug("ZooKeeper reconnected, updating secret manager"); + log.debug("ZooKeeper reconnected, updating secret manager; {}", event); try { updateAuthKeys(); } catch (KeeperException | InterruptedException e) { - log.error("Failed to update secret manager after ZooKeeper reconnect"); + log.error("Failed to update secret manager after ZooKeeper reconnect; {}", event, e); } break; default: - log.warn("Unhandled: {}", event); + log.warn("Unhandled {}", event); } // Nothing more to do for EventType.None @@ -84,7 +84,7 @@ public class ZooAuthenticationKeyWatcher implements Watcher { } if (!path.startsWith(baseNode)) { - log.info("Ignoring event for path: {}", path); + log.info("Ignoring event for path {}; {}", path, event); return; } @@ -95,7 +95,7 @@ public class ZooAuthenticationKeyWatcher implements Watcher { processChildNode(event); } } catch (KeeperException | InterruptedException e) { - log.error("Failed to communicate with ZooKeeper", e); + log.error("Failed to communicate with ZooKeeper processing {}", event, e); } } @@ -123,7 +123,7 @@ public class ZooAuthenticationKeyWatcher implements Watcher { // The data on the parent changed. We aren't storing anything there so it's a noop break; default: - log.warn("Unsupported event type: {}", event.getType()); + log.warn("Unsupported {}", event); break; } } @@ -167,7 +167,7 @@ public class ZooAuthenticationKeyWatcher implements Watcher { case NodeDeleted: // Key expired if (path == null) { - log.error("Got null path for NodeDeleted event"); + log.error("Got null path for {}", event); return; } @@ -181,7 +181,7 @@ public class ZooAuthenticationKeyWatcher implements Watcher { case NodeCreated: // New key created if (path == null) { - log.error("Got null path for NodeCreated event"); + log.error("Got null path for {}", event); return; } // Get the data and reset the watcher @@ -192,7 +192,7 @@ public class ZooAuthenticationKeyWatcher implements Watcher { case NodeDataChanged: // Key changed, could happen on restart after not running Accumulo. if (path == null) { - log.error("Got null path for NodeDataChanged event"); + log.error("Got null path for {}", event); return; } // Get the data and reset the watcher @@ -202,10 +202,10 @@ public class ZooAuthenticationKeyWatcher implements Watcher { break; case NodeChildrenChanged: // no children for the children.. - log.warn("Unexpected NodeChildrenChanged event for authentication key node {}", path); + log.warn("Unexpected event for authentication key node {}; {}", path, event); break; default: - log.warn("Unsupported event type: {}", event.getType()); + log.warn("Unsupported {}", event); break; } } diff --git a/server/base/src/main/java/org/apache/accumulo/server/tables/TableManager.java b/server/base/src/main/java/org/apache/accumulo/server/tables/TableManager.java index 76c4a6a8eb..25f95ac3fb 100644 --- a/server/base/src/main/java/org/apache/accumulo/server/tables/TableManager.java +++ b/server/base/src/main/java/org/apache/accumulo/server/tables/TableManager.java @@ -258,7 +258,7 @@ public class TableManager { if (zPath != null && zPath.equals(tablesPrefix)) { updateTableStateCache(); } else { - log.warn("Unexpected path {}", zPath); + log.warn("Unexpected path {} in {}", zPath, event); } break; case NodeCreated: @@ -281,7 +281,7 @@ public class TableManager { case None: switch (event.getState()) { case Expired: - log.trace("Session expired {}", event); + log.trace("Session expired; {}", event); synchronized (observers) { for (TableObserver to : observers) to.sessionExpired(); diff --git a/server/base/src/main/java/org/apache/accumulo/server/zookeeper/DistributedWorkQueue.java b/server/base/src/main/java/org/apache/accumulo/server/zookeeper/DistributedWorkQueue.java index cbbf81b22c..23a9c6a341 100644 --- a/server/base/src/main/java/org/apache/accumulo/server/zookeeper/DistributedWorkQueue.java +++ b/server/base/src/main/java/org/apache/accumulo/server/zookeeper/DistributedWorkQueue.java @@ -201,15 +201,16 @@ public class DistributedWorkQueue { try { lookForWork(processor, zoo.getChildren(path, this)); } catch (KeeperException e) { - log.error("Failed to look for work", e); + log.error("Failed to look for work at path {}; {}", path, event, e); } catch (InterruptedException e) { - log.info("Interrupted looking for work", e); + log.info("Interrupted looking for work at path {}; {}", path, event, e); } else - log.info("Unexpected path for NodeChildrenChanged event {}", event.getPath()); + log.info("Unexpected path for NodeChildrenChanged event watching path {}; {}", path, + event); break; default: - log.info("Got unexpected zookeeper event: {} for {}", event.getType(), path); + log.info("Unexpected event watching path {}; {}", path, event); break; } } @@ -270,7 +271,7 @@ public class DistributedWorkQueue { } break; default: - log.info("Got unexpected zookeeper event: {} for {}", event.getType(), path); + log.info("Got unexpected zookeeper event for path {}: {}", path, event); break; } }