Make Functions Framework use StackDriver-compatible logging when on GCF.

In this environment, outputting a particular JSON-formatted string will produce a log entry with fields parsed from that string.

Remove the special logging.properties file. The intent was to omit information like the timestamp that would be duplicated by the StackDriver logging framework. But we are now replacing the logger completely, so this logging.properties is no longer consulted.

The logging.properties that was deleted also didn't include the
[`%6$s` field](https://docs.oracle.com/en/java/javase/11/docs/api/java.logging/java/util/logging/SimpleFormatter.html#format(java.util.logging.LogRecord))
which meant that if there was an exception associated with the log message it did not appear.

PiperOrigin-RevId: 302709439

Author: eamonnmcmanus

invoker/core/src/main/java/com/google/cloud/functions/invoker/gcf/JsonLogHandler.java

@@ -0,0 +1,122 @@
+package com.google.cloud.functions.invoker.gcf;
+
+import java.io.PrintStream;
+import java.io.PrintWriter;
+import java.io.StringWriter;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.logging.Handler;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+
+/**
+ * A log handler that publishes log messages in a json format. This is StackDriver's
+ * <a href="https://cloud.google.com/logging/docs/structured-logging">"structured
+ * logging" format</a>.
+ */
+public final class JsonLogHandler extends Handler {
+  private static final String SOURCE_LOCATION_KEY = "\"logging.googleapis.com/sourceLocation\": ";
+
+  private static final String DEBUG = "DEBUG";
+  private static final String INFO = "INFO";
+  private static final String WARNING = "WARNING";
+  private static final String ERROR = "ERROR";
+  private static final String DEFAULT = "DEFAULT";
+
+  private final PrintStream out;
+  private final boolean closePrintStreamOnClose;
+
+  public JsonLogHandler(PrintStream out, boolean closePrintStreamOnClose) {
+    this.out = out;
+    this.closePrintStreamOnClose = closePrintStreamOnClose;
+  }
+
+  @Override
+  public void publish(LogRecord record) {
+    // We avoid String.format and String.join even though they would simplify the code.
+    // Logging code often shows up in profiling so we want to make this fast and StringBuilder is
+    // more performant.
+    StringBuilder json = new StringBuilder("{");
+    appendSeverity(json, record);
+    appendSourceLocation(json, record);
+    appendMessage(json, record); // must be last, see appendMessage
+    json.append("}");
+    // We must output the log all at once (should only call println once per call to publish)
+    out.println(json);
+  }
+
+  private static void appendMessage(StringBuilder json, LogRecord record) {
+    // This must be the last item in the JSON object, because it has no trailing comma. JSON is
+    // unforgiving about commas and you can't have one just before }.
+    json.append("\"message\": \"").append(escapeString(record.getMessage()));
+    if (record.getThrown() != null) {
+      json.append("\\n")
+          .append(escapeString(getStackTraceAsString(record.getThrown())));
+    }
+    json.append("\"");
+  }
+
+  private static void appendSeverity(StringBuilder json, LogRecord record) {
+    json.append("\"severity\": \"").append(levelToSeverity(record.getLevel())).append("\", ");
+  }
+
+  private static String levelToSeverity(Level level) {
+    int intLevel = (level == null) ? 0 : level.intValue();
+    switch (intLevel) {
+      case 300: // FINEST
+      case 400: // FINER
+      case 500: // FINE
+        return DEBUG;
+      case 700: // CONFIG
+      case 800: // INFO
+        // Java's CONFIG is lower than its INFO, while Stackdriver's NOTICE is greater than its
+        // INFO. So despite the similarity, we don't try to use NOTICE for CONFIG.
+        return INFO;
+      case 900: // WARNING
+        return WARNING;
+      case 1000: // SEVERE
+        return ERROR;
+      default:
+        return DEFAULT;
+    }
+  }
+
+  private static void appendSourceLocation(StringBuilder json, LogRecord record) {
+    if (record.getSourceClassName() == null && record.getSourceMethodName() == null) {
+      return;
+    }
+    List<String> entries = new ArrayList<>();
+    if (record.getSourceClassName() != null) {
+      // TODO: Handle nested classes. If the source class name is com.example.Foo$Bar then the
+      // source file is com/example/Foo.java, not com/example/Foo$Bar.java.
+      String fileName = record.getSourceClassName().replace('.', '/') + ".java";
+      entries.add("\"file\": \"" + escapeString(fileName) + "\"");
+    }
+    if (record.getSourceMethodName() != null) {
+      entries.add("\"method\": \"" + escapeString(record.getSourceMethodName()) + "\"");
+    }
+    json.append(SOURCE_LOCATION_KEY).append("{").append(String.join(", ", entries)).append("}, ");
+  }
+
+  private static String escapeString(String s) {
+    return s.replace("\\", "\\\\").replace("\"", "\\\"").replace("\n", "\\n").replace("\r", "\\r");
+  }
+
+  private static String getStackTraceAsString(Throwable t) {
+    StringWriter stringWriter = new StringWriter();
+    t.printStackTrace(new PrintWriter(stringWriter));
+    return stringWriter.toString();
+  }
+
+  @Override
+  public void flush() {
+    out.flush();
+  }
+
+  @Override
+  public void close() throws SecurityException {
+    if (closePrintStreamOnClose) {
+      out.close();
+    }
+  }
+}

invoker/core/src/main/java/com/google/cloud/functions/invoker/runner/Invoker.java

@@ -31,6 +31,7 @@
 import com.google.cloud.functions.invoker.HttpFunctionSignatureMatcher;
 import com.google.cloud.functions.invoker.NewBackgroundFunctionExecutor;
 import com.google.cloud.functions.invoker.NewHttpFunctionExecutor;
+import com.google.cloud.functions.invoker.gcf.JsonLogHandler;
 import java.io.File;
 import java.io.IOException;
 import java.io.UncheckedIOException;
@@ -50,8 +51,8 @@
 import java.util.Objects;
 import java.util.Optional;
 import java.util.Set;
+import java.util.logging.Handler;
 import java.util.logging.Level;
-import java.util.logging.LogManager;
 import java.util.logging.Logger;
 import java.util.stream.Stream;
 import javax.servlet.ServletException;
@@ -80,17 +81,19 @@
  * </ul>
  */
 public class Invoker {
-
-  private static final Logger logger;
+  private static final Logger rootLogger = Logger.getLogger("");
+  private static final Logger logger = Logger.getLogger(Invoker.class.getName());
 
   static {
-    try {
-      LogManager.getLogManager()
-          .readConfiguration(Invoker.class.getResourceAsStream("/logging.properties"));
-    } catch (IOException e) {
-      System.out.println("Failed to read logging configuration file, error: " + e.getMessage());
+    if (isGcf()) {
+      // If we're running with Google Cloud Functions, we'll get better-looking logs if we arrange
+      // for them to be formatted using StackDriver's "structured logging" JSON format. Remove the
+      // JDK's standard logger and replace it with the JSON one.
+      for (Handler handler : rootLogger.getHandlers()) {
+        rootLogger.removeHandler(handler);
+      }
+      rootLogger.addHandler(new JsonLogHandler(System.out, false));
     }
-    logger = Logger.getLogger(Invoker.class.getName());
   }
 
   private static class Options {
@@ -365,13 +368,19 @@ private static List<URL> jarsIn(String dir) {
   }
 
   private void logServerInfo() {
-    if (isLocalRun()) {
+    if (!isGcf()) {
       logger.log(Level.INFO, "Serving function...");
       logger.log(Level.INFO, "Function: {0}", functionTarget);
       logger.log(Level.INFO, "URL: http://localhost:{0,number,#}/", port);
     }
   }
 
+  private static boolean isGcf() {
+    // This environment variable is set in the GCF environment but won't be set when invoking
+    // the Functions Framework directly. We don't use its value, just whether it is set.
+    return System.getenv("K_SERVICE") != null;
+  }
+
   /**
    * Wrapper that intercepts requests for {@code /favicon.ico} and {@code /robots.txt} and causes
    * them to produce a 404 status. Otherwise they would be sent to the function code, like any

invoker/core/src/main/resources/logging.properties

@@ -41,6 +41,7 @@
 import java.net.ServerSocket;
 import java.net.URI;
 import java.net.URL;
+import java.net.URLEncoder;
 import java.nio.charset.StandardCharsets;
 import java.nio.file.Files;
 import java.nio.file.Path;
@@ -147,6 +148,8 @@ abstract static class TestCase {
 
     abstract Optional<String> expectedContentType();
 
+    abstract Optional<String> expectedOutput();
+
     abstract String httpContentType();
 
     abstract ImmutableMap<String, String> httpHeaders();
@@ -178,6 +181,8 @@ abstract static class Builder {
 
       abstract Builder setExpectedContentType(String x);
 
+      abstract Builder setExpectedOutput(String x);
+
       abstract Builder setExpectedJsonString(String x);
 
       abstract Builder setHttpContentType(String x);
@@ -272,6 +277,41 @@ public void newEchoUrl() throws Exception {
     testHttpFunction(fullTarget("NewEchoUrl"), testCases);
   }
 
+  @Test
+  public void stackDriverLogging() throws Exception {
+    String simpleExpectedOutput =
+        "{\"severity\": \"INFO\", "
+            + "\"logging.googleapis.com/sourceLocation\": "
+            + "{\"file\": \"com/google/cloud/functions/invoker/testfunctions/Log.java\","
+            + " \"method\": \"service\"},"
+            + " \"message\": \"blim\"}";
+    TestCase simpleTestCase =
+        TestCase.builder()
+            .setUrl("/?message=blim")
+            .setExpectedOutput(simpleExpectedOutput)
+            .build();
+    String quotingExpectedOutput = "\"message\": \"foo\\nbar\\\"";
+    TestCase quotingTestCase =
+        TestCase.builder()
+            .setUrl("/?message=" + URLEncoder.encode("foo\nbar\"", "UTF-8"))
+            .setExpectedOutput(quotingExpectedOutput)
+            .build();
+    String exceptionExpectedOutput =
+        "{\"severity\": \"ERROR\", "
+            + "\"logging.googleapis.com/sourceLocation\": "
+            + "{\"file\": \"com/google/cloud/functions/invoker/testfunctions/Log.java\", "
+            + "\"method\": \"service\"}, "
+            + "\"message\": \"oops\\njava.lang.Exception: disaster\\n"
+            + "	at com.google.cloud.functions.invoker.testfunctions.Log.service(Log.java:";
+    TestCase exceptionTestCase =
+        TestCase.builder()
+            .setUrl("/?message=oops&level=severe&exception=disaster")
+            .setExpectedOutput(exceptionExpectedOutput)
+            .build();
+    testHttpFunction(
+        fullTarget("Log"), ImmutableList.of(simpleTestCase, quotingTestCase, exceptionTestCase));
+  }
+
   @Test
   public void background() throws Exception {
     File snoopFile = snoopFile();
@@ -480,6 +520,8 @@ private void testFunction(
         if (testCase.snoopFile().isPresent()) {
           checkSnoopFile(testCase.snoopFile().get(), testCase.expectedJsonString().get());
         }
+        testCase.expectedOutput()
+            .ifPresent(output -> expect.that(serverProcess.output().toString()).contains(output));
       }
     } finally {
       serverProcess.close();
@@ -505,13 +547,29 @@ public String toString() {
     }
   }
 
-  @AutoValue
-  abstract static class ServerProcess implements AutoCloseable {
-    abstract Process process();
-    abstract Future<?> outputMonitorResult();
+  private static class ServerProcess implements AutoCloseable {
+    private final Process process;
+    private final Future<?> outputMonitorResult;
+    private final StringBuilder output;
 
-    static ServerProcess of(Process process, Future<?> outputMonitorResult) {
-      return new AutoValue_IntegrationTest_ServerProcess(process, outputMonitorResult);
+    ServerProcess(Process process, Future<?> outputMonitorResult, StringBuilder output) {
+      this.process = process;
+      this.outputMonitorResult = outputMonitorResult;
+      this.output = output;
+    }
+
+    Process process() {
+      return process;
+    }
+
+    Future<?> outputMonitorResult() {
+      return outputMonitorResult;
+    }
+
+    String output() {
+      synchronized (output) {
+        return output.toString();
+      }
     }
 
     @Override
@@ -544,24 +602,29 @@ private ServerProcess startServer(
     processBuilder.environment().putAll(environment);
     Process serverProcess = processBuilder.start();
     CountDownLatch ready = new CountDownLatch(1);
+    StringBuilder output = new StringBuilder();
     Future<?> outputMonitorResult = EXECUTOR.submit(
-        () -> monitorOutput(serverProcess.getInputStream(), ready));
+        () -> monitorOutput(serverProcess.getInputStream(), ready, output));
     boolean serverReady = ready.await(5, TimeUnit.SECONDS);
     if (!serverReady) {
       serverProcess.destroy();
       throw new AssertionError("Server never became ready");
     }
-    return ServerProcess.of(serverProcess, outputMonitorResult);
+    return new ServerProcess(serverProcess, outputMonitorResult, output);
   }
 
-  private void monitorOutput(InputStream processOutput, CountDownLatch ready) {
+  private void monitorOutput(
+      InputStream processOutput, CountDownLatch ready, StringBuilder output) {
     try (BufferedReader reader = new BufferedReader(new InputStreamReader(processOutput))) {
       String line;
       while ((line = reader.readLine()) != null) {
         if (line.contains(SERVER_READY_STRING)) {
           ready.countDown();
         }
         System.out.println(line);
+        synchronized (output) {
+          output.append(line).append('\n');
+        }
         if (line.contains("WARNING")) {
           throw new AssertionError("Found warning in server output:\n" + line);
         }

invoker/core/src/test/java/com/google/cloud/functions/invoker/IntegrationTest.java

@@ -0,0 +1,28 @@
+package com.google.cloud.functions.invoker.testfunctions;
+
+import com.google.cloud.functions.HttpFunction;
+import com.google.cloud.functions.HttpRequest;
+import com.google.cloud.functions.HttpResponse;
+import java.lang.reflect.Field;
+import java.util.Optional;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+/** Emit log messages with configurable level, message, and exception. */
+public class Log implements HttpFunction {
+  private static final Logger logger = Logger.getLogger(Log.class.getName());
+
+  @Override
+  public void service(HttpRequest request, HttpResponse response) throws Exception {
+    String message = request.getFirstQueryParameter("message").orElse("Default message");
+    String levelString = request.getFirstQueryParameter("level").orElse("info");
+    Optional<String> exceptionString = request.getFirstQueryParameter("exception");
+    Field levelField = Level.class.getField(levelString.toUpperCase());
+    Level level = (Level) levelField.get(null);
+    if (exceptionString.isPresent()) {
+      logger.log(level, message, new Exception(exceptionString.get()));
+    } else {
+      logger.log(level, message);
+    }
+  }
+}