Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

core: ChannelLogger #5024

Merged
merged 11 commits into from Nov 7, 2018

Rename Level to ChannelLogLevel; Add formatter method and skip log ge…

…neration for DEBUG if not logged.
  • Loading branch information...
zhangkun83 committed Nov 5, 2018
commit 6c4c62ffd0607a723c3c2742ea6391a9f589cc0c
@@ -18,8 +18,10 @@

/**
* A Channel-specific logger provided by GRPC library to {@link LoadBalancer} implementations.
* Information logged here goes to <string>Channelz</strong>, and to Java logger as well.
* Information logged here goes to <string>Channelz</strong>, and to the Java logger of this class
* as well.
*/
@ExperimentalApi("https://github.com/grpc/grpc-java/issues/5029")
public abstract class ChannelLogger {

This comment has been minimized.

Copy link
@carl-mastrangelo

carl-mastrangelo Nov 2, 2018

Contributor

is this threadsafe?

This comment has been minimized.

Copy link
@zhangkun83

zhangkun83 Nov 5, 2018

Author Contributor

Yes. Added annotation.

/**
* Log levels. See the table below for the mapping from the ChannelLogger levels to Channelz
@@ -37,15 +39,21 @@
* +---------------------+-------------------+-------------------+
* </pre>
*/
public enum Level {
public enum ChannelLogLevel {
DEBUG,
INFO,
WARNING,
ERROR
}

/**
* Logs a message, which is exported on Channelz as well as the Java logger for this class.
* Logs a message.
*/
public abstract void log(Level level, String message);
public abstract void log(ChannelLogLevel level, String message);

/**
* Logs a message, using a message template and a list of arguments used to generate the log
* message with {@link String#format}.
*/
public abstract void log(ChannelLogLevel level, String template, Object... args);

This comment has been minimized.

Copy link
@carl-mastrangelo

carl-mastrangelo Nov 5, 2018

Contributor

Isn't this format different than what normal loggers use? (i.e. {}) ?

I think this should be something that fits in with other, similar log statements. (I.e. it should do what SimpleFormatter does)

This comment has been minimized.

Copy link
@ejona86

ejona86 Nov 6, 2018

Member

It should use MessageFormat.

This comment has been minimized.

Copy link
@zhangkun83

zhangkun83 Nov 6, 2018

Author Contributor

Used MessageFormat. PTAL.

}
@@ -19,7 +19,7 @@
import com.google.common.annotations.VisibleForTesting;
import com.google.common.base.Ascii;
import io.grpc.Attributes;
import io.grpc.ChannelLogger.Level;
import io.grpc.ChannelLogger.ChannelLogLevel;
import io.grpc.ConnectivityState;
import io.grpc.ConnectivityStateInfo;
import io.grpc.EquivalentAddressGroup;
@@ -98,9 +98,8 @@ public void handleResolvedAddressGroups(
LoadBalancer old = delegate;
delegate = delegateProvider.newLoadBalancer(helper);
helper.getChannelLogger().log(
Level.INFO,
"Load balancer changed from " + old.getClass().getSimpleName()
+ " to " + delegate.getClass().getSimpleName());
ChannelLogLevel.INFO, "Load balancer changed from %s to %s",
old.getClass().getSimpleName(), delegate.getClass().getSimpleName());
}
getDelegate().handleResolvedAddressGroups(servers, attributes);
}
@@ -21,6 +21,7 @@
import io.grpc.ChannelLogger;
import io.grpc.InternalChannelz.ChannelTrace.Event;
import io.grpc.InternalChannelz.ChannelTrace.Event.Severity;
import java.util.logging.Level;

final class ChannelLoggerImpl extends ChannelLogger {
private final ChannelTracer tracer;
@@ -32,19 +33,36 @@
}

@Override
public void log(Level level, String msg) {
if (level == Level.DEBUG) {
tracer.logOnly(java.util.logging.Level.FINEST, msg);
public void log(ChannelLogLevel level, String msg) {
if (level == ChannelLogLevel.DEBUG) {
tracer.logOnly(Level.FINEST, msg);
} else {
tracer.reportEvent(new Event.Builder()
.setDescription(msg)
.setSeverity(toTracerSeverity(level))
.setTimestampNanos(time.currentTimeNanos())
.build());
reportToTracer(level, msg);
}
}

private Severity toTracerSeverity(Level level) {
@Override
public void log(ChannelLogLevel level, String template, Object... args) {
if (level == ChannelLogLevel.DEBUG) {
// DEBUG logs can be expensive to generate (e.g., large proto messages), and when not logged,
// go nowhere. We will skip the generation if it's not logged.
if (ChannelTracer.logger.isLoggable(Level.FINEST)) {
tracer.logOnly(Level.FINEST, String.format(template, args));
}
} else {
reportToTracer(level, String.format(template, args));
}
}

private void reportToTracer(ChannelLogLevel level, String msg) {
tracer.reportEvent(new Event.Builder()
.setDescription(msg)
.setSeverity(toTracerSeverity(level))
.setTimestampNanos(time.currentTimeNanos())
.build());
}

private Severity toTracerSeverity(ChannelLogLevel level) {
switch (level) {
case ERROR:
return Severity.CT_ERROR;
@@ -38,7 +38,7 @@
final class ChannelTracer {
// The logs go to ChannelLogger's logger so that user can control the logging level on that public
// class rather than on this internal class.
private static final Logger logger = Logger.getLogger(ChannelLogger.class.getName());
static final Logger logger = Logger.getLogger(ChannelLogger.class.getName());
private final Object lock = new Object();
private final InternalLogId logId;
@GuardedBy("lock")
@@ -33,7 +33,7 @@
import io.grpc.Attributes;
import io.grpc.CallOptions;
import io.grpc.ChannelLogger;
import io.grpc.ChannelLogger.Level;
import io.grpc.ChannelLogger.ChannelLogLevel;
import io.grpc.ConnectivityState;
import io.grpc.ConnectivityStateInfo;
import io.grpc.EquivalentAddressGroup;
@@ -54,6 +54,7 @@
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.ScheduledFuture;
import java.util.concurrent.TimeUnit;
import java.util.logging.Level;
import java.util.logging.Logger;
import javax.annotation.Nullable;
import javax.annotation.concurrent.GuardedBy;
@@ -211,7 +212,7 @@ ClientTransport obtainActiveTransport() {
return savedTransport;
}
if (state.getState() == IDLE) {
channelLogger.log(Level.INFO, "CONNECTING as requested");
channelLogger.log(ChannelLogLevel.INFO, "CONNECTING as requested");
gotoNonErrorState(CONNECTING);
startNewTransport();
}
@@ -288,14 +289,14 @@ public void run() {
// started when it's being canceled.
return;
}
channelLogger.log(Level.INFO, "CONNECTING after backoff");
channelLogger.log(ChannelLogLevel.INFO, "CONNECTING after backoff");
gotoNonErrorState(CONNECTING);
startNewTransport();
}
} catch (Throwable t) {
// TODO(zhangkun): we may consider using SynchronizationContext to schedule the reconnect
// timer, so that we don't need this catch, since SynchronizationContext would catch it.
log.log(java.util.logging.Level.WARNING, "Exception handling end of backoff", t);
log.log(Level.WARNING, "Exception handling end of backoff", t);
} finally {
syncContext.drain();
}
@@ -309,9 +310,8 @@ public void run() {
long delayNanos =
reconnectPolicy.nextBackoffNanos() - connectingTimer.elapsed(TimeUnit.NANOSECONDS);
channelLogger.log(
Level.INFO,
"TRANSIENT_FAILURE (" + printShortStatus(status) + "). Will reconnect after "
+ delayNanos + "ns");
ChannelLogLevel.INFO,
"TRANSIENT_FAILURE (%s). Will reconnect after %s ns", printShortStatus(status), delayNanos);
Preconditions.checkState(reconnectTask == null, "previous reconnectTask is not done");
reconnectCanceled = false;
reconnectTask = scheduledExecutor.schedule(
@@ -331,7 +331,7 @@ void resetConnectBackoff() {
return;
}
cancelReconnectTask();
channelLogger.log(Level.INFO, "CONNECTING; backoff interrupted");
channelLogger.log(ChannelLogLevel.INFO, "CONNECTING; backoff interrupted");
gotoNonErrorState(CONNECTING);
startNewTransport();
}
@@ -446,7 +446,7 @@ public String toString() {

@GuardedBy("lock")
private void handleTermination() {
channelLogger.log(Level.INFO, "Terminated");
channelLogger.log(ChannelLogLevel.INFO, "Terminated");
syncContext.executeLater(new Runnable() {
@Override
public void run() {
@@ -555,7 +555,7 @@ private static void checkListHasNoNulls(List<?> list, String msg) {

@Override
public void transportReady() {
channelLogger.log(Level.INFO, "READY");
channelLogger.log(ChannelLogLevel.INFO, "READY");
Status savedShutdownReason;
try {
synchronized (lock) {
@@ -587,7 +587,7 @@ public void transportInUse(boolean inUse) {
@Override
public void transportShutdown(Status s) {
channelLogger.log(
Level.INFO, transport.getLogId() + " SHUTDOWN with " + printShortStatus(s));
ChannelLogLevel.INFO, "%s SHUTDOWN with %s", transport.getLogId(), printShortStatus(s));
try {
synchronized (lock) {
if (state.getState() == SHUTDOWN) {
@@ -620,7 +620,7 @@ public void transportShutdown(Status s) {

@Override
public void transportTerminated() {
channelLogger.log(Level.INFO, transport.getLogId() + " Terminated");
channelLogger.log(ChannelLogLevel.INFO, "%s Terminated", transport.getLogId());
channelz.removeClientSocket(transport);
handleTransportInUseState(transport, false);
try {
@@ -35,7 +35,7 @@
import io.grpc.CallOptions;
import io.grpc.Channel;
import io.grpc.ChannelLogger;
import io.grpc.ChannelLogger.Level;
import io.grpc.ChannelLogger.ChannelLogLevel;
import io.grpc.ClientCall;
import io.grpc.ClientInterceptor;
import io.grpc.ClientInterceptors;
@@ -84,6 +84,7 @@
import java.util.concurrent.TimeUnit;
import java.util.concurrent.TimeoutException;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.regex.Pattern;
import javax.annotation.CheckForNull;
@@ -139,7 +140,7 @@
@Override
public void uncaughtException(Thread t, Throwable e) {
logger.log(
java.util.logging.Level.SEVERE,
Level.SEVERE,
"[" + getLogId() + "] Uncaught exception in the SynchronizationContext. Panic!",
e);
panic(e);
@@ -345,7 +346,7 @@ void exitIdleMode() {
if (lbHelper != null) {
return;
}
channelLogger.log(Level.INFO, "Exiting idle mode");
channelLogger.log(ChannelLogLevel.INFO, "Exiting idle mode");
lbHelper = new LbHelperImpl(nameResolver);
lbHelper.lb = loadBalancerFactory.newLoadBalancer(lbHelper);

@@ -367,7 +368,7 @@ private void enterIdleMode() {
shutdownNameResolverAndLoadBalancer(true);
delayedTransport.reprocess(null);
nameResolver = getNameResolver(target, nameResolverFactory, nameResolverParams);
channelLogger.log(Level.INFO, "Entering IDLE state");
channelLogger.log(ChannelLogLevel.INFO, "Entering IDLE state");
channelStateManager.gotoState(IDLE);
if (inUseStateAggregator.isInUse()) {
exitIdleMode();
@@ -650,7 +651,7 @@ static NameResolver getNameResolver(String target, NameResolver.Factory nameReso
*/
@Override
public ManagedChannelImpl shutdown() {
channelLogger.log(Level.DEBUG, "shutdown() called");
channelLogger.log(ChannelLogLevel.DEBUG, "shutdown() called");
if (!shutdown.compareAndSet(false, true)) {
return this;
}
@@ -662,7 +663,7 @@ public ManagedChannelImpl shutdown() {
final class Shutdown implements Runnable {
@Override
public void run() {
channelLogger.log(Level.INFO, "Entering SHUTDOWN state");
channelLogger.log(ChannelLogLevel.INFO, "Entering SHUTDOWN state");
channelStateManager.gotoState(SHUTDOWN);
}
}
@@ -688,7 +689,7 @@ public void run() {
*/
@Override
public ManagedChannelImpl shutdownNow() {
channelLogger.log(Level.DEBUG, "shutdownNow() called");
channelLogger.log(ChannelLogLevel.DEBUG, "shutdownNow() called");
shutdown();
uncommittedRetriableStreamsRegistry.onShutdownNow(SHUTDOWN_NOW_STATUS);
final class ShutdownNow implements Runnable {
@@ -728,7 +729,7 @@ public PickResult pickSubchannel(PickSubchannelArgs args) {
}

updateSubchannelPicker(new PanicSubchannelPicker());
channelLogger.log(Level.ERROR, "PANIC! Entering TRANSIENT_FAILURE");
channelLogger.log(ChannelLogLevel.ERROR, "PANIC! Entering TRANSIENT_FAILURE");
channelStateManager.gotoState(TRANSIENT_FAILURE);
}

@@ -815,7 +816,7 @@ private void maybeTerminateChannel() {
return;
}
if (shutdown.get() && subchannels.isEmpty() && oobChannels.isEmpty()) {
channelLogger.log(Level.INFO, "Terminated");
channelLogger.log(ChannelLogLevel.INFO, "Terminated");
channelz.removeRootChannel(this);
terminated = true;
terminatedLatch.countDown();
@@ -1002,7 +1003,7 @@ public AbstractSubchannel createSubchannel(
try {
syncContext.throwIfNotInThisSynchronizationContext();
} catch (IllegalStateException e) {
logger.log(java.util.logging.Level.WARNING,
logger.log(Level.WARNING,
"We sugguest you call createSubchannel() from SynchronizationContext."
+ " Otherwise, it may race with handleSubchannelState()."
+ " See https://github.com/grpc/grpc-java/issues/5015", e);
@@ -1110,7 +1111,7 @@ public void run() {
// It's not appropriate to report SHUTDOWN state from lb.
// Ignore the case of newState == SHUTDOWN for now.
if (newState != SHUTDOWN) {
channelLogger.log(Level.INFO, "Entering " + newState + " state");
channelLogger.log(ChannelLogLevel.INFO, "Entering %s state", newState);
channelStateManager.gotoState(newState);
}
}
@@ -1251,16 +1252,16 @@ public void onAddresses(final List<EquivalentAddressGroup> servers, final Attrib
"Name resolver " + helper.nr + " returned an empty list"));
return;
}
channelLogger.log(Level.DEBUG, "Resolved address: " + servers + ", config=" + config);
channelLogger.log(ChannelLogLevel.DEBUG, "Resolved address: %s, config=%s", servers, config);

if (haveBackends == null || !haveBackends) {
channelLogger.log(Level.INFO, "Address resolved: " + servers);
channelLogger.log(ChannelLogLevel.INFO, "Address resolved: %s", servers);
haveBackends = true;
}
final Map<String, Object> serviceConfig =
config.get(GrpcAttributes.NAME_RESOLVER_SERVICE_CONFIG);
if (serviceConfig != null && !serviceConfig.equals(lastServiceConfig)) {
channelLogger.log(Level.INFO, "Service config changed");
channelLogger.log(ChannelLogLevel.INFO, "Service config changed");
lastServiceConfig = serviceConfig;
}

@@ -1282,7 +1283,7 @@ public void run() {
}
} catch (RuntimeException re) {
logger.log(
java.util.logging.Level.WARNING,
Level.WARNING,
"[" + getLogId() + "] Unexpected exception from parsing service config",
re);
}
@@ -1298,10 +1299,10 @@ public void run() {
@Override
public void onError(final Status error) {
checkArgument(!error.isOk(), "the error status must not be OK");
logger.log(java.util.logging.Level.WARNING, "[{0}] Failed to resolve name. status={1}",
logger.log(Level.WARNING, "[{0}] Failed to resolve name. status={1}",
new Object[] {getLogId(), error});
if (haveBackends == null || haveBackends) {
channelLogger.log(Level.WARNING, "Failed to resolve name: " + error);
channelLogger.log(ChannelLogLevel.WARNING, "Failed to resolve name: %s", error);
haveBackends = false;
}
final class NameResolverErrorHandler implements Runnable {
@@ -1324,8 +1325,8 @@ public void run() {
}
long delayNanos = nameResolverBackoffPolicy.nextBackoffNanos();
channelLogger.log(
Level.DEBUG,
"Scheduling DNS resolution backoff for " + delayNanos + "ns");
ChannelLogLevel.DEBUG,
"Scheduling DNS resolution backoff for %s ns", delayNanos);
nameResolverRefresh = new NameResolverRefresh();
nameResolverRefreshFuture =
transportFactory
ProTip! Use n and p to navigate between commits in a pull request.
You can’t perform that action at this time.