Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Jetty 12]Recive websocket close frame after server idle timeout. #11088

Closed
leonchen83 opened this issue Dec 20, 2023 · 4 comments
Closed

[Jetty 12]Recive websocket close frame after server idle timeout. #11088

leonchen83 opened this issue Dec 20, 2023 · 4 comments
Labels
Bug For general bugs on Jetty side

Comments

@leonchen83
Copy link
Contributor

leonchen83 commented Dec 20, 2023 •
edited

Jetty version(s)
jetty 12.0.5
Jetty Environment
ee10

Java version/vendor (use: java -version)
java 17
OS type/version

Linux krampus-dev 3.10.0-1127.19.1.el7.x86_64 #1 SMP Tue Aug 25 17:23:54 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

Description

when websocket client send close frame to server. client recieve close frame after server idle timeout.(code:1001, reason:Connection Idle Timeout)

jetty log

23-12-20 16:20:50.828 DEBUG[jetty.server.pool-4 WebSocketCoreSession.onOpen:368]onOpen() WebSocketCoreSession@342073a2{SERVER,WebSocketSessionState@5b00b3d4{CONNECTING,i=NO-OP,o=NO-OP,c=null},[ws://dev-krampus-advance.nextop.cn:0/api/v1/realtime,null,false.[]],af=true,i/o=4096/4096,fs=65536}->JettyWebSocketFrameHandler@10bb11cb[cn.nextop.gadget.web.support.socket.XWebSocketAdapter]
23-12-20 16:20:51.279 DEBUG[jetty.server.pool-14 WebSocketCoreSession.onFrame:631]receiveFrame(CLOSE@67abb932[len=2,fin=true,rsv=000,m=00000000]DirectByteBuffer@7f226e53[p=0,l=2,c=2,r=2]={<<<\x03\xE8>>>}:{1000=NORMAL,null}, org.eclipse.jetty.websocket.core.WebSocketConnection$1@30328936) - connectionState=WebSocketSessionState@5b00b3d4{OPEN,i=NO-OP,o=NO-OP,c=null}, handler=JettyWebSocketFrameHandler@10bb11cb[cn.nextop.gadget.web.support.socket.XWebSocketAdapter]
23-12-20 16:21:51.278 DEBUG[jetty.server.pool-10 WebSocketCoreSession.onEof:238]onEof() WebSocketCoreSession@342073a2{SERVER,WebSocketSessionState@5b00b3d4{ISHUT,i=NO-OP,o=NO-OP,c={1000=NORMAL,null}},[ws://dev-krampus-advance.nextop.cn:0/api/v1/realtime,null,false.[]],af=true,i/o=512/4096,fs=65536}->JettyWebSocketFrameHandler@10bb11cb[cn.nextop.gadget.web.support.socket.XWebSocketAdapter]
23-12-20 16:21:51.291 DEBUG[Scheduler-1004931143-1 WebSocketConnection.onIdleExpired:232]onIdleExpired()
23-12-20 16:21:51.291 DEBUG[Scheduler-1004931143-1 WebSocketCoreSession.processHandlerError:338]processHandlerError WebSocketCoreSession@342073a2{SERVER,WebSocketSessionState@5b00b3d4{ISHUT,i=NO-OP,o=NO-OP,c={1000=NORMAL,null}},[ws://dev-krampus-advance.nextop.cn:0/api/v1/realtime,null,false.[]],af=true,i/o=512/4096,fs=65536}->JettyWebSocketFrameHandler@10bb11cb[cn.nextop.gadget.web.support.socket.XWebSocketAdapter]
org.eclipse.jetty.websocket.core.exception.WebSocketTimeoutException: Connection Idle Timeout
	at org.eclipse.jetty.websocket.core.WebSocketConnection.onIdleExpired(WebSocketConnection.java:235)
	at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:389)
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:172)
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 60000/60000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:167)
	... 7 common frames omitted
23-12-20 16:21:51.291 DEBUG[Scheduler-1004931143-1 WebSocketCoreSession.sendFrame:485]sendFrame(CLOSE@44f2ef76[len=25,fin=true,rsv=000,m=null]HeapByteBuffer@62c799cd[p=0,l=25,c=25,r=25]={<<<\x03\xE9Connection Idle Timeout>>>}:{1001=SHUTDOWN,Connection Idle Timeout}, Callback.NOOP, false)
23-12-20 16:21:51.291 DEBUG[Scheduler-1004931143-1 WebSocketCoreSession$Flusher.sendFrame:68]Queuing CLOSE@44f2ef76[len=25,fin=true,rsv=000,m=null]HeapByteBuffer@62c799cd[p=0,l=25,c=25,r=25]={<<<\x03\xE9Connection Idle Timeout>>>}:{1001=SHUTDOWN,Connection Idle Timeout}
23-12-20 16:21:51.291 DEBUG[Scheduler-1004931143-1 WebSocketCoreSession$Flusher.process:162]onFrame CLOSE@44f2ef76[len=25,fin=true,rsv=000,m=null]HeapByteBuffer@62c799cd[p=0,l=25,c=25,r=25]={<<<\x03\xE9Connection Idle Timeout>>>}:{1001=SHUTDOWN,Connection Idle Timeout}
23-12-20 16:21:51.291 DEBUG[Scheduler-1004931143-1 WebSocketCoreSession$Flusher.notifyCallbackSuccess:193]notifyCallbackSuccess Callback@785b423c{BLOCKING, org.eclipse.jetty.websocket.core.WebSocketCoreSession$$Lambda$1680/0x00000008017ec000@74187602,org.eclipse.jetty.websocket.core.WebSocketCoreSession$$Lambda$1681/0x00000008017ec228@27c2aea8}
23-12-20 16:21:51.291 DEBUG[jetty.server.pool-14 WebSocketConnection.onClose:211]onClose() of physical connection
23-12-20 16:21:51.291 DEBUG[Scheduler-1004931143-1 WebSocketCoreSession.closeConnection:247]closeConnection() {1001=SHUTDOWN,Connection Idle Timeout} WebSocketCoreSession@342073a2{SERVER,WebSocketSessionState@5b00b3d4{CLOSED,i=NO-OP,o=NO-OP,c={1001=SHUTDOWN,Connection Idle Timeout}},[ws://dev-krampus-advance.nextop.cn:0/api/v1/realtime,null,false.[]],af=true,i/o=512/4096,fs=65536}->JettyWebSocketFrameHandler@10bb11cb[cn.nextop.gadget.web.support.socket.XWebSocketAdapter]
23-12-20 16:21:51.291 DEBUG[jetty.server.pool-14 WebSocketCoreSession.processConnectionError:306]processConnectionError WebSocketCoreSession@342073a2{SERVER,WebSocketSessionState@5b00b3d4{CLOSED,i=NO-OP,o=NO-OP,c={1001=SHUTDOWN,Connection Idle Timeout}},[ws://dev-krampus-advance.nextop.cn:0/api/v1/realtime,null,false.[]],af=true,i/o=512/4096,fs=65536}->JettyWebSocketFrameHandler@10bb11cb[cn.nextop.gadget.web.support.socket.XWebSocketAdapter]
org.eclipse.jetty.util.StaticException: Closed
23-12-20 16:21:51.292 DEBUG[Scheduler-1004931143-1 WebSocketCoreSession.abort:530]abort(): WebSocketCoreSession@342073a2{SERVER,WebSocketSessionState@5b00b3d4{CLOSED,i=NO-OP,o=NO-OP,c={1001=SHUTDOWN,Connection Idle Timeout}},[ws://dev-krampus-advance.nextop.cn:0/api/v1/realtime,null,false.[]],af=true,i/o=512/4096,fs=65536}->JettyWebSocketFrameHandler@10bb11cb[cn.nextop.gadget.web.support.socket.XWebSocketAdapter]

How to reproduce?

/**
 * 
 * @author Jingqi Xu
 * https://eclipse.dev/jetty/documentation/jetty-12/programming-guide/index.html#pg-websocket-endpoints-demand
 */
@WebSocket
public class XWebSocketAdapter {
	//
	private WebSocketHandler handler;
	private XWebSocketSession session;
	
	/**
	 * @see ByteBufferMessageSink
	 * @see JettyWebSocketHandlerAdapter
	 */
	@OnWebSocketError
	public void onWebSocketError(Throwable error) {
		try { this.handler.handleTransportError( session , error ); }
		catch (Throwable cause) { this.close(this.session , cause); }
	}
	
	@OnWebSocketOpen
	public void onWebSocketOpen (Session session) {
		try {
			this.session.initializeNativeSession(session);
			this.handler.afterConnectionEstablished(this.session);
		} catch(Throwable cause) { this.close(this.session, cause); }
	}
	
	@OnWebSocketClose
	public void onWebSocketClose(int code, String text) {
		try {
			final CloseStatus status = new CloseStatus(code, text);
			this.handler.afterConnectionClosed(this.session, status);
		} catch(Throwable cause) { this.close(this.session, cause); }
	}
	
	/**
	 * 
	 */
	@OnWebSocketMessage
	public void onWebSocketText(String text) {
		final TextMessage message = new TextMessage(text);
		try { this.handler.handleMessage( this.session , message ); }
		catch (Throwable cause) { this.close(this.session , cause); }
	}
	
	@OnWebSocketMessage
	public void onWebSocketBinary(ByteBuffer data, @Out Callback o) {
		final BinaryMessage message = new BinaryMessage(data , true);
		try { handler.handleMessage(session, message); o.succeed(); }
		catch (Throwable tx) { o.fail(tx); this.close(session, tx); }
	}
	
	@OnWebSocketFrame
	public void onWebSocketFrame( Frame frame , @Out Callback out ) {
		try {
			if(PONG != frame.getOpCode()) return;
			ByteBuffer payload = frame.getPayload();
			if(payload == null) payload = EMPTY_PAYLOAD;
			final PongMessage pong = new PongMessage(payload);
			handler.handleMessage(session, pong); out.succeed();
		} catch (Throwable tx) { out.fail(tx); close(session , tx); }
	}
	
	/**
	 * 
	 */
	protected void close(XWebSocketSession session, Throwable root) {
		if(session == null || !session.isOpen()) { return; }/* NOP */
		LOGGER.error("close websocket session: {}" , session , root);
		try{ session.close(SERVER_ERROR); } catch (Throwable nop) { }
	}
	
	/**
	 * 
	 */
	private static Logger LOGGER = getLogger(XWebSocketAdapter.class);
	
	private static final ByteBuffer EMPTY_PAYLOAD = wrap(new byte[0]);
	
	public static XWebSocketAdapter valueOf(
		@Required WebSocketHandler h, @Required XWebSocketSession s) {
		var r = new XWebSocketAdapter(); r.handler = h; r.session = s;
		return r;
	}
}
@leonchen83 leonchen83 added the Bug For general bugs on Jetty side label Dec 20, 2023
@leonchen83 leonchen83 changed the title recive websocket close frame after server idle timeout. [Jetty 12]Recive websocket close frame after server idle timeout. Dec 20, 2023
@leonchen83
Copy link
Contributor Author

Found the reason

	@OnWebSocketFrame
	public void onWebSocketFrame( Frame frame , @Out Callback out ) {
		try {
			if(PONG != frame.getOpCode()) return;
			ByteBuffer payload = frame.getPayload();
			if(payload == null) payload = EMPTY_PAYLOAD;
			final PongMessage pong = new PongMessage(payload);
			handler.handleMessage(session, pong); out.succeed();
		} catch (Throwable tx) { out.fail(tx); close(session , tx); }
	}

if(PONG != frame.getOpCode()) return; should change to if(PONG != frame.getOpCode()) { out.succeed(); return; }

@leonchen83 leonchen83 mentioned this issue Dec 20, 2023
Closed
leonchen83 added a commit to leonchen83/spring-framework that referenced this issue Dec 20, 2023
@leonchen83
complete frame callback when opcode is not PONG
460522f 
onWebSocketFrame method should complete callback. more details see issue [JETTY 11088](jetty/jetty.project#11088)
@sbordet
Copy link
Contributor

sbordet commented Dec 20, 2023

I'm not sure I understand what the problem is?

I don't think this is a Jetty issue.

If you think it is, please describe exactly what do you think it should happen, and what happens instead.

@leonchen83
Copy link
Contributor Author

I think it's a spring framework bug, the out.succeed(); should always to be invoked.

JettyWebSocketFrameHandler onFrame method

    @Override
    public void onFrame(Frame frame, Callback coreCallback)
    {
        CompletableFuture<Void> frameCallback = null;
        if (frameHandle != null)
        {
            try
            {
                frameCallback = new org.eclipse.jetty.websocket.api.Callback.Completable();
                frameHandle.invoke(new JettyWebSocketFrame(frame), frameCallback);
            }
            catch (Throwable cause)
            {
                coreCallback.failed(new WebSocketException(endpointInstance.getClass().getSimpleName() + " FRAME method error: " + cause.getMessage(), cause));
                return;
            }
        }

        Callback.Completable eventCallback = new Callback.Completable();
        switch (frame.getOpCode())
        {
            case OpCode.CLOSE -> onCloseFrame(frame, eventCallback);
            case OpCode.PING -> onPingFrame(frame, eventCallback);
            case OpCode.PONG -> onPongFrame(frame, eventCallback);
            case OpCode.TEXT -> onTextFrame(frame, eventCallback);
            case OpCode.BINARY -> onBinaryFrame(frame, eventCallback);
            case OpCode.CONTINUATION -> onContinuationFrame(frame, eventCallback);
            default -> coreCallback.failed(new IllegalStateException());
        };

        // Combine the callback from the frame handler and the event handler.
        CompletableFuture<Void> callback = eventCallback;
        if (frameCallback != null)
            callback = frameCallback.thenCompose(ignored -> eventCallback);
        callback.whenComplete((r, x) ->
        {
            if (x == null)
                coreCallback.succeeded();
            else
                coreCallback.failed(x);
        });
    }

if not we can't execute coreCallback.succeeded(); in above method. more details refer to this PR

@sbordet
Copy link
Contributor

sbordet commented Dec 20, 2023

I think it's a spring framework bug, the out.succeed(); should always to be invoked.

Yes, good catch.

Feel free to close this issue.

sdeleuze pushed a commit to sdeleuze/spring-framework that referenced this issue Dec 21, 2023
@leonchen83 @sdeleuze
Complete Jetty frame callback when opcode is not PONG
2c63a9c 
The onWebSocketFrame method should complete callback.
More details see
jetty/jetty.project#11088.

Closes spring-projectsgh-31869
sdeleuze pushed a commit to sdeleuze/spring-framework that referenced this issue Dec 21, 2023
@leonchen83 @sdeleuze
Complete Jetty frame callback when opcode is not PONG
e00a882 
The onWebSocketFrame method should complete callback.
For more details, see jetty/jetty.project#11088.

Closes spring-projectsgh-31869
TAKETODAY added a commit to TAKETODAY/today-infrastructure that referenced this issue Dec 23, 2023
@TAKETODAY
✨ Complete Jetty frame callback when opcode is not PONG
efb23ef 
The onWebSocketFrame method should complete callback.
For more details, see jetty/jetty.project#11088.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug For general bugs on Jetty side
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@sbordet @leonchen83