diff --git a/java/google/registry/proxy/BUILD b/java/google/registry/proxy/BUILD index c921dcc36..28ab60bdd 100644 --- a/java/google/registry/proxy/BUILD +++ b/java/google/registry/proxy/BUILD @@ -21,6 +21,9 @@ java_library( "//java/google/registry/config", "//java/google/registry/util", "@com_beust_jcommander", + "@com_fasterxml_jackson_core", + "@com_fasterxml_jackson_core_jackson_annotations", + "@com_fasterxml_jackson_core_jackson_databind", "@com_google_api_client", "@com_google_apis_google_api_services_cloudkms", "@com_google_apis_google_api_services_monitoring", diff --git a/java/google/registry/proxy/EppProtocolModule.java b/java/google/registry/proxy/EppProtocolModule.java index 499675642..2a6edeb03 100644 --- a/java/google/registry/proxy/EppProtocolModule.java +++ b/java/google/registry/proxy/EppProtocolModule.java @@ -39,7 +39,6 @@ import io.netty.channel.ChannelHandler; import io.netty.channel.socket.nio.NioSocketChannel; import io.netty.handler.codec.LengthFieldBasedFrameDecoder; import io.netty.handler.codec.LengthFieldPrepender; -import io.netty.handler.logging.LoggingHandler; import io.netty.handler.timeout.ReadTimeoutHandler; import java.io.IOException; import java.util.concurrent.ExecutorService; @@ -87,7 +86,6 @@ public class EppProtocolModule { Provider lengthFieldPrependerProvider, Provider eppServiceHandlerProvider, Provider eppQuotaHandlerProvider, - Provider loggingHandlerProvider, Provider relayHandlerProvider) { return ImmutableList.of( proxyProtocolHandlerProvider, @@ -97,7 +95,6 @@ public class EppProtocolModule { lengthFieldPrependerProvider, eppServiceHandlerProvider, eppQuotaHandlerProvider, - loggingHandlerProvider, relayHandlerProvider); } diff --git a/java/google/registry/proxy/GcpJsonFormatter.java b/java/google/registry/proxy/GcpJsonFormatter.java new file mode 100644 index 000000000..e7b2d391f --- /dev/null +++ b/java/google/registry/proxy/GcpJsonFormatter.java @@ -0,0 +1,138 @@ +// Copyright 2017 The Nomulus Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package google.registry.proxy; + +import com.fasterxml.jackson.annotation.JsonProperty; +import com.fasterxml.jackson.core.JsonProcessingException; +import com.fasterxml.jackson.databind.ObjectMapper; +import com.google.auto.value.AutoValue; +import java.io.PrintWriter; +import java.io.StringWriter; +import java.util.logging.Formatter; +import java.util.logging.Level; +import java.util.logging.LogRecord; + +/** + * JUL formatter that formats log messages in a single-line JSON that Stackdriver logging can parse. + * + *

There is no clear documentation on how to achieve this or on the format of the JSON. This is + * much a trial and error process, plus a lot of searching. To summarize, if the logs are printed to + * {@code STDOUT} or {@code STDERR} in a single-line JSON, with the content in the {@code message} + * field and the log level in the {@code severity} field, it will be picked up by Stackdriver + * logging agent running in GKE containers and logged at correct level.. + * + * @see + * Formatting Python Logs from Stackdriver + * GKE & Stackdriver: Java logback logging format? + */ +class GcpJsonFormatter extends Formatter { + + private static final ObjectMapper MAPPER = new ObjectMapper(); + + @Override + public String format(LogRecord record) { + try { + return MAPPER.writeValueAsString(LogEvent.create(record)) + "\n"; + } catch (JsonProcessingException e) { + throw new RuntimeException(e); + } + } + + @AutoValue + abstract static class LogEvent { + + /** Field that determines the log level. */ + @JsonProperty("severity") + abstract String severity(); + + /** + * Field that stores the calling class and function when the log occurs. + * + *

This field is not used by Stackdriver, but it is useful and can be found when the log + * entries are expanded + */ + @JsonProperty("source") + abstract String source(); + + /** Field that contains the content, this will show up as the main entry in a log. */ + @JsonProperty("message") + abstract String message(); + + static LogEvent create(LogRecord record) { + // Add an extra newline before the message. Stackdriver does not show newlines correctly, and + // treats them as whitespace. If you want to see correctly formatted log message, expand the + // log and look for the jsonPayload.message field. This newline makes sure that the entire + // message starts on its own line, so that indentation within the message is correct. + + String message = "\n" + record.getMessage(); + Level level = record.getLevel(); + // See + // https://github.com/GoogleCloudPlatform/google-cloud-java/blob/master/google-cloud-logging/src/main/java/com/google/cloud/logging/Severity.java + // on how {@code Level} is mapped to severity. + String severity; + switch (level.intValue()) { + // FINEST + case 300: + // FINER + case 400: + // FINE + case 500: + severity = "DEBUG"; + break; + // CONFIG + case 700: + // INFO + case 800: + severity = "INFO"; + break; + // WARNING + case 900: + severity = "WARNING"; + break; + // SEVERE + case 1000: + severity = "ERROR"; + break; + default: + severity = "DEFAULT"; + } + + // The rest is mostly lifted from java.util.logging.SimpleFormatter. + String stacktrace = ""; + if (record.getThrown() != null) { + StringWriter sw = new StringWriter(); + try (PrintWriter pw = new PrintWriter(sw)) { + pw.println(); + record.getThrown().printStackTrace(pw); + } + stacktrace = sw.toString(); + } + + String source; + if (record.getSourceClassName() != null) { + source = record.getSourceClassName(); + if (record.getSourceMethodName() != null) { + source += " " + record.getSourceMethodName(); + } + } else { + source = record.getLoggerName(); + } + + return new AutoValue_GcpJsonFormatter_LogEvent(severity, source, message + stacktrace); + } + } +} diff --git a/java/google/registry/proxy/ProxyModule.java b/java/google/registry/proxy/ProxyModule.java index 70ad5ea5a..14b77ff34 100644 --- a/java/google/registry/proxy/ProxyModule.java +++ b/java/google/registry/proxy/ProxyModule.java @@ -28,9 +28,9 @@ import com.google.api.services.cloudkms.v1.CloudKMS; import com.google.api.services.cloudkms.v1.model.DecryptRequest; import com.google.common.base.Optional; import com.google.common.base.Supplier; -import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; import com.google.common.collect.Maps; +import com.google.monitoring.metrics.MetricReporter; import dagger.Component; import dagger.Module; import dagger.Provides; @@ -42,11 +42,12 @@ import google.registry.proxy.WhoisProtocolModule.WhoisProtocol; import google.registry.util.Clock; import google.registry.util.FormattingLogger; import google.registry.util.SystemClock; +import io.netty.handler.logging.LogLevel; import io.netty.handler.logging.LoggingHandler; import io.netty.handler.ssl.OpenSsl; import io.netty.handler.ssl.SslProvider; import java.io.IOException; -import java.util.Objects; +import java.util.Arrays; import java.util.Set; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; @@ -83,28 +84,27 @@ public class ProxyModule { boolean log; /** - * Enable FINE level logging. + * Configure logging parameters depending on the {@link Environment}. * - *

Set the loggers log level to {@code FINE}, and also add a console handler that actually - * output {@code FINE} level messages to stdout. The handler filters out all non FINE level log - * record to avoid double logging. Log records at level higher than FINE (e. g. INFO) will be - * handled at parent loggers. Note that {@code FINE} level corresponds to {@code DEBUG} level in - * Netty. + *

If not running locally, set the logging formatter to {@link GcpJsonFormatter} that formats + * the log in a single-line json string printed to {@code STDOUT} or {@code STDERR}, will be + * correctly parsed by Stackdriver logging. + * + * @see + * Logging Best Practices */ - private static void enableDebugLevelLogging() { - ImmutableList parentLoggers = - ImmutableList.of( - Logger.getLogger("io.netty.handler.logging.LoggingHandler"), - // Parent of all FormattingLoggers, so that we do not have to configure each - // FormattingLogger individually. - Logger.getLogger("google.registry.proxy")); - for (Logger logger : parentLoggers) { - logger.setLevel(Level.FINE); - Handler handler = new ConsoleHandler(); - handler.setFilter(record -> Objects.equals(record.getLevel(), Level.FINE)); - handler.setLevel(Level.FINE); - logger.addHandler(handler); + private void configureLogging() { + // Remove all other handlers on the root logger to avoid double logging. + Logger rootLogger = Logger.getLogger(""); + Arrays.asList(rootLogger.getHandlers()).forEach(h -> rootLogger.removeHandler(h)); + + // If running on in a non-local environment, use GCP JSON formater. + Handler rootHandler = new ConsoleHandler(); + rootHandler.setLevel(Level.FINE); + if (env != Environment.LOCAL) { + rootHandler.setFormatter(new GcpJsonFormatter()); } + rootLogger.addHandler(rootHandler); } /** @@ -122,10 +122,7 @@ public class ProxyModule { jCommander.usage(); throw e; } - if (log) { - logger.info("DEBUG LOGGING: ENABLED"); - enableDebugLevelLogging(); - } + configureLogging(); return this; } @@ -158,11 +155,23 @@ public class ProxyModule { return env; } - /** Shared logging handler, set to default DEBUG(FINE) level. */ + /** + * Provides shared logging handler. + * + *

The {@link LoggingHandler} records logs at {@code LogLevel.DEBUG} (internal Netty log + * level), which corresponds to {@code Level.FINE} (JUL log level). It uses a JUL logger called + * {@code io.netty.handler.logging.LoggingHandler} to actually process the logs. This logger is + * set to {@code Level.FINE} if {@code --log} parameter is passed, so that it does not filter out + * logs that the {@link LoggingHandler} captures. Otherwise the logs are silently ignored because + * the default logger level is {@code Level.INFO}. + */ @Singleton @Provides - static LoggingHandler provideLoggingHandler() { - return new LoggingHandler(); + LoggingHandler provideLoggingHandler() { + if (log) { + Logger.getLogger("io.netty.handler.logging.LoggingHandler").setLevel(Level.FINE); + } + return new LoggingHandler(LogLevel.DEBUG); } @Singleton @@ -308,10 +317,14 @@ public class ProxyModule { HttpsRelayProtocolModule.class, WhoisProtocolModule.class, EppProtocolModule.class, - HealthCheckProtocolModule.class + HealthCheckProtocolModule.class, + MetricsModule.class } ) interface ProxyComponent { + ImmutableMap portToProtocolMap(); + + MetricReporter metricReporter(); } } diff --git a/java/google/registry/proxy/ProxyServer.java b/java/google/registry/proxy/ProxyServer.java index 6524ba673..59edcd1c6 100644 --- a/java/google/registry/proxy/ProxyServer.java +++ b/java/google/registry/proxy/ProxyServer.java @@ -51,8 +51,7 @@ import javax.inject.Provider; public class ProxyServer implements Runnable { private static final FormattingLogger logger = FormattingLogger.getLoggerForCallerClass(); - private static final MetricReporter metricReporter = - DaggerMetricsModule_MetricsComponent.create().metricReporter(); + /** Maximum length of the queue of incoming connections. */ private static final int MAX_SOCKET_BACKLOG = 128; @@ -211,6 +210,14 @@ public class ProxyServer implements Runnable { // which is what google.registry.util.FormattingLog uses under the hood. InternalLoggerFactory.setDefaultFactory(JdkLoggerFactory.INSTANCE); + // Configure the components, this needs to run first so that the logging format is properly + // configured for each environment. + ProxyComponent proxyComponent = + DaggerProxyModule_ProxyComponent.builder() + .proxyModule(new ProxyModule().parse(args)) + .build(); + + MetricReporter metricReporter = proxyComponent.metricReporter(); try { metricReporter.startAsync().awaitRunning(10, TimeUnit.SECONDS); logger.info("Started up MetricReporter"); @@ -226,14 +233,10 @@ public class ProxyServer implements Runnable { metricReporter.stopAsync().awaitTerminated(10, TimeUnit.SECONDS); logger.info("Shut down MetricReporter"); } catch (TimeoutException timeoutException) { - logger.severefmt("Failed to stop MetricReporter: %s", timeoutException); + logger.warningfmt("Failed to stop MetricReporter: %s", timeoutException); } })); - ProxyComponent proxyComponent = - DaggerProxyModule_ProxyComponent.builder() - .proxyModule(new ProxyModule().parse(args)) - .build(); new ProxyServer(proxyComponent).run(); } } diff --git a/java/google/registry/proxy/WhoisProtocolModule.java b/java/google/registry/proxy/WhoisProtocolModule.java index 6df29cee0..94f3aa0fd 100644 --- a/java/google/registry/proxy/WhoisProtocolModule.java +++ b/java/google/registry/proxy/WhoisProtocolModule.java @@ -33,7 +33,6 @@ import google.registry.proxy.quota.TokenStore; import google.registry.util.Clock; import io.netty.channel.ChannelHandler; import io.netty.handler.codec.LineBasedFrameDecoder; -import io.netty.handler.logging.LoggingHandler; import io.netty.handler.timeout.ReadTimeoutHandler; import java.util.concurrent.ExecutorService; import java.util.concurrent.ScheduledExecutorService; @@ -76,7 +75,6 @@ public class WhoisProtocolModule { Provider lineBasedFrameDecoderProvider, Provider whoisServiceHandlerProvider, Provider whoisQuotaHandlerProvider, - Provider loggingHandlerProvider, Provider relayHandlerProvider) { return ImmutableList.of( proxyProtocolHandlerProvider, @@ -84,7 +82,6 @@ public class WhoisProtocolModule { lineBasedFrameDecoderProvider, whoisServiceHandlerProvider, whoisQuotaHandlerProvider, - loggingHandlerProvider, relayHandlerProvider); } diff --git a/java/google/registry/proxy/handler/ProxyProtocolHandler.java b/java/google/registry/proxy/handler/ProxyProtocolHandler.java index 58275e696..dfa06c3f0 100644 --- a/java/google/registry/proxy/handler/ProxyProtocolHandler.java +++ b/java/google/registry/proxy/handler/ProxyProtocolHandler.java @@ -17,7 +17,6 @@ package google.registry.proxy.handler; import static com.google.common.base.Preconditions.checkState; import static java.nio.charset.StandardCharsets.US_ASCII; -import google.registry.util.FormattingLogger; import io.netty.buffer.ByteBuf; import io.netty.channel.ChannelHandlerContext; import io.netty.handler.codec.ByteToMessageDecoder; @@ -56,8 +55,6 @@ public class ProxyProtocolHandler extends ByteToMessageDecoder { public static final AttributeKey REMOTE_ADDRESS_KEY = AttributeKey.valueOf("REMOTE_ADDRESS_KEY"); - private static final FormattingLogger logger = FormattingLogger.getLoggerForCallerClass(); - // The proxy header must start with this prefix. // Sample header: "PROXY TCP4 255.255.255.255 255.255.255.255 65535 65535\r\n". private static final byte[] HEADER_PREFIX = "PROXY".getBytes(US_ASCII); @@ -73,8 +70,6 @@ public class ProxyProtocolHandler extends ByteToMessageDecoder { super.channelRead(ctx, msg); if (finished) { if (proxyHeader != null) { - logger.finefmt("PROXIED CONNECTION: %s", ctx.channel()); - logger.finefmt("PROXY HEADER: %s", proxyHeader); ctx.channel().attr(REMOTE_ADDRESS_KEY).set(proxyHeader.split(" ")[2]); } else { SocketAddress remoteAddress = ctx.channel().remoteAddress(); @@ -82,7 +77,6 @@ public class ProxyProtocolHandler extends ByteToMessageDecoder { ctx.channel() .attr(REMOTE_ADDRESS_KEY) .set(((InetSocketAddress) remoteAddress).getAddress().getHostAddress()); - logger.finefmt("REMOTE IP ADDRESS: %s", ctx.channel().attr(REMOTE_ADDRESS_KEY).get()); } } ctx.pipeline().remove(this); diff --git a/java/google/registry/proxy/handler/SslClientInitializer.java b/java/google/registry/proxy/handler/SslClientInitializer.java index 4335ed685..419c06aab 100644 --- a/java/google/registry/proxy/handler/SslClientInitializer.java +++ b/java/google/registry/proxy/handler/SslClientInitializer.java @@ -53,7 +53,7 @@ public class SslClientInitializer extends ChannelInitializer< SslClientInitializer( SslProvider sslProvider, @Nullable @Named("relayTrustedCertificates") X509Certificate... trustCertificates) { - logger.finefmt("Client SSL Provider: %s", sslProvider); + logger.infofmt("Client SSL Provider: %s", sslProvider); this.sslProvider = sslProvider; this.trustedCertificates = trustCertificates; } diff --git a/java/google/registry/proxy/handler/SslServerInitializer.java b/java/google/registry/proxy/handler/SslServerInitializer.java index a99907612..a7b54acdb 100644 --- a/java/google/registry/proxy/handler/SslServerInitializer.java +++ b/java/google/registry/proxy/handler/SslServerInitializer.java @@ -68,7 +68,7 @@ public class SslServerInitializer extends ChannelInitializer< SslProvider sslProvider, PrivateKey privateKey, @Named("eppServerCertificates") X509Certificate... certificates) { - logger.finefmt("Server SSL Provider: %s", sslProvider); + logger.infofmt("Server SSL Provider: %s", sslProvider); this.sslProvider = sslProvider; this.privateKey = privateKey; this.certificates = certificates; diff --git a/java/google/registry/proxy/kubernetes/proxy-autoscale.yaml b/java/google/registry/proxy/kubernetes/proxy-autoscale.yaml new file mode 100644 index 000000000..b42d81217 --- /dev/null +++ b/java/google/registry/proxy/kubernetes/proxy-autoscale.yaml @@ -0,0 +1,13 @@ +apiVersion: autoscaling/v2beta1 +kind: HorizontalPodAutoscaler +metadata: + name: proxy-autoscale + labels: + app: proxy +spec: + scaleTargetRef: + apiVersion: extensions/v1beta1 + kind: Deployment + name: proxy-deployment + maxReplicas: 5 + minReplicas: 1 diff --git a/java/google/registry/proxy/kubernetes/proxy-deployment.yaml b/java/google/registry/proxy/kubernetes/proxy-deployment.yaml index dec081448..314bad9c4 100644 --- a/java/google/registry/proxy/kubernetes/proxy-deployment.yaml +++ b/java/google/registry/proxy/kubernetes/proxy-deployment.yaml @@ -42,7 +42,7 @@ spec: - name: service-account mountPath: /var/secrets/google imagePullPolicy: Always - args: ["--log"] + args: ["--env", "alpha", "--log"] env: - name: GOOGLE_APPLICATION_CREDENTIALS value: /var/secrets/google/service-account.json diff --git a/javatests/google/registry/proxy/GcpJsonFormatterTest.java b/javatests/google/registry/proxy/GcpJsonFormatterTest.java new file mode 100644 index 000000000..bb4be43d3 --- /dev/null +++ b/javatests/google/registry/proxy/GcpJsonFormatterTest.java @@ -0,0 +1,108 @@ +// Copyright 2017 The Nomulus Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package google.registry.proxy; + +import static com.google.common.truth.Truth.assertThat; + +import com.google.common.base.Joiner; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.JUnit4; + +/** Unit tests for {@link google.registry.proxy.GcpJsonFormatter}. */ +@RunWith(JUnit4.class) +public class GcpJsonFormatterTest { + + private static final String LOGGER_NAME = "example.company.app.logger"; + private static final String SOURCE_CLASS_NAME = "example.company.app.component.Doer"; + private static final String SOURCE_METHOD_NAME = "doStuff"; + private static final String MESSAGE = "Something I have to say"; + + private final GcpJsonFormatter formatter = new GcpJsonFormatter(); + private final LogRecord logRecord = new LogRecord(Level.WARNING, MESSAGE); + + private static String makeJson(String severity, String source, String message) { + StringBuilder builder = new StringBuilder(); + builder.append("{"); + builder.append( + Joiner.on(",") + .join( + makeJsonField("severity", severity), + makeJsonField("source", source), + makeJsonField("message", "\\n" + message))); + builder.append("}\n"); + return builder.toString(); + } + + private static String makeJsonField(String name, String content) { + return Joiner.on(":").join(addQuoteAndReplaceNewline(name), addQuoteAndReplaceNewline(content)); + } + + private static String addQuoteAndReplaceNewline(String content) { + // This quadruple escaping is hurting my eyes. + return "\"" + content.replaceAll("\n", "\\\\n") + "\""; + } + + @Before + public void setUp() { + logRecord.setLoggerName(LOGGER_NAME); + } + + @Test + public void testSuccess() { + String actual = formatter.format(logRecord); + String expected = makeJson("WARNING", LOGGER_NAME, MESSAGE); + assertThat(actual).isEqualTo(expected); + } + + @Test + public void testSuccess_sourceClassAndMethod() { + logRecord.setSourceClassName(SOURCE_CLASS_NAME); + logRecord.setSourceMethodName(SOURCE_METHOD_NAME); + String actual = formatter.format(logRecord); + String expected = makeJson("WARNING", SOURCE_CLASS_NAME + " " + SOURCE_METHOD_NAME, MESSAGE); + assertThat(actual).isEqualTo(expected); + } + + @Test + public void testSuccess_multilineMessage() { + String multilineMessage = "First line message\nSecond line message\n"; + logRecord.setMessage(multilineMessage); + String actual = formatter.format(logRecord); + String expected = makeJson("WARNING", LOGGER_NAME, multilineMessage); + assertThat(actual).isEqualTo(expected); + } + + @Test + public void testSuccess_withCause() { + Throwable throwable = new Throwable("Some reason"); + StackTraceElement[] stacktrace = { + new StackTraceElement("class1", "method1", "file1", 5), + new StackTraceElement("class2", "method2", "file2", 10), + }; + String stacktraceString = + "java.lang.Throwable: Some reason\\n" + + "\\tat class1.method1(file1:5)\\n" + + "\\tat class2.method2(file2:10)\\n"; + throwable.setStackTrace(stacktrace); + logRecord.setThrown(throwable); + String actual = formatter.format(logRecord); + String expected = makeJson("WARNING", LOGGER_NAME, MESSAGE + "\\n" + stacktraceString); + assertThat(actual).isEqualTo(expected); + } +}