diff options
author | jonmv <venstad@gmail.com> | 2022-10-13 13:06:08 +0200 |
---|---|---|
committer | jonmv <venstad@gmail.com> | 2022-10-13 13:06:08 +0200 |
commit | 7cb5dd3fefd538d457f2e9657c03ea701339eeac (patch) | |
tree | 7ae3fdabe59631fc2344eb74c802ff8f4c86c750 /zkfacade | |
parent | 55273728967bc6edea0185f062c93a3e61e6cf66 (diff) |
More logging
Diffstat (limited to 'zkfacade')
-rw-r--r-- | zkfacade/src/main/java/com/yahoo/vespa/curator/SingletonManager.java | 51 |
1 files changed, 35 insertions, 16 deletions
diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/SingletonManager.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/SingletonManager.java index d2fe6ac6625..ec1aec4f370 100644 --- a/zkfacade/src/main/java/com/yahoo/vespa/curator/SingletonManager.java +++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/SingletonManager.java @@ -21,9 +21,12 @@ import java.util.concurrent.LinkedBlockingDeque; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicReference; -import java.util.logging.Level; import java.util.logging.Logger; +import static java.util.logging.Level.FINE; +import static java.util.logging.Level.INFO; +import static java.util.logging.Level.WARNING; + /** * Manages {@link com.yahoo.vespa.curator.api.VespaCurator.SingletonWorker}. * @@ -96,7 +99,7 @@ class SingletonManager { int i = 0; for (SingletonWorker singleton : List.copyOf(registrations.keySet())) { String id = registrations.get(singleton); - logger.log(Level.WARNING, singleton + " still registered with id '" + id + "' at shutdown"); + logger.log(WARNING, singleton + " still registered with id '" + id + "' at shutdown"); futures[i++] = unregister(singleton); } return CompletableFuture.allOf(futures) @@ -150,12 +153,13 @@ class SingletonManager { public void unlock() { doom.set(null); if (lock != null) try { + logger.log(INFO, "Releasing lease for " + id); metrics.hasLease(false); lock.close(); lock = null; } catch (Exception e) { - logger.log(Level.WARNING, "failed closing " + lock, e); + logger.log(WARNING, "Failed closing " + lock, e); } } @@ -172,7 +176,7 @@ class SingletonManager { } catch (InterruptedException e) { if ( ! shutdown.get()) { - logger.log(Level.WARNING, worker + " interrupted, restarting event loop"); + logger.log(WARNING, worker + " interrupted, restarting event loop"); } } } @@ -199,46 +203,55 @@ class SingletonManager { } } catch (RuntimeException e) { - logger.log(Level.WARNING, "Exception attempting to " + task.type + " " + task.singleton + " in " + worker, e); + logger.log(WARNING, "Exception attempting to " + task.type + " " + task.singleton + " in " + worker, e); task.future.completeExceptionally(e); } } private void doRegister(SingletonWorker singleton) { + logger.log(INFO, "Registering " + singleton + " with ID: " + id); SingletonWorker current = singletons.peek(); singletons.push(singleton); if (active) { RuntimeException e = null; if (current != null) try { + logger.log(INFO, "Deactivating " + current); metrics.deactivation(current::deactivate); } catch (RuntimeException f) { e = f; } try { + logger.log(INFO, "Activating " + singleton); metrics.activation(singleton::activate); } catch (RuntimeException f) { if (e == null) e = f; else e.addSuppressed(f); } - if (singletons.isEmpty()) doom.set(INVALID); + if (singletons.isEmpty()) { + logger.log(INFO, "No registered singletons, invalidating lease"); + invalidate(); + } if (e != null) throw e; } } private void doUnregister(SingletonWorker singleton) { + logger.log(INFO, "Unregistering " + singleton + " with ID: " + id); RuntimeException e = null; SingletonWorker current = singletons.peek(); if ( ! singletons.remove(singleton)) return; if (active && current == singleton) { try { + logger.log(INFO, "Deactivating " + singleton); metrics.deactivation(singleton::deactivate); } catch (RuntimeException f) { e = f; } if ( ! singletons.isEmpty()) try { + logger.log(INFO, "Activating " + singletons.peek()); metrics.activation(singletons.peek()::activate); } catch (RuntimeException f) { @@ -246,7 +259,10 @@ class SingletonManager { else e.addSuppressed(f); } } - if (singletons.isEmpty()) doom.set(INVALID); + if (singletons.isEmpty()) { + logger.log(INFO, "No registered singletons, invalidating lease"); + invalidate(); + } if (e != null) throw e; } @@ -256,6 +272,7 @@ class SingletonManager { */ private void renewLease() { if (doom.get() == INVALID) { + logger.log(INFO, "Lease invalidated"); doom.set(null); return; // Skip to updateStatus, deactivation, and release the lock. } @@ -264,21 +281,22 @@ class SingletonManager { Instant start = clock.instant(); if (lock == null) try { lock = curator.lock(path.append("lock"), tickTimeout); + logger.log(INFO, "Acquired lock for ID: " + id); metrics.hasLease(true); } catch (RuntimeException e) { - logger.log(Level.FINE, "Failed acquiring lock for '" + path + "' within " + tickTimeout, e); + logger.log(FINE, "Failed acquiring lock for '" + path + "' within " + tickTimeout, e); return; } try { curator.set(path.append("ping"), new byte[0]); } catch (RuntimeException e) { - logger.log(Level.FINE, "Failed pinging ZK cluster", e); + logger.log(FINE, "Failed pinging ZK cluster", e); return; } if ( ! doom.compareAndSet(ourDoom, start.plus(Curator.ZK_SESSION_TIMEOUT.multipliedBy(9).dividedBy(10)))) { - logger.log(Level.FINE, "Deadline changed, invalidating current lease renewal"); + logger.log(FINE, "Deadline changed, current lease renewal is void"); } } @@ -290,22 +308,24 @@ class SingletonManager { Instant ourDoom = doom.get(); boolean shouldBeActive = ourDoom != null && ourDoom != INVALID && ! clock.instant().isAfter(ourDoom); if ( ! active && shouldBeActive) { + logger.log(INFO, "Activating singletons for ID :" + id); try { active = true; if ( ! singletons.isEmpty()) metrics.activation(singletons.peek()::activate); } catch (RuntimeException e) { - logger.log(Level.WARNING, "Failed to activate " + singletons.peek() + ", deactivating again", e); + logger.log(WARNING, "Failed to activate " + singletons.peek() + ", deactivating again", e); shouldBeActive = false; } } if (active && ! shouldBeActive) { + logger.log(INFO, "Deactivating singletons due to doom value of '" + ourDoom + "', for ID :" + id); try { if ( ! singletons.isEmpty()) metrics.deactivation(singletons.peek()::deactivate); active = false; } catch (RuntimeException e) { - logger.log(Level.WARNING, "Failed to deactivate " + singletons.peek(), e); + logger.log(WARNING, "Failed to deactivate " + singletons.peek(), e); } unlock(); } @@ -328,8 +348,9 @@ class SingletonManager { } void shutdown() { + logger.log(INFO, "Shutting down " + this); if ( ! shutdown.compareAndSet(false, true)) { - logger.log(Level.WARNING, "Shutdown called more than once on " + this); + logger.log(WARNING, "Shutdown called more than once on " + this); } if (Thread.currentThread() != worker) { try { @@ -343,7 +364,7 @@ class SingletonManager { unlock(); } if ( ! tasks.isEmpty()) { - logger.log(Level.WARNING, "Non-empty task list after shutdown: " + tasks.size() + " remaining"); + logger.log(WARNING, "Non-empty task list after shutdown: " + tasks.size() + " remaining"); for (Task task : tasks) task.future.cancel(true); // Shouldn't happen. } } @@ -374,7 +395,6 @@ class SingletonManager { Instant start = clock.instant(); boolean failed = false; metric.add(ACTIVATION, 1, context); - logger.log(Level.INFO, "Activating singleton with ID " + id); try { activation.run(); } @@ -393,7 +413,6 @@ class SingletonManager { Instant start = clock.instant(); boolean failed = false; metric.add(DEACTIVATION, 1, context); - logger.log(Level.INFO, "Deactivating singleton with ID " + id); try { deactivation.run(); } |