From 2d5417f39cac7b5c093ab6e26a760f1428611389 Mon Sep 17 00:00:00 2001 From: Arne Juul Date: Mon, 19 Apr 2021 06:43:43 +0000 Subject: add more logging * make it possible to track which location broker various components are registered with or mirroring information from. * most of these log messages should now look the same in the Java and C++ implementations --- jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java | 15 ++++++++-- .../com/yahoo/jrt/slobrok/api/BackOffPolicy.java | 8 +++++ jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java | 30 ++++++++++++++----- jrt/src/com/yahoo/jrt/slobrok/api/Register.java | 34 +++++++++++++--------- jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java | 2 +- 5 files changed, 63 insertions(+), 26 deletions(-) (limited to 'jrt') diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java b/jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java index d8a6718b407..f883ac32b72 100644 --- a/jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java +++ b/jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java @@ -1,15 +1,18 @@ // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.jrt.slobrok.api; - class BackOff implements BackOffPolicy { - private double time = 0.50; + private static final double initialTime = 0.50; + + private double time = initialTime; + @Override public void reset() { - time = 0.50; + time = initialTime; } + @Override public double get() { double ret = time; if (time < 5.0) { @@ -24,7 +27,13 @@ class BackOff implements BackOffPolicy return ret; } + @Override public boolean shouldWarn(double t) { return ((t > 8.1 && t < 9.9) || (t > 29.9)); } + + @Override + public boolean shouldInform(double t) { + return (t == initialTime); + } } diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/BackOffPolicy.java b/jrt/src/com/yahoo/jrt/slobrok/api/BackOffPolicy.java index f98e3456880..4cc402b1706 100644 --- a/jrt/src/com/yahoo/jrt/slobrok/api/BackOffPolicy.java +++ b/jrt/src/com/yahoo/jrt/slobrok/api/BackOffPolicy.java @@ -35,4 +35,12 @@ public interface BackOffPolicy * @param t current delay value **/ public boolean shouldWarn(double t); + + /** + * Check if a certain delay should result in an information message logged. + * + * @return true if we should log + * @param t current delay value + **/ + public boolean shouldInform(double t); } diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java b/jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java index 1a00cd25a2c..6e39e2a3dbd 100644 --- a/jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java +++ b/jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java @@ -39,6 +39,7 @@ public class Mirror implements IMirror { private final BackOffPolicy backOff; private volatile int updates = 0; private boolean requestDone = false; + private boolean logOnSuccess = true; private AtomicReference specs = new AtomicReference<>(new Entry[0]); private int specsGeneration = 0; private final TransportThread transportThread; @@ -176,18 +177,22 @@ public class Mirror implements IMirror { } if (target != null && ! slobroks.contains(currSlobrok)) { + log.log(Level.INFO, "location broker "+currSlobrok+" removed, will disconnect and use one of: "+slobroks); target.close(); target = null; } if (target == null) { + logOnSuccess = true; currSlobrok = slobroks.nextSlobrokSpec(); if (currSlobrok == null) { double delay = backOff.get(); + Level level = Level.FINE; + if (backOff.shouldInform(delay)) level = Level.INFO; + // note: since this happens quite often during normal operation, + // the level is lower than the more-natural Level.WARNING: + if (backOff.shouldWarn(delay)) level = Level.INFO; + log.log(level, "no location brokers available, retrying: "+slobroks+" (in " + delay + " seconds)"); updateTask.schedule(delay); - if (backOff.shouldWarn(delay)) { - log.log(Level.INFO, "no location brokers available " - + "(retry in " + delay + " seconds) for: " + slobroks); - } return; } target = orb.connect(new Spec(currSlobrok)); @@ -216,6 +221,11 @@ public class Mirror implements IMirror { for (int idx = 0; idx < numNames; idx++) { newSpecs[idx] = new Entry(n[idx], s[idx]); } + if (logOnSuccess) { + log.log(Level.INFO, "successfully connected to location broker "+currSlobrok+ + "(mirror initialized with "+numNames+" service names)"); + logOnSuccess = false; + } specs.set(newSpecs); specsGeneration = answer.get(2).asInt32(); @@ -233,15 +243,16 @@ public class Mirror implements IMirror { || (req.returnValues().get(2).count() != req.returnValues().get(3).count())) { - log.log(Level.INFO, "Error when handling update from slobrok. Error: " + req.errorMessage() + - " (error code " + req.errorCode() + ")" + ", target: " + target); + if (! logOnSuccess) { + log.log(Level.INFO, "Error with location broker "+currSlobrok+" update: " + req.errorMessage() + + " (error code " + req.errorCode() + ")"); + } target.close(); target = null; updateTask.scheduleNow(); // try next slobrok return; } - Values answer = req.returnValues(); int diffFromGeneration = answer.get(0).asInt32(); @@ -279,7 +290,10 @@ public class Mirror implements IMirror { newSpecs[idx++] = e; } } - + if (logOnSuccess) { + log.log(Level.INFO, "successfully connected to location broker "+currSlobrok+" (mirror initialized with "+newSpecs.length+" service names)"); + logOnSuccess = false; + } specs.set(newSpecs); specsGeneration = diffToGeneration; diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/Register.java b/jrt/src/com/yahoo/jrt/slobrok/api/Register.java index 713cecc62d1..0da390f8bf6 100644 --- a/jrt/src/com/yahoo/jrt/slobrok/api/Register.java +++ b/jrt/src/com/yahoo/jrt/slobrok/api/Register.java @@ -181,6 +181,7 @@ public class Register { reqDone = false; boolean logOnSuccess = false; + boolean logOnFailure = true; synchronized (this) { if (req.methodName().equals(UNREGISTER_METHOD_NAME)) { logOnSuccess = true; @@ -191,16 +192,21 @@ public class Register { lastRegisterSucceeded.remove(name); } else { final Boolean lastSucceeded = lastRegisterSucceeded.get(name); - if (lastSucceeded == null || lastSucceeded != !req.isError()) { + if (lastSucceeded == null) { + logOnSuccess = true; + logOnFailure = false; + } else if (lastSucceeded != !req.isError()) { logOnSuccess = true; - lastRegisterSucceeded.put(name, !req.isError()); } + lastRegisterSucceeded.put(name, !req.isError()); } } if (req.isError()) { if (req.errorCode() != ErrorCode.METHOD_FAILED) { - log.log(Level.INFO, logMessagePrefix() + " failed, will disconnect: " + req.errorMessage() + " (code " + req.errorCode() + ")"); + if (logOnFailure) { + log.log(Level.INFO, logMessagePrefix() + " failed, will disconnect: " + req.errorMessage() + " (code " + req.errorCode() + ")"); + } target.close(); target = null; } else { @@ -210,7 +216,6 @@ public class Register { log.log(logOnSuccess ? Level.INFO : Level.FINE, logMessagePrefix() + " completed successfully"); backOff.reset(); } - req = null; name = null; } @@ -219,7 +224,7 @@ public class Register { return; // current request still in progress } if (target != null && ! slobroks.contains(currSlobrok)) { - log.log(Level.INFO, "RPC server " + mySpec + ": Slobrok server " + currSlobrok + " removed, will disconnect"); + log.log(Level.INFO, "[RPC @ " + mySpec + "] location broker " + currSlobrok + " removed, will disconnect and use one of: "+slobroks); target.close(); target = null; } @@ -227,9 +232,10 @@ public class Register { currSlobrok = slobroks.nextSlobrokSpec(); if (currSlobrok == null) { double delay = backOff.get(); - Level level = backOff.shouldWarn(delay) ? Level.WARNING : Level.FINE; - log.log(level, "RPC server " + mySpec + ": All Slobrok servers tried, will retry in " + delay - + " seconds: " + slobroks); + Level level = Level.FINE; + if (backOff.shouldInform(delay)) level = Level.INFO; + if (backOff.shouldWarn(delay)) level = Level.WARNING; + log.log(level, "[RPC @ " + mySpec + "] no location brokers available, retrying: "+slobroks+" (in " + delay + " seconds)"); updateTask.schedule(delay); return; } @@ -247,8 +253,8 @@ public class Register { } if (logFine) { - log.log(Level.FINE, "RPC server " + mySpec + ": Connect to Slobrok server " + currSlobrok + - " and reregister all Slobrok names: " + namesString); + log.log(Level.FINE, "[RPC @ " + mySpec + "] Connect to location broker " + currSlobrok + + " and reregister all service names: " + namesString); } } @@ -261,7 +267,7 @@ public class Register { req = new Request(REGISTER_METHOD_NAME); } else { pending.addAll(names); - log.log(Level.FINE, "RPC server " + mySpec + ": Reregister all Slobrok names in 30 seconds: " + names); + log.log(Level.FINE, "[RPC @ " + mySpec + "] Reregister all service names in 30 seconds: " + names); updateTask.schedule(30.0); return; } @@ -274,9 +280,9 @@ public class Register { } private String logMessagePrefix() { - return "RPC server " + mySpec - + (req.methodName().equals(UNREGISTER_METHOD_NAME) ? " unregistering " : " registering ") - + name + " with Slobrok server " + currSlobrok; + return "[RPC @ " + mySpec + "] " + + (req.methodName().equals(UNREGISTER_METHOD_NAME) ? "unregistering " : "registering ") + + name + " with location broker " + currSlobrok; } private synchronized void handleRpcList(Request req) { diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java b/jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java index b524c25d8ff..10d8923d9f5 100644 --- a/jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java +++ b/jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java @@ -48,7 +48,7 @@ public class SlobrokList { public boolean contains(String slobrok) { checkUpdate(); for (String s : slobroks) { - if (s == slobrok) return true; + if (s.equals(slobrok)) return true; } return false; } -- cgit v1.2.3