Issue #5193 - Adding more EventDriver logging

Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>

jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/AbstractEventDriver.java

@@ -20,6 +20,7 @@ package org.eclipse.jetty.websocket.common.events;
 
 import java.io.IOException;
 import java.nio.ByteBuffer;
+import java.util.Objects;
 
 import org.eclipse.jetty.util.BufferUtil;
 import org.eclipse.jetty.util.Utf8Appendable.NotUtf8Exception;
@@ -42,7 +43,7 @@ import org.eclipse.jetty.websocket.common.message.MessageAppender;
  */
 public abstract class AbstractEventDriver extends AbstractLifeCycle implements IncomingFrames, EventDriver
 {
-    private static final Logger LOG = Log.getLogger(AbstractEventDriver.class);
+    private final Logger logger;
     protected final Logger targetLog;
     protected WebSocketPolicy policy;
     protected final Object websocket;
@@ -51,8 +52,9 @@ public abstract class AbstractEventDriver extends AbstractLifeCycle implements I
 
     public AbstractEventDriver(WebSocketPolicy policy, Object websocket)
     {
+        this.logger = Log.getLogger(this.getClass());
         this.policy = policy;
-        this.websocket = websocket;
+        this.websocket = Objects.requireNonNull(websocket, "WebSocket endpoint may not be null");
         this.targetLog = Log.getLogger(websocket.getClass());
     }
 
@@ -87,9 +89,9 @@ public abstract class AbstractEventDriver extends AbstractLifeCycle implements I
     @Override
     public void incomingFrame(Frame frame)
     {
-        if (LOG.isDebugEnabled())
+        if (logger.isDebugEnabled())
         {
-            LOG.debug("incomingFrame({})", frame);
+            logger.debug("incomingFrame({})", frame);
         }
 
         try
@@ -112,9 +114,9 @@ public abstract class AbstractEventDriver extends AbstractLifeCycle implements I
                 }
                 case OpCode.PING:
                 {
-                    if (LOG.isDebugEnabled())
+                    if (logger.isDebugEnabled())
                     {
-                        LOG.debug("PING: {}", BufferUtil.toDetailString(frame.getPayload()));
+                        logger.debug("PING: {}", BufferUtil.toDetailString(frame.getPayload()));
                     }
                     ByteBuffer pongBuf;
                     if (frame.hasPayload())
@@ -133,9 +135,9 @@ public abstract class AbstractEventDriver extends AbstractLifeCycle implements I
                 }
                 case OpCode.PONG:
                 {
-                    if (LOG.isDebugEnabled())
+                    if (logger.isDebugEnabled())
                     {
-                        LOG.debug("PONG: {}", BufferUtil.toDetailString(frame.getPayload()));
+                        logger.debug("PONG: {}", BufferUtil.toDetailString(frame.getPayload()));
                     }
                     onPong(frame.getPayload());
                     break;
@@ -157,8 +159,8 @@ public abstract class AbstractEventDriver extends AbstractLifeCycle implements I
                 }
                 default:
                 {
-                    if (LOG.isDebugEnabled())
-                        LOG.debug("Unhandled OpCode: {}", opcode);
+                    if (logger.isDebugEnabled())
+                        logger.debug("Unhandled OpCode: {}", opcode);
                 }
             }
         }
@@ -202,10 +204,9 @@ public abstract class AbstractEventDriver extends AbstractLifeCycle implements I
     @Override
     public void openSession(WebSocketSession session)
     {
-        if (LOG.isDebugEnabled())
+        if (logger.isDebugEnabled())
         {
-            LOG.debug("openSession({})", session);
-            LOG.debug("objectFactory={}", session.getContainerScope().getObjectFactory());
+            logger.debug("openSession({}) objectFactory={}", session, session.getContainerScope().getObjectFactory());
         }
         this.session = session;
         this.session.getContainerScope().getObjectFactory().decorate(this.websocket);

jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java

@@ -22,7 +22,9 @@ import java.io.IOException;
 import java.io.InputStream;
 import java.io.Reader;
 import java.nio.ByteBuffer;
+import java.util.Objects;
 
+import org.eclipse.jetty.util.BufferUtil;
 import org.eclipse.jetty.util.log.Log;
 import org.eclipse.jetty.util.log.Logger;
 import org.eclipse.jetty.websocket.api.BatchMode;
@@ -36,6 +38,7 @@ import org.eclipse.jetty.websocket.common.message.MessageReader;
 import org.eclipse.jetty.websocket.common.message.NullMessage;
 import org.eclipse.jetty.websocket.common.message.SimpleBinaryMessage;
 import org.eclipse.jetty.websocket.common.message.SimpleTextMessage;
+import org.eclipse.jetty.websocket.common.util.TextUtil;
 
 /**
  * Handler for Annotated User WebSocket objects.
@@ -50,7 +53,7 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     public JettyAnnotatedEventDriver(WebSocketPolicy policy, Object websocket, JettyAnnotatedMetadata events)
     {
         super(policy, websocket);
-        this.events = events;
+        this.events = Objects.requireNonNull(events, "JettyAnnotatedMetadata may not be null");
 
         WebSocket anno = websocket.getClass().getAnnotation(WebSocket.class);
         // Setup the policy
@@ -71,6 +74,11 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
             this.policy.setIdleTimeout(anno.maxIdleTime());
         }
         this.batchMode = anno.batchMode();
+
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("ctor / object={}, policy={}, batchMode={}, events={}", websocket, policy, batchMode, events);
+        }
     }
 
     @Override
@@ -82,6 +90,11 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onBinaryFrame(ByteBuffer buffer, boolean fin) throws IOException
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onBinaryFrame({}, {}) - events.onBinary={}", BufferUtil.toDetailString(buffer), fin, events.onBinary);
+        }
+
         if (events.onBinary == null)
         {
             // not interested in binary events
@@ -126,6 +139,11 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onBinaryMessage(byte[] data)
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onBinaryMessage([{}]) - events.onBinary={}", data.length, events.onBinary);
+        }
+
         if (events.onBinary != null)
         {
             events.onBinary.call(websocket, session, data, 0, data.length);
@@ -141,6 +159,12 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
             return;
         }
         hasCloseBeenCalled = true;
+
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onClose({}) - events.onClose={}", close, events.onClose);
+        }
+
         if (events.onClose != null)
         {
             events.onClose.call(websocket, session, close.getStatusCode(), close.getReason());
@@ -150,6 +174,11 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onConnect()
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onConnect() - events.onConnect={}", events.onConnect);
+        }
+
         if (events.onConnect != null)
         {
             events.onConnect.call(websocket, session);
@@ -159,6 +188,11 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onError(Throwable cause)
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onError({}) - events.onError={}", cause.getClass().getName(), events.onError);
+        }
+
         if (events.onError != null)
         {
             events.onError.call(websocket, session, cause);
@@ -172,6 +206,11 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onFrame(Frame frame)
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onFrame({}) - events.onFrame={}", frame, events.onFrame);
+        }
+
         if (events.onFrame != null)
         {
             events.onFrame.call(websocket, session, frame);
@@ -181,6 +220,13 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onInputStream(InputStream stream)
     {
+        Objects.requireNonNull(stream, "InputStream may not be null");
+
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onInputStream({}) - events.onBinary={}", stream.getClass().getName(), events.onBinary);
+        }
+
         if (events.onBinary != null)
         {
             events.onBinary.call(websocket, session, stream);
@@ -190,6 +236,13 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onReader(Reader reader)
     {
+        Objects.requireNonNull(reader, "Reader may not be null");
+
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onReader({}) - events.onText={}", reader.getClass().getName(), events.onText);
+        }
+
         if (events.onText != null)
         {
             events.onText.call(websocket, session, reader);
@@ -199,6 +252,11 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onTextFrame(ByteBuffer buffer, boolean fin) throws IOException
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onTextFrame({}, {}) - events.onText={}", BufferUtil.toDetailString(buffer), fin, events.onText);
+        }
+
         if (events.onText == null)
         {
             // not interested in text events
@@ -243,6 +301,14 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver
     @Override
     public void onTextMessage(String message)
     {
+        if (LOG.isDebugEnabled())
+        {
+            if (message == null)
+                LOG.debug("onTextMessage(<null>) - events.onText={}", events.onText);
+            else
+                LOG.debug("onTextMessage([{}] \"{}\") - events.onText={}", message.length(), TextUtil.maxStringLength(60, message), events.onText);
+        }
+
         if (events.onText != null)
         {
             events.onText.call(websocket, session, message);

jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedMetadata.java

@@ -24,27 +24,27 @@ import org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallab
 public class JettyAnnotatedMetadata
 {
     /**
-     * @OnWebSocketConnect ()
+     * {@code @OnWebSocketConnect ()}
      */
     public CallableMethod onConnect;
     /**
-     * @OnWebSocketMessage (byte[], or ByteBuffer, or InputStream)
+     * {@code @OnWebSocketMessage (byte[], or ByteBuffer, or InputStream)}
      */
     public OptionalSessionCallableMethod onBinary;
     /**
-     * @OnWebSocketMessage (String, or Reader)
+     * {@code @OnWebSocketMessage (String, or Reader)}
      */
     public OptionalSessionCallableMethod onText;
     /**
-     * @OnWebSocketFrame (Frame)
+     * {@code @OnWebSocketFrame (Frame)}
      */
     public OptionalSessionCallableMethod onFrame;
     /**
-     * @OnWebSocketError (Throwable)
+     * {@code @OnWebSocketError (Throwable)}
      */
     public OptionalSessionCallableMethod onError;
     /**
-     * @OnWebSocketClose (Frame)
+     * {@code @OnWebSocketClose (Frame)}
      */
     public OptionalSessionCallableMethod onClose;
 
@@ -52,7 +52,8 @@ public class JettyAnnotatedMetadata
     public String toString()
     {
         StringBuilder s = new StringBuilder();
-        s.append("JettyPojoMetadata[");
+        s.append(this.getClass().getSimpleName());
+        s.append("[");
         s.append("onConnect=").append(onConnect);
         s.append(",onBinary=").append(onBinary);
         s.append(",onText=").append(onText);

jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyListenerEventDriver.java

@@ -22,7 +22,9 @@ import java.io.IOException;
 import java.io.InputStream;
 import java.io.Reader;
 import java.nio.ByteBuffer;
+import java.util.Objects;
 
+import org.eclipse.jetty.util.BufferUtil;
 import org.eclipse.jetty.util.Utf8StringBuilder;
 import org.eclipse.jetty.util.log.Log;
 import org.eclipse.jetty.util.log.Logger;
@@ -38,6 +40,7 @@ import org.eclipse.jetty.websocket.common.CloseInfo;
 import org.eclipse.jetty.websocket.common.frames.ReadOnlyDelegatedFrame;
 import org.eclipse.jetty.websocket.common.message.SimpleBinaryMessage;
 import org.eclipse.jetty.websocket.common.message.SimpleTextMessage;
+import org.eclipse.jetty.websocket.common.util.TextUtil;
 
 /**
  * Handler for {@link WebSocketListener} based User WebSocket implementations.
@@ -58,12 +61,25 @@ public class JettyListenerEventDriver extends AbstractEventDriver
     public JettyListenerEventDriver(WebSocketPolicy policy, WebSocketConnectionListener listener)
     {
         super(policy, listener);
-        this.listener = listener;
+        this.listener = Objects.requireNonNull(listener, "Listener may not be null");
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("ctor / listener={}, policy={}", listener.getClass().getName(), policy);
+        }
     }
 
     @Override
     public void onBinaryFrame(ByteBuffer buffer, boolean fin) throws IOException
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onBinaryFrame({}, {}) - webSocketListener:{}, webSocketPartialListener:{}, listener:{}",
+                BufferUtil.toDetailString(buffer), fin,
+                (listener instanceof WebSocketListener),
+                (listener instanceof WebSocketPartialListener),
+                listener.getClass().getName());
+        }
+
         if (listener instanceof WebSocketListener)
         {
             if (activeMessage == null)
@@ -98,6 +114,14 @@ public class JettyListenerEventDriver extends AbstractEventDriver
     @Override
     public void onBinaryMessage(byte[] data)
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onBinaryMessage([{}]) - webSocketListener:{}, listener:{}",
+                data.length,
+                (listener instanceof WebSocketListener),
+                this.listener.getClass().getName());
+        }
+
         if (listener instanceof WebSocketListener)
         {
             ((WebSocketListener)listener).onWebSocketBinary(data, 0, data.length);
@@ -116,6 +140,11 @@ public class JettyListenerEventDriver extends AbstractEventDriver
 
         int statusCode = close.getStatusCode();
         String reason = close.getReason();
+
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onClose({},{}) - listener:{}", statusCode, reason, this.listener.getClass().getName());
+        }
         listener.onWebSocketClose(statusCode, reason);
     }
 
@@ -123,19 +152,34 @@ public class JettyListenerEventDriver extends AbstractEventDriver
     public void onConnect()
     {
         if (LOG.isDebugEnabled())
-            LOG.debug("onConnect({})", session);
+        {
+            LOG.debug("onConnect({}) - listener:{}", session, this.listener.getClass().getName());
+        }
         listener.onWebSocketConnect(session);
     }
 
     @Override
     public void onError(Throwable cause)
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onError({}) - listener:{}", cause.getClass().getName(), this.listener.getClass().getName());
+        }
         listener.onWebSocketError(cause);
     }
 
     @Override
     public void onFrame(Frame frame)
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onFrame({}) - frameListener:{}, pingPongListener:{}, listener:{}",
+                frame,
+                (listener instanceof WebSocketFrameListener),
+                (listener instanceof WebSocketPingPongListener),
+                this.listener.getClass().getName());
+        }
+
         if (listener instanceof WebSocketFrameListener)
         {
             ((WebSocketFrameListener)listener).onWebSocketFrame(new ReadOnlyDelegatedFrame(frame));
@@ -169,6 +213,16 @@ public class JettyListenerEventDriver extends AbstractEventDriver
     @Override
     public void onTextFrame(ByteBuffer buffer, boolean fin) throws IOException
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onTextFrame({}, {}) - webSocketListener:{}, webSocketPartialListener:{}, listener:{}",
+                BufferUtil.toDetailString(buffer),
+                fin,
+                (listener instanceof WebSocketListener),
+                (listener instanceof WebSocketPartialListener),
+                listener.getClass().getName());
+        }
+
         if (listener instanceof WebSocketListener)
         {
             if (activeMessage == null)
@@ -226,6 +280,18 @@ public class JettyListenerEventDriver extends AbstractEventDriver
     @Override
     public void onTextMessage(String message)
     {
+        if (LOG.isDebugEnabled())
+        {
+            String msgDetail = message == null
+                ? "<null>"
+                : String.format("[%d] \"%s\"", message.length(), TextUtil.maxStringLength(60, message));
+
+            LOG.debug("onTextMessage({}) - webSocketListener:{} listener:{}",
+                msgDetail,
+                (listener instanceof WebSocketListener),
+                listener.getClass().getName());
+        }
+
         if (listener instanceof WebSocketListener)
         {
             ((WebSocketListener)listener).onWebSocketText(message);
@@ -234,6 +300,15 @@ public class JettyListenerEventDriver extends AbstractEventDriver
 
     public void onContinuationFrame(ByteBuffer buffer, boolean fin) throws IOException
     {
+        if (LOG.isDebugEnabled())
+        {
+            LOG.debug("onContinuationFrame({}, {}) - webSocketListener:{}, webSocketPartialListener:{}, listener:{}",
+                BufferUtil.toDetailString(buffer), fin,
+                (listener instanceof WebSocketListener),
+                (listener instanceof WebSocketPartialListener),
+                listener.getClass().getName());
+        }
+
         if (listener instanceof WebSocketPartialListener)
         {
             switch (partialMode)

jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/annotated/CallableMethod.java

@@ -139,6 +139,9 @@ public class CallableMethod
     @Override
     public String toString()
     {
-        return String.format("%s[%s]", this.getClass().getSimpleName(), method.toGenericString());
+        return String.format("%s[pojo=%s,method=%s]",
+            this.getClass().getSimpleName(),
+            pojo.getName(),
+            method.toGenericString());
     }
 }

jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/annotated/OptionalSessionCallableMethod.java

@@ -86,6 +86,11 @@ public class OptionalSessionCallableMethod extends CallableMethod
     @Override
     public String toString()
     {
-        return String.format("%s[%s]", this.getClass().getSimpleName(), method.toGenericString());
+        return String.format("%s[pojo=%s,method=%s,wantsSession=%b,streaming=%s]",
+            this.getClass().getSimpleName(),
+            pojo.getName(),
+            method.toGenericString(),
+            wantsSession,
+            streaming);
     }
 }