Merge pull request #16065 from vespa-engine/bjorncs/jdisc-connection-log

Bjorncs/jdisc connection log

2 files changed, 220 insertions, 65 deletions

diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/ConnectionLogEntry.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/ConnectionLogEntry.java
index e1dbcd4af84..6702e7a5fcc 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/ConnectionLogEntry.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/ConnectionLogEntry.java
@@ -2,7 +2,6 @@
 
 package com.yahoo.container.logging;
 
-import com.fasterxml.jackson.core.JsonGenerator;
 import com.yahoo.slime.Cursor;
 import com.yahoo.slime.Slime;
 import com.yahoo.slime.SlimeUtils;
@@ -10,7 +9,6 @@ import com.yahoo.slime.SlimeUtils;
 import java.io.IOException;
 import java.nio.charset.StandardCharsets;
 import java.time.Instant;
-import java.util.Optional;
 import java.util.UUID;
 
 /**
@@ -22,23 +20,64 @@ public class ConnectionLogEntry {
     private final Instant timestamp;
     private final String peerAddress;
     private final Integer peerPort;
-
-    private ConnectionLogEntry(UUID id, Instant timestamp, String peerAddress, int peerPort) {
-        this.id = id;
-        this.timestamp = timestamp;
-        this.peerAddress = peerAddress;
-        this.peerPort = peerPort;
+    private final String localAddress;
+    private final Integer localPort;
+    private final Long bytesReceived;
+    private final Long bytesSent;
+    private final Long requests;
+    private final Long responses;
+    private final String sslSessionId;
+    private final String sslProtocol;
+    private final String sslCipherSuite;
+    private final String sslPeerSubject;
+    private final Instant sslPeerNotBefore;
+    private final Instant sslPeerNotAfter;
+    private final String sslSniServerName;
+
+    private ConnectionLogEntry(Builder builder) {
+        this.id = builder.id;
+        this.timestamp = builder.timestamp;
+        this.peerAddress = builder.peerAddress;
+        this.peerPort = builder.peerPort;
+        this.localAddress = builder.localAddress;
+        this.localPort = builder.localPort;
+        this.bytesReceived = builder.bytesReceived;
+        this.bytesSent = builder.bytesSent;
+        this.requests = builder.requests;
+        this.responses = builder.responses;
+        this.sslSessionId = builder.sslSessionId;
+        this.sslProtocol = builder.sslProtocol;
+        this.sslCipherSuite = builder.sslCipherSuite;
+        this.sslPeerSubject = builder.sslPeerSubject;
+        this.sslPeerNotBefore = builder.sslPeerNotBefore;
+        this.sslPeerNotAfter = builder.sslPeerNotAfter;
+        this.sslSniServerName = builder.sslSniServerName;
     }
 
     public String toJson() throws IOException {
         Slime slime = new Slime();
         Cursor cursor = slime.setObject();
         cursor.setString("id", id.toString());
-        cursor.setString("timestamp", timestamp.toString());
+        setTimestamp(cursor, "timestamp", timestamp);
 
         setString(cursor, "peerAddress", peerAddress);
-        setLong(cursor, "peerPort", peerPort);
-
+        setInteger(cursor, "peerPort", peerPort);
+        setString(cursor, "localAddress", localAddress);
+        setInteger(cursor, "localPort", localPort);
+        setLong(cursor, "bytesReceived", bytesReceived);
+        setLong(cursor, "bytesSent", bytesSent);
+        setLong(cursor, "requests", requests);
+        setLong(cursor, "responses", responses);
+        if (sslProtocol != null) {
+            Cursor sslCursor = cursor.setObject("ssl");
+            setString(sslCursor, "protocol", sslProtocol);
+            setString(sslCursor, "sessionId", sslSessionId);
+            setString(sslCursor, "cipherSuite", sslCipherSuite);
+            setString(sslCursor, "peerSubject", sslPeerSubject);
+            setTimestamp(sslCursor, "peerNotBefore", sslPeerNotBefore);
+            setTimestamp(sslCursor, "peerNotAfter", sslPeerNotAfter);
+            setString(sslCursor, "sniServerName", sslSniServerName);
+        }
         return new String(SlimeUtils.toJsonBytes(slime), StandardCharsets.UTF_8);
     }
 
@@ -48,12 +87,24 @@ public class ConnectionLogEntry {
         }
     }
 
-    private void setLong(Cursor cursor, String key, Integer value) {
+    private void setLong(Cursor cursor, String key, Long value) {
+        if (value != null) {
+            cursor.setLong(key, value);
+        }
+    }
+
+    private void setInteger(Cursor cursor, String key, Integer value) {
         if (value != null) {
             cursor.setLong(key, value);
         }
     }
 
+    private void setTimestamp(Cursor cursor, String key, Instant timestamp) {
+        if (timestamp != null) {
+            cursor.setString(key, timestamp.toString());
+        }
+    }
+
     public static Builder builder(UUID id, Instant timestamp) {
         return new Builder(id, timestamp);
     }
@@ -67,6 +118,19 @@ public class ConnectionLogEntry {
         private final Instant timestamp;
         private String peerAddress;
         private Integer peerPort;
+        private String localAddress;
+        private Integer localPort;
+        private Long bytesReceived;
+        private Long bytesSent;
+        private Long requests;
+        private Long responses;
+        private String sslSessionId;
+        private String sslProtocol;
+        private String sslCipherSuite;
+        private String sslPeerSubject;
+        private Instant sslPeerNotBefore;
+        private Instant sslPeerNotAfter;
+        private String sslSniServerName;
 
         Builder(UUID id, Instant timestamp) {
             this.id = id;
@@ -81,9 +145,61 @@ public class ConnectionLogEntry {
             this.peerPort = peerPort;
             return this;
         }
+        public Builder withLocalAddress(String localAddress) {
+            this.localAddress = localAddress;
+            return this;
+        }
+        public Builder withLocalPort(int localPort) {
+            this.localPort = localPort;
+            return this;
+        }
+        public Builder withBytesReceived(long bytesReceived) {
+            this.bytesReceived = bytesReceived;
+            return this;
+        }
+        public Builder withBytesSent(long bytesSent) {
+            this.bytesSent = bytesSent;
+            return this;
+        }
+        public Builder withRequests(long requests) {
+            this.requests = requests;
+            return this;
+        }
+        public Builder withResponses(long responses) {
+            this.responses = responses;
+            return this;
+        }
+        public Builder withSslSessionId(String sslSessionId) {
+            this.sslSessionId = sslSessionId;
+            return this;
+        }
+        public Builder withSslProtocol(String sslProtocol) {
+            this.sslProtocol = sslProtocol;
+            return this;
+        }
+        public Builder withSslCipherSuite(String sslCipherSuite) {
+            this.sslCipherSuite = sslCipherSuite;
+            return this;
+        }
+        public Builder withSslPeerSubject(String sslPeerSubject) {
+            this.sslPeerSubject = sslPeerSubject;
+            return this;
+        }
+        public Builder withSslPeerNotBefore(Instant sslPeerNotBefore) {
+            this.sslPeerNotBefore = sslPeerNotBefore;
+            return this;
+        }
+        public Builder withSslPeerNotAfter(Instant sslPeerNotAfter) {
+            this.sslPeerNotAfter = sslPeerNotAfter;
+            return this;
+        }
+        public Builder withSslSniServerName(String sslSniServerName) {
+            this.sslSniServerName = sslSniServerName;
+            return this;
+        }
 
         public ConnectionLogEntry build(){
-            return new ConnectionLogEntry(id, timestamp, peerAddress, peerPort);
+            return new ConnectionLogEntry(this);
         }
     }
 }
diff --git a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JettyConnectionLogger.java b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JettyConnectionLogger.java
index 261e9387909..5edb68fc3b0 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JettyConnectionLogger.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JettyConnectionLogger.java
@@ -3,6 +3,7 @@ package com.yahoo.jdisc.http.server.jetty;
 
 import com.yahoo.container.logging.ConnectionLog;
 import com.yahoo.container.logging.ConnectionLogEntry;
+import com.yahoo.io.HexDump;
 import com.yahoo.jdisc.http.ServerConfig;
 import org.eclipse.jetty.io.Connection;
 import org.eclipse.jetty.io.EndPoint;
@@ -12,10 +13,12 @@ import org.eclipse.jetty.server.Request;
 import org.eclipse.jetty.util.component.AbstractLifeCycle;
 
 import javax.net.ssl.ExtendedSSLSession;
+import javax.net.ssl.SNIHostName;
 import javax.net.ssl.SNIServerName;
 import javax.net.ssl.SSLEngine;
 import javax.net.ssl.SSLPeerUnverifiedException;
 import javax.net.ssl.SSLSession;
+import javax.net.ssl.StandardConstants;
 import java.net.InetSocketAddress;
 import java.security.cert.X509Certificate;
 import java.time.Instant;
@@ -29,7 +32,7 @@ import java.util.logging.Level;
 import java.util.logging.Logger;
 
 /**
- * Jetty integration for jdisc connection log (TODO link interface)
+ * Jetty integration for jdisc connection log ({@link ConnectionLog}).
  *
  * @author bjorncs
  */
@@ -54,13 +57,13 @@ class JettyConnectionLogger extends AbstractLifeCycle implements Connection.List
     //
     @Override
     protected void doStop() {
-        if (!enabled) return;
+        handleListenerInvocation("AbstractLifeCycle", "doStop", "", List.of(), () -> {});
         log.log(Level.FINE, () -> "Jetty connection logger is stopped");
     }
 
     @Override
     protected void doStart() {
-        if (!enabled) return;
+        handleListenerInvocation("AbstractLifeCycle", "doStart", "", List.of(), () -> {});
         log.log(Level.FINE, () -> "Jetty connection logger is started");
     }
     //
@@ -72,37 +75,37 @@ class JettyConnectionLogger extends AbstractLifeCycle implements Connection.List
     //
     @Override
     public void onOpened(Connection connection) {
-        if (!enabled) return;
-        onListenerInvoked("Connection.Listener", "onOpened", "%h", connection);
-        AggregatedConnectionInfo info = new AggregatedConnectionInfo(UUID.randomUUID());
-        synchronized (info.lock()) {
-            EndPoint endpoint = connection.getEndPoint();
-            info.setCreatedAt(endpoint.getCreatedTimeStamp())
-                    .setLocalAddress(endpoint.getLocalAddress())
-                    .setPeerAddress(endpoint.getRemoteAddress());
-            if (connection instanceof SslConnection) {
-                SslConnection sslConnection = (SslConnection) connection;
-                SSLEngine sslEngine = sslConnection.getSSLEngine();
-                SSLSession sslSession = sslEngine.getSession();
-                info.setSslSessionDetails(sslSession);
+        handleListenerInvocation("Connection.Listener", "onOpened", "%h", List.of(connection), () -> {
+            AggregatedConnectionInfo info = new AggregatedConnectionInfo(UUID.randomUUID());
+            synchronized (info.lock()) {
+                EndPoint endpoint = connection.getEndPoint();
+                info.setCreatedAt(endpoint.getCreatedTimeStamp())
+                        .setLocalAddress(endpoint.getLocalAddress())
+                        .setPeerAddress(endpoint.getRemoteAddress());
+                if (connection instanceof SslConnection) {
+                    SslConnection sslConnection = (SslConnection) connection;
+                    SSLEngine sslEngine = sslConnection.getSSLEngine();
+                    SSLSession sslSession = sslEngine.getSession();
+                    info.setSslSessionDetails(sslSession);
+                }
             }
-        }
-        connectionInfo.put(connection, info);
+            connectionInfo.put(connection, info);
+        });
     }
 
     @Override
     public void onClosed(Connection connection) {
-        if (!enabled) return;
-        onListenerInvoked("Connection.Listener", "onClosed", "%h", connection);
-        // TODO Decide on handling of connection upgrade where old connection object is closed and replaced by a new (e.g for proxy-protocol auto detection)
-        AggregatedConnectionInfo builder = Objects.requireNonNull(connectionInfo.remove(connection));
-        ConnectionLogEntry logEntry;
-        synchronized (builder.lock()) {
-            logEntry = builder.setBytesReceived(connection.getBytesIn())
-                    .setBytesSent(connection.getBytesOut())
-                    .toLogEntry();
-        }
-        connectionLog.log(logEntry);
+        handleListenerInvocation("Connection.Listener", "onClosed", "%h", List.of(connection), () -> {
+            // TODO Decide on handling of connection upgrade where old connection object is closed and replaced by a new (e.g for proxy-protocol auto detection)
+            AggregatedConnectionInfo builder = Objects.requireNonNull(connectionInfo.remove(connection));
+            ConnectionLogEntry logEntry;
+            synchronized (builder.lock()) {
+                logEntry = builder.setBytesReceived(connection.getBytesIn())
+                        .setBytesSent(connection.getBytesOut())
+                        .toLogEntry();
+            }
+            connectionLog.log(logEntry);
+        });
     }
     //
     // Connection.Listener methods end
@@ -113,36 +116,45 @@ class JettyConnectionLogger extends AbstractLifeCycle implements Connection.List
     //
     @Override
     public void onRequestBegin(Request request) {
-        if (!enabled) return;
-        onListenerInvoked("HttpChannel.Listener", "onRequestBegin", "%h", request);
-        Connection connection = request.getHttpChannel().getConnection();
-        AggregatedConnectionInfo info = Objects.requireNonNull(connectionInfo.get(connection));
-        UUID uuid;
-        synchronized (info.lock()) {
-            info.incrementRequests();
-            uuid = info.uuid();
-        }
-        request.setAttribute(CONNECTION_ID_REQUEST_ATTRIBUTE, uuid);
+        handleListenerInvocation("HttpChannel.Listener", "onRequestBegin", "%h", List.of(request), () -> {
+            Connection connection = request.getHttpChannel().getConnection();
+            AggregatedConnectionInfo info = Objects.requireNonNull(connectionInfo.get(connection));
+            UUID uuid;
+            synchronized (info.lock()) {
+                info.incrementRequests();
+                uuid = info.uuid();
+            }
+            request.setAttribute(CONNECTION_ID_REQUEST_ATTRIBUTE, uuid);
+        });
     }
 
     @Override
     public void onResponseBegin(Request request) {
-        if (!enabled) return;
-        onListenerInvoked("HttpChannel.Listener", "onResponseBegin", "%h", request);
-        Connection connection = request.getHttpChannel().getConnection();
-        AggregatedConnectionInfo info = Objects.requireNonNull(connectionInfo.get(connection));
-        synchronized (info.lock()) {
-            info.incrementResponses();
-        }
+        handleListenerInvocation("HttpChannel.Listener", "onResponseBegin", "%h", List.of(request), () -> {
+            Connection connection = request.getHttpChannel().getConnection();
+            AggregatedConnectionInfo info = Objects.requireNonNull(connectionInfo.get(connection));
+            synchronized (info.lock()) {
+                info.incrementResponses();
+            }
+        });
     }
     //
     // HttpChannel.Listener methods end
     //
 
-    private void onListenerInvoked(String listenerType, String methodName, String methodArgumentsFormat, Object... methodArguments) {
-        log.log(Level.FINE, () -> String.format(listenerType + "." + methodName + "(" + methodArgumentsFormat + ")", methodArguments));
+    private void handleListenerInvocation(
+            String listenerType, String methodName, String methodArgumentsFormat, List<Object> methodArguments, ListenerHandler handler) {
+        if (!enabled) return;
+        try {
+            log.log(Level.FINE, () -> String.format(listenerType + "." + methodName + "(" + methodArgumentsFormat + ")", methodArguments.toArray()));
+            handler.run();
+        } catch (Exception e) {
+            log.log(Level.WARNING, String.format("Exception in %s.%s listener: %s", listenerType, methodName, e.getMessage()), e);
+        }
     }
 
+    @FunctionalInterface private interface ListenerHandler { void run() throws Exception; }
+
     private static class AggregatedConnectionInfo {
         private final Object monitor = new Object();
 
@@ -206,10 +218,37 @@ class JettyConnectionLogger extends AbstractLifeCycle implements Connection.List
         }
 
         ConnectionLogEntry toLogEntry() {
-            return ConnectionLogEntry.builder(uuid, Instant.ofEpochMilli(createdAt))
-                    .withPeerAddress(peerAddress.getHostString())
-                    .withPeerPort(peerAddress.getPort())
-                    .build();
+            ConnectionLogEntry.Builder builder = ConnectionLogEntry.builder(uuid, Instant.ofEpochMilli(createdAt))
+                    .withBytesReceived(bytesReceived)
+                    .withBytesSent(bytesSent)
+                    .withRequests(requests)
+                    .withResponses(responses);
+            if (peerAddress != null) {
+                builder.withPeerAddress(peerAddress.getHostString())
+                        .withPeerPort(peerAddress.getPort());
+            }
+            if (localAddress != null) {
+                builder.withLocalAddress(localAddress.getHostString())
+                        .withLocalPort(localAddress.getPort());
+            }
+            if (sslProtocol != null && sslCipherSuite != null && sslSessionId != null) {
+                builder.withSslProtocol(sslProtocol)
+                        .withSslCipherSuite(sslCipherSuite)
+                        .withSslSessionId(HexDump.toHexString(sslSessionId));
+            }
+            if (sslSniServerNames != null) {
+                sslSniServerNames.stream()
+                        .filter(name -> name instanceof SNIHostName && name.getType() == StandardConstants.SNI_HOST_NAME)
+                        .map(name -> ((SNIHostName) name).getAsciiName())
+                        .findAny()
+                        .ifPresent(builder::withSslSniServerName);
+            }
+            if (sslPeerSubject != null && sslPeerNotAfter != null && sslPeerNotBefore != null) {
+                builder.withSslPeerSubject(sslPeerSubject)
+                        .withSslPeerNotAfter(sslPeerNotAfter.toInstant())
+                        .withSslPeerNotBefore(sslPeerNotBefore.toInstant());
+            }
+            return builder.build();
         }
 
     }