Log websessions when they are produced and consumed Generate a new websession_log file under $GERRIT_SITE/logs in order to trace the activity of the websessions created and received from the other nodes. Only non-sensitive information is logged, whilst the authentication keys and the binary session payload is omitted. Change-Id: I9da0ac4478ecedf06b93a6d93e97a219770503df

diff --git a/src/main/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSession.java b/src/main/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSession.java
index fbd0882..733581c 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSession.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSession.java

@@ -27,9 +27,12 @@
 import com.google.gerrit.server.events.EventTypes;
 import com.google.inject.Inject;
 import com.google.inject.Provider;
+import com.google.inject.Scopes;
 import com.google.inject.internal.UniqueAnnotations;
 import com.google.inject.servlet.RequestScoped;
 import com.google.inject.servlet.ServletScopes;
+import com.googlesource.gerrit.plugins.websession.broker.log.Log4jWebSessionLogger;
+import com.googlesource.gerrit.plugins.websession.broker.log.WebSessionLogger;
 import java.lang.annotation.Annotation;
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
@@ -49,6 +52,9 @@
 
       listener(BrokerBasedWebSessionCache.class);
       listener(BrokerBasedWebSessionCacheCleaner.class);
+      listener(Log4jWebSessionLogger.class);
+
+      bind(WebSessionLogger.class).to(Log4jWebSessionLogger.class).in(Scopes.SINGLETON);
     }
 
     private void listener(Class<? extends LifecycleListener> classObj) {

diff --git a/src/main/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSessionCache.java b/src/main/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSessionCache.java
index 6dc1689..147fa93 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSessionCache.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSessionCache.java

@@ -31,6 +31,8 @@
 import com.google.inject.Inject;
 import com.google.inject.Singleton;
 import com.google.inject.name.Named;
+import com.googlesource.gerrit.plugins.websession.broker.log.WebSessionLogger;
+import com.googlesource.gerrit.plugins.websession.broker.log.WebSessionLogger.Direction;
 import com.googlesource.gerrit.plugins.websession.broker.util.TimeMachine;
 import java.io.ByteArrayInputStream;
 import java.io.ByteArrayOutputStream;
@@ -40,6 +42,7 @@
 import java.time.Instant;
 import java.util.Map;
 import java.util.Map.Entry;
+import java.util.Optional;
 import java.util.UUID;
 import java.util.concurrent.Callable;
 import java.util.concurrent.ConcurrentMap;
@@ -56,6 +59,7 @@
   String webSessionTopicName;
   DynamicItem<BrokerApi> brokerApi;
   TimeMachine timeMachine;
+  private final WebSessionLogger webSessionLogger;
 
   @Inject
   public BrokerBasedWebSessionCache(
@@ -63,11 +67,13 @@
       DynamicItem<BrokerApi> brokerApi,
       TimeMachine timeMachine,
       PluginConfigFactory cfg,
-      @PluginName String pluginName) {
+      @PluginName String pluginName,
+      WebSessionLogger webSessionLogger) {
     this.cache = cache;
     this.brokerApi = brokerApi;
     this.timeMachine = timeMachine;
     this.webSessionTopicName = getWebSessionTopicName(cfg, pluginName);
+    this.webSessionLogger = webSessionLogger;
   }
 
   protected void processMessage(EventMessage message) {
@@ -84,6 +90,8 @@
         try (ByteArrayInputStream in = new ByteArrayInputStream(event.payload);
             ObjectInputStream inputStream = new ObjectInputStream(in)) {
           Val value = (Val) inputStream.readObject();
+
+          webSessionLogger.log(Direction.CONSUME, webSessionTopicName, event, Optional.of(value));
           Instant expires = Instant.ofEpochMilli(value.getExpiresAt());
           if (expires.isAfter(timeMachine.now())) {
             cache.put(event.key, value);
@@ -96,6 +104,8 @@
         break;
       case REMOVE:
         cache.invalidate(event.key);
+        webSessionLogger.log(Direction.CONSUME, webSessionTopicName, event, Optional.empty());
+
         break;
       default:
         logger.atWarning().log(
@@ -181,18 +191,19 @@
       objectOutputStream.writeObject(value);
       out.flush();
       byte[] serializedObject = out.toByteArray();
-      EventMessage message =
-          brokerApi
-              .get()
-              .newMessage(UUID.randomUUID(), new WebSessionEvent(key, serializedObject, operation));
+      WebSessionEvent webSessionEvent = new WebSessionEvent(key, serializedObject, operation);
+      EventMessage message = brokerApi.get().newMessage(UUID.randomUUID(), webSessionEvent);
       succeeded = brokerApi.get().send(webSessionTopicName, message);
+      if (succeeded) {
+        webSessionLogger.log(
+            Direction.PUBLISH, webSessionTopicName, webSessionEvent, Optional.ofNullable(value));
+      } else {
+        logger.atSevere().log(
+            "Cannot send web-session message for '%s Topic: '%s'", key, webSessionTopicName);
+      }
     } catch (IOException e) {
       logger.atSevere().withCause(e).log(
           "Cannot serialize event for account id '%s': [Exception: %s]", value.getAccountId());
-    } finally {
-      if (!succeeded)
-        logger.atSevere().log(
-            "Cannot send web-session message for '%s Topic: '%s'", key, webSessionTopicName);
     }
   }
 

diff --git a/src/main/java/com/googlesource/gerrit/plugins/websession/broker/log/Log4jWebSessionLogger.java b/src/main/java/com/googlesource/gerrit/plugins/websession/broker/log/Log4jWebSessionLogger.java
new file mode 100644
index 0000000..f10a3bf
--- /dev/null
+++ b/src/main/java/com/googlesource/gerrit/plugins/websession/broker/log/Log4jWebSessionLogger.java

@@ -0,0 +1,58 @@
+// Copyright (C) 2020 The Android Open Source Project
+//
+// 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 com.googlesource.gerrit.plugins.websession.broker.log;
+
+import com.google.gerrit.extensions.systemstatus.ServerInformation;
+import com.google.gerrit.httpd.WebSessionManager.Val;
+import com.google.gerrit.server.util.PluginLogFile;
+import com.google.gerrit.server.util.SystemLog;
+import com.google.inject.Inject;
+import com.googlesource.gerrit.plugins.websession.broker.BrokerBasedWebSessionCache.WebSessionEvent;
+import java.util.Optional;
+import org.apache.log4j.PatternLayout;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public class Log4jWebSessionLogger extends PluginLogFile implements WebSessionLogger {
+  private static final String LOG_NAME = "websession_log";
+  private final Logger msgLog;
+
+  @Inject
+  public Log4jWebSessionLogger(SystemLog systemLog, ServerInformation serverInfo) {
+    super(systemLog, serverInfo, LOG_NAME, new PatternLayout("[%d{ISO8601}] [%t] %-5p : %m%n"));
+    this.msgLog = LoggerFactory.getLogger(LOG_NAME);
+  }
+
+  @Override
+  public void log(Direction direction, String topic, WebSessionEvent event, Optional<Val> payload) {
+    msgLog.info("{} {} {} {}", direction, topic, formatEvent(event), formatSession(payload));
+  }
+
+  private Object formatEvent(WebSessionEvent event) {
+    return String.format(
+        "{ \"operation\":\"%s\", \"key\":\"%s\", \"eventCreatedOn\":%d }",
+        event.operation, event.key, event.eventCreatedOn);
+  }
+
+  private Object formatSession(Optional<Val> payload) {
+    return payload
+        .map(
+            session ->
+                String.format(
+                    "{ \"accountId\":%d, \"expiresAt\":%d }",
+                    session.getAccountId().get(), session.getExpiresAt()))
+        .orElse("");
+  }
+}

diff --git a/src/main/java/com/googlesource/gerrit/plugins/websession/broker/log/WebSessionLogger.java b/src/main/java/com/googlesource/gerrit/plugins/websession/broker/log/WebSessionLogger.java
new file mode 100644
index 0000000..37b04c2
--- /dev/null
+++ b/src/main/java/com/googlesource/gerrit/plugins/websession/broker/log/WebSessionLogger.java

@@ -0,0 +1,29 @@
+// Copyright (C) 2020 The Android Open Source Project
+//
+// 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 com.googlesource.gerrit.plugins.websession.broker.log;
+
+import com.google.gerrit.httpd.WebSessionManager.Val;
+import com.googlesource.gerrit.plugins.websession.broker.BrokerBasedWebSessionCache.WebSessionEvent;
+import java.util.Optional;
+
+public interface WebSessionLogger {
+
+  public enum Direction {
+    PUBLISH,
+    CONSUME;
+  }
+
+  public void log(Direction direction, String topic, WebSessionEvent event, Optional<Val> payload);
+}

diff --git a/src/test/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSessionCacheTest.java b/src/test/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSessionCacheTest.java
index 746d3e6..60e995e 100644
--- a/src/test/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSessionCacheTest.java
+++ b/src/test/java/com/googlesource/gerrit/plugins/websession/broker/BrokerBasedWebSessionCacheTest.java

@@ -35,6 +35,7 @@
 import com.google.gerrit.server.events.Event;
 import com.googlesource.gerrit.plugins.websession.broker.BrokerBasedWebSessionCache.WebSessionEvent;
 import com.googlesource.gerrit.plugins.websession.broker.BrokerBasedWebSessionCache.WebSessionEvent.Operation;
+import com.googlesource.gerrit.plugins.websession.broker.log.WebSessionLogger;
 import com.googlesource.gerrit.plugins.websession.broker.util.TimeMachine;
 import java.time.Instant;
 import java.util.UUID;
@@ -72,6 +73,7 @@
   @Mock TimeMachine timeMachine;
   @Mock PluginConfigFactory cfg;
   @Mock PluginConfig pluginConfig;
+  @Mock WebSessionLogger webSessionLogger;
   @Captor ArgumentCaptor<EventMessage> eventCaptor;
   @Captor ArgumentCaptor<Val> valCaptor;
 
@@ -84,7 +86,9 @@
     when(cfg.getFromGerritConfig(PLUGIN_NAME)).thenReturn(pluginConfig);
     when(timeMachine.now()).thenReturn(Instant.EPOCH);
     DynamicItem<BrokerApi> item = DynamicItem.itemOf(BrokerApi.class, brokerApi);
-    objectUnderTest = new BrokerBasedWebSessionCache(cache, item, timeMachine, cfg, PLUGIN_NAME);
+    objectUnderTest =
+        new BrokerBasedWebSessionCache(
+            cache, item, timeMachine, cfg, PLUGIN_NAME, webSessionLogger);
   }
 
   @Test