JakartaWebSocketSession.close() blocks long time when called from SendHandlerCallback

[yamass]

Jetty version(s)
11.0.9
(worked with 9.4.44.v20210927)

Java version/vendor (use: java -version)
temurin-17.0.2

OS type/version
Ubuntu Linux

Description

JakartaWebSocketSession.close() blocks when it is invoked from a SendHandlerCallback. In fact, it only unblocks after the idle timeout. Example (see also attached project):

@ClientEndpoint
@ServerEndpoint(value = "/events/")
public class TestSocketJetty11 {

	@OnOpen
	public void onWebSocketConnect(Session session) {
		System.out.println("Socket Connected: " + session);
		Executors.newSingleThreadScheduledExecutor().schedule(() -> {
			System.out.println("outer...");
			session.getAsyncRemote().sendText("GOODBYE", sendResult -> { // call close inside the callback!
				try {
					System.out.println("inner...");
					long startTime = System.currentTimeMillis();
					session.close();
					System.out.println("inner done. Took " + (System.currentTimeMillis() - startTime) + "ms.");
				} catch (IOException e) {
					throw new RuntimeException(e);
				}
			});
			System.out.println("outer done");
		}, 2, TimeUnit.SECONDS);
	}

	@OnClose
	public void onWebSocketClose(CloseReason reason) {
		System.out.println("Socket Closed: " + reason);
	}

	@OnError
	public void onWebSocketError(Throwable cause) {
		cause.printStackTrace(System.err);
	}

}

Result:

Socket Connected: JakartaWebSocketSession@7fb54e1e[SERVER,JakartaWebSocketFrameHandler@5611479e[endpoint=org.eclipse.jetty.demo.TestSocketJetty11]]
outer...
inner...
org.eclipse.jetty.websocket.core.exception.WebSocketTimeoutException: Connection Idle Timeout
	at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.onIdleExpired(WebSocketConnection.java:233)
	at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:407)
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:108)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:264)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java)
	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)
Socket Closed: CloseReason[1001,Connection Idle Timeout]
inner done. Took 31001ms.
outer done

This seems to be due to the fact that the previous (outer) callback is not yet terminated when close() is called.

Note that the same code worked without blocking in Jetty 9.4.44.v20210927. The attached project also contains an example for it.

This is a common use case I guess, since many protocolls will send a last message to the client before closing the connection.

How to reproduce?

See attachment, which is a maven project.

Start TestServerJetty11 and connect using test.html.

embedded-jetty-websocket-examples.zip

[joakime]

Interesting use case.
I don't see anything specifically preventing this on the spec.

[lachlan-roberts]

fixes merged with #8164