From 1690e9d30de3b59c9f78b65839a24c0dc4cca9a9 Mon Sep 17 00:00:00 2001 From: Joakim Erdfelt Date: Wed, 26 Aug 2020 06:56:17 -0500 Subject: [PATCH 1/5] Issue #5193 - Adding more EventDriver logging Signed-off-by: Joakim Erdfelt --- .../common/events/AbstractEventDriver.java | 27 ++++--- .../events/JettyAnnotatedEventDriver.java | 68 +++++++++++++++- .../common/events/JettyAnnotatedMetadata.java | 15 ++-- .../events/JettyListenerEventDriver.java | 79 ++++++++++++++++++- .../events/annotated/CallableMethod.java | 5 +- .../OptionalSessionCallableMethod.java | 7 +- 6 files changed, 176 insertions(+), 25 deletions(-) diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/AbstractEventDriver.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/AbstractEventDriver.java index 2c54ace5c18..d69fe68044f 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/AbstractEventDriver.java +++ b/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); diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java index cb993d213d0..5bec0316252 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java +++ b/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() - 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); diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedMetadata.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedMetadata.java index 536faeaaf2a..c56f9efb89f 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedMetadata.java +++ b/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); diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyListenerEventDriver.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyListenerEventDriver.java index 9af52f99937..fcf85a1a594 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyListenerEventDriver.java +++ b/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 + ? "" + : 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) diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/annotated/CallableMethod.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/annotated/CallableMethod.java index 0f10c71e9bd..145ea510e96 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/annotated/CallableMethod.java +++ b/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()); } } diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/annotated/OptionalSessionCallableMethod.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/annotated/OptionalSessionCallableMethod.java index aca97a2eb01..115a6d12417 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/annotated/OptionalSessionCallableMethod.java +++ b/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); } } From eebb47cbc56da317cbf3bf10f1c6a7b3b6320a07 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Thu, 27 Aug 2020 17:14:01 +1000 Subject: [PATCH 2/5] add test to reproduce issue #5193 Signed-off-by: Lachlan Roberts --- .../websocket/tests/SingleOnMessageTest.java | 159 ++++++++++++++++++ 1 file changed, 159 insertions(+) create mode 100644 jetty-websocket/jetty-websocket-tests/src/test/java/org/eclipse/jetty/websocket/tests/SingleOnMessageTest.java diff --git a/jetty-websocket/jetty-websocket-tests/src/test/java/org/eclipse/jetty/websocket/tests/SingleOnMessageTest.java b/jetty-websocket/jetty-websocket-tests/src/test/java/org/eclipse/jetty/websocket/tests/SingleOnMessageTest.java new file mode 100644 index 00000000000..492037ad687 --- /dev/null +++ b/jetty-websocket/jetty-websocket-tests/src/test/java/org/eclipse/jetty/websocket/tests/SingleOnMessageTest.java @@ -0,0 +1,159 @@ +package org.eclipse.jetty.websocket.tests; + +import java.net.URI; +import java.nio.ByteBuffer; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.TimeUnit; + +import org.eclipse.jetty.server.Server; +import org.eclipse.jetty.server.ServerConnector; +import org.eclipse.jetty.servlet.ServletContextHandler; +import org.eclipse.jetty.util.BlockingArrayQueue; +import org.eclipse.jetty.util.BufferUtil; +import org.eclipse.jetty.websocket.api.RemoteEndpoint; +import org.eclipse.jetty.websocket.api.Session; +import org.eclipse.jetty.websocket.api.StatusCode; +import org.eclipse.jetty.websocket.api.annotations.OnWebSocketClose; +import org.eclipse.jetty.websocket.api.annotations.OnWebSocketConnect; +import org.eclipse.jetty.websocket.api.annotations.OnWebSocketMessage; +import org.eclipse.jetty.websocket.api.annotations.WebSocket; +import org.eclipse.jetty.websocket.api.util.WSURI; +import org.eclipse.jetty.websocket.client.WebSocketClient; +import org.eclipse.jetty.websocket.server.NativeWebSocketServletContainerInitializer; +import org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.Matchers.is; +import static org.junit.jupiter.api.Assertions.assertTrue; + +public class SingleOnMessageTest +{ + private final Server server = new Server(); + private final WebSocketClient client = new WebSocketClient(); + private final EventSocket serverSocket = new EventSocket(); + private URI serverUri; + + @BeforeEach + public void start() throws Exception + { + ServerConnector connector = new ServerConnector(server); + server.addConnector(connector); + + ServletContextHandler contextHandler = new ServletContextHandler(ServletContextHandler.SESSIONS); + contextHandler.setContextPath("/"); + NativeWebSocketServletContainerInitializer.configure(contextHandler, + (context, container) -> container.addMapping("/", (req, resp) -> serverSocket)); + WebSocketUpgradeFilter.configure(contextHandler); + + server.setHandler(contextHandler); + server.start(); + serverUri = WSURI.toWebsocket(server.getURI()); + + client.start(); + } + + @AfterEach + public void stop() throws Exception + { + client.stop(); + server.stop(); + } + + @Test + public void testTextHandler() throws Exception + { + TextOnlyHandler handler = new TextOnlyHandler(); + client.connect(handler, serverUri); + assertTrue(handler.openLatch.await(5, TimeUnit.SECONDS)); + assertTrue(serverSocket.openLatch.await(5, TimeUnit.SECONDS)); + + // The server sends a sequence of Binary and Text messages + RemoteEndpoint remote = serverSocket.session.getRemote(); + remote.sendBytes(BufferUtil.toBuffer("this should get rejected")); + remote.sendString("WebSocket_Data0"); + remote.sendString("WebSocket_Data1"); + serverSocket.session.close(StatusCode.NORMAL, "test complete"); + + // The client receives the messages and has discarded the binary message. + assertThat(handler.messages.poll(5, TimeUnit.SECONDS), is("WebSocket_Data0")); + assertThat(handler.messages.poll(5, TimeUnit.SECONDS), is("WebSocket_Data1")); + assertTrue(handler.closeLatch.await(5, TimeUnit.SECONDS)); + assertThat(handler.closeCode, is(StatusCode.NORMAL)); + assertThat(handler.closeReason, is("test complete")); + } + + @Test + public void testBinaryHandler() throws Exception + { + BinaryOnlyHandler handler = new BinaryOnlyHandler(); + client.connect(handler, serverUri); + assertTrue(handler.openLatch.await(5, TimeUnit.SECONDS)); + assertTrue(serverSocket.openLatch.await(5, TimeUnit.SECONDS)); + + // The server sends a sequence of Binary and Text messages + RemoteEndpoint remote = serverSocket.session.getRemote(); + remote.sendString("this should get rejected"); + remote.sendBytes(BufferUtil.toBuffer("WebSocket_Data0")); + remote.sendBytes(BufferUtil.toBuffer("WebSocket_Data1")); + serverSocket.session.close(StatusCode.NORMAL, "test complete"); + + // The client receives the messages and has discarded the binary message. + assertThat(handler.messages.poll(5, TimeUnit.SECONDS), is(BufferUtil.toBuffer("WebSocket_Data0"))); + assertThat(handler.messages.poll(5, TimeUnit.SECONDS), is(BufferUtil.toBuffer("WebSocket_Data1"))); + assertTrue(handler.closeLatch.await(5, TimeUnit.SECONDS)); + assertThat(handler.closeCode, is(StatusCode.NORMAL)); + assertThat(handler.closeReason, is("test complete")); + } + + @WebSocket + public static class TextOnlyHandler extends AbstractHandler + { + final BlockingArrayQueue messages = new BlockingArrayQueue<>(); + + @OnWebSocketMessage + public void onMessage(String message) + { + messages.add(message); + } + } + + @WebSocket + public static class BinaryOnlyHandler extends AbstractHandler + { + final BlockingArrayQueue messages = new BlockingArrayQueue<>(); + + @OnWebSocketMessage + public void onMessage(byte[] array, int offset, int length) + { + messages.add(BufferUtil.toBuffer(array, offset, length)); + } + } + + @WebSocket + public static class AbstractHandler + { + final CountDownLatch openLatch = new CountDownLatch(1); + final CountDownLatch closeLatch = new CountDownLatch(1); + Session session; + int closeCode; + String closeReason; + + @OnWebSocketClose + public void onClose(int statusCode, String reason) + { + this.closeCode = statusCode; + this.closeReason = reason; + this.closeLatch.countDown(); + } + + @OnWebSocketConnect + public void onConnect(Session session) + { + this.session = session; + this.openLatch.countDown(); + } + } +} From 478bcdc868378c841239d631977a58faf275bc67 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Thu, 27 Aug 2020 17:18:48 +1000 Subject: [PATCH 3/5] Issue #5193 - fix lost message bug when using single onMessage annotation Signed-off-by: Lachlan Roberts --- .../events/JettyAnnotatedEventDriver.java | 37 +++++++------------ 1 file changed, 13 insertions(+), 24 deletions(-) diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java index cb993d213d0..cbb32adfec6 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java +++ b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java @@ -45,7 +45,7 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver private static final Logger LOG = Log.getLogger(JettyAnnotatedEventDriver.class); private final JettyAnnotatedMetadata events; private boolean hasCloseBeenCalled = false; - private BatchMode batchMode; + private final BatchMode batchMode; public JettyAnnotatedEventDriver(WebSocketPolicy policy, Object websocket, JettyAnnotatedMetadata events) { @@ -82,20 +82,14 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver @Override public void onBinaryFrame(ByteBuffer buffer, boolean fin) throws IOException { - if (events.onBinary == null) - { - // not interested in binary events - if (activeMessage == null) - { - activeMessage = NullMessage.INSTANCE; - } - - return; - } - if (activeMessage == null) { - if (events.onBinary.isStreaming()) + if (events.onBinary == null) + { + // not interested in binary events + activeMessage = NullMessage.INSTANCE; + } + else if (events.onBinary.isStreaming()) { final MessageInputStream inputStream = new MessageInputStream(session); activeMessage = inputStream; @@ -199,19 +193,14 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver @Override public void onTextFrame(ByteBuffer buffer, boolean fin) throws IOException { - if (events.onText == null) - { - // not interested in text events - if (activeMessage == null) - { - activeMessage = NullMessage.INSTANCE; - } - return; - } - if (activeMessage == null) { - if (events.onText.isStreaming()) + if (events.onText == null) + { + // not interested in text events + activeMessage = NullMessage.INSTANCE; + } + else if (events.onText.isStreaming()) { MessageInputStream inputStream = new MessageInputStream(session); activeMessage = new MessageReader(inputStream); From 92e5abb1bded5a1a26469caa14d41e0999f16ef1 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Thu, 27 Aug 2020 18:05:56 +1000 Subject: [PATCH 4/5] add missing licence header in SingleOnMessageTest Signed-off-by: Lachlan Roberts --- .../websocket/tests/SingleOnMessageTest.java | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/jetty-websocket/jetty-websocket-tests/src/test/java/org/eclipse/jetty/websocket/tests/SingleOnMessageTest.java b/jetty-websocket/jetty-websocket-tests/src/test/java/org/eclipse/jetty/websocket/tests/SingleOnMessageTest.java index 492037ad687..03acf813ed5 100644 --- a/jetty-websocket/jetty-websocket-tests/src/test/java/org/eclipse/jetty/websocket/tests/SingleOnMessageTest.java +++ b/jetty-websocket/jetty-websocket-tests/src/test/java/org/eclipse/jetty/websocket/tests/SingleOnMessageTest.java @@ -1,3 +1,21 @@ +// +// ======================================================================== +// Copyright (c) 1995-2020 Mort Bay Consulting Pty Ltd and others. +// ------------------------------------------------------------------------ +// All rights reserved. This program and the accompanying materials +// are made available under the terms of the Eclipse Public License v1.0 +// and Apache License v2.0 which accompanies this distribution. +// +// The Eclipse Public License is available at +// http://www.eclipse.org/legal/epl-v10.html +// +// The Apache License v2.0 is available at +// http://www.opensource.org/licenses/apache2.0.php +// +// You may elect to redistribute this code under either of these licenses. +// ======================================================================== +// + package org.eclipse.jetty.websocket.tests; import java.net.URI; From 46402bc382a0627b648b593bcf052d4fe7728211 Mon Sep 17 00:00:00 2001 From: Joakim Erdfelt Date: Fri, 28 Aug 2020 05:46:07 -0500 Subject: [PATCH 5/5] Issue #5193 - Updating logging per review Signed-off-by: Joakim Erdfelt --- .../events/JettyAnnotatedEventDriver.java | 12 +++---- .../events/JettyListenerEventDriver.java | 34 +++++++++---------- 2 files changed, 23 insertions(+), 23 deletions(-) diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java index 5bec0316252..56aa8d57b97 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java +++ b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyAnnotatedEventDriver.java @@ -92,7 +92,8 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onBinaryFrame({}, {}) - events.onBinary={}", BufferUtil.toDetailString(buffer), fin, events.onBinary); + LOG.debug("onBinaryFrame({}, {}) - events.onBinary={}, activeMessage={}", + BufferUtil.toDetailString(buffer), fin, events.onBinary, activeMessage); } if (events.onBinary == null) @@ -254,7 +255,8 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onTextFrame({}, {}) - events.onText={}", BufferUtil.toDetailString(buffer), fin, events.onText); + LOG.debug("onTextFrame({}, {}) - events.onText={}, activeMessage={}", + BufferUtil.toDetailString(buffer), fin, events.onText, activeMessage); } if (events.onText == null) @@ -303,10 +305,8 @@ public class JettyAnnotatedEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - if (message == null) - LOG.debug("onTextMessage() - events.onText={}", events.onText); - else - LOG.debug("onTextMessage([{}] \"{}\") - events.onText={}", message.length(), TextUtil.maxStringLength(60, message), events.onText); + LOG.debug("onTextMessage([{}] \"{}\") - events.onText={}", + message.length(), TextUtil.maxStringLength(60, message), events.onText); } if (events.onText != null) diff --git a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyListenerEventDriver.java b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyListenerEventDriver.java index fcf85a1a594..dc9ed1059c3 100644 --- a/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyListenerEventDriver.java +++ b/jetty-websocket/websocket-common/src/main/java/org/eclipse/jetty/websocket/common/events/JettyListenerEventDriver.java @@ -73,11 +73,12 @@ public class JettyListenerEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onBinaryFrame({}, {}) - webSocketListener:{}, webSocketPartialListener:{}, listener:{}", + LOG.debug("onBinaryFrame({}, {}) - webSocketListener={}, webSocketPartialListener={}, listener={}, activeMessage={}", BufferUtil.toDetailString(buffer), fin, (listener instanceof WebSocketListener), (listener instanceof WebSocketPartialListener), - listener.getClass().getName()); + listener.getClass().getName(), + activeMessage); } if (listener instanceof WebSocketListener) @@ -116,7 +117,7 @@ public class JettyListenerEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onBinaryMessage([{}]) - webSocketListener:{}, listener:{}", + LOG.debug("onBinaryMessage([{}]) - webSocketListener={}, listener={}", data.length, (listener instanceof WebSocketListener), this.listener.getClass().getName()); @@ -143,7 +144,7 @@ public class JettyListenerEventDriver extends AbstractEventDriver if (LOG.isDebugEnabled()) { - LOG.debug("onClose({},{}) - listener:{}", statusCode, reason, this.listener.getClass().getName()); + LOG.debug("onClose({},{}) - listener={}", statusCode, reason, this.listener.getClass().getName()); } listener.onWebSocketClose(statusCode, reason); } @@ -153,7 +154,7 @@ public class JettyListenerEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onConnect({}) - listener:{}", session, this.listener.getClass().getName()); + LOG.debug("onConnect({}) - listener={}", session, this.listener.getClass().getName()); } listener.onWebSocketConnect(session); } @@ -163,7 +164,7 @@ public class JettyListenerEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onError({}) - listener:{}", cause.getClass().getName(), this.listener.getClass().getName()); + LOG.debug("onError({}) - listener={}", cause.getClass().getName(), this.listener.getClass().getName()); } listener.onWebSocketError(cause); } @@ -173,7 +174,7 @@ public class JettyListenerEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onFrame({}) - frameListener:{}, pingPongListener:{}, listener:{}", + LOG.debug("onFrame({}) - frameListener={}, pingPongListener={}, listener={}", frame, (listener instanceof WebSocketFrameListener), (listener instanceof WebSocketPingPongListener), @@ -215,12 +216,13 @@ public class JettyListenerEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onTextFrame({}, {}) - webSocketListener:{}, webSocketPartialListener:{}, listener:{}", + LOG.debug("onTextFrame({}, {}) - webSocketListener={}, webSocketPartialListener={}, listener={}, activeMessage={}", BufferUtil.toDetailString(buffer), fin, (listener instanceof WebSocketListener), (listener instanceof WebSocketPartialListener), - listener.getClass().getName()); + listener.getClass().getName(), + activeMessage); } if (listener instanceof WebSocketListener) @@ -282,12 +284,9 @@ public class JettyListenerEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - String msgDetail = message == null - ? "" - : String.format("[%d] \"%s\"", message.length(), TextUtil.maxStringLength(60, message)); - - LOG.debug("onTextMessage({}) - webSocketListener:{} listener:{}", - msgDetail, + LOG.debug("onTextMessage([{}] \"{}\") - webSocketListener={}, listener={}", + message.length(), + TextUtil.maxStringLength(60, message), (listener instanceof WebSocketListener), listener.getClass().getName()); } @@ -302,11 +301,12 @@ public class JettyListenerEventDriver extends AbstractEventDriver { if (LOG.isDebugEnabled()) { - LOG.debug("onContinuationFrame({}, {}) - webSocketListener:{}, webSocketPartialListener:{}, listener:{}", + LOG.debug("onContinuationFrame({}, {}) - webSocketListener={}, webSocketPartialListener={}, listener={}, activeMessage={}", BufferUtil.toDetailString(buffer), fin, (listener instanceof WebSocketListener), (listener instanceof WebSocketPartialListener), - listener.getClass().getName()); + listener.getClass().getName(), + activeMessage); } if (listener instanceof WebSocketPartialListener)