onTimeout timing out?

[guusdk]

Hi! We're getting instances of the stack traces below in our logs. Am I reading this correct that the onTimeout event listener is invoked, but that its execution itself times out? If I'm reading this right, this then causes an error to be sent on the response, which fails as the response is already committed. Am I barking up the right tree here? Any suggestions on how to approach an issue like this?

2025.06.28 21:57:36.229 WARN  [Jetty-QTP-BOSH-43885]: org.eclipse.jetty.ee8.nested.HttpChannelState - java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms while invoking onTimeout listener org.jivesoftware.openfire.http.HttpSession$1@15226abf
2025.06.28 21:57:36.229 WARN  [Jetty-QTP-BOSH-43885]: org.eclipse.jetty.util.thread.QueuedThreadPool - Job failed
java.lang.IllegalStateException: COMMITTED
        at org.eclipse.jetty.ee8.nested.HttpChannelState.sendError(HttpChannelState.java:806) ~[jetty-ee8-nested-12.0.22.jar:12.0.22]
        at org.eclipse.jetty.ee8.nested.HttpChannelState.nextAction(HttpChannelState.java:469) ~[jetty-ee8-nested-12.0.22.jar:12.0.22]
        at org.eclipse.jetty.ee8.nested.HttpChannelState.unhandle(HttpChannelState.java:410) ~[jetty-ee8-nested-12.0.22.jar:12.0.22]
        at org.eclipse.jetty.ee8.nested.HttpChannel.handle(HttpChannel.java:558) ~[jetty-ee8-nested-12.0.22.jar:12.0.22]
        at org.eclipse.jetty.ee8.nested.HttpChannel.run(HttpChannel.java:430) ~[jetty-ee8-nested-12.0.22.jar:12.0.22]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:981) [jetty-util-12.0.22.jar:12.0.22]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1211) [jetty-util-12.0.22.jar:12.0.22]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1166) [jetty-util-12.0.22.jar:12.0.22]
        at java.lang.Thread.run(Thread.java:840) [?:?]

[joakime]

The java.lang.IllegalStateException: COMMITTED is just telling you that the sendError cannot be performed due to the response being in committed state. Nothing sendError can do there.

The java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms while invoking onTimeout listener org.jivesoftware.openfire.http.HttpSession is telling you that the idle timeout of 30,000ms triggered, and Jetty called org.jivesoftware.openfire.http.HttpSession$1.onTimeout(AsyncEvent) (which appears to be a servlet AsyncListener), but the onTimeout() call produced an IOException.

The idleTimeout triggered, the connection is likely dead, Jetty told openfire about the idle timeout, but openfire decided it wanted to send more content for some reason, but couldn't as the connection is likely dead, hence the IOException. Then finally the unhandled exception was flowing to sendError impl in Jetty internals and couldn't sendError either because the response was committed.

[guusdk]

Nothing sendError can do there.

I figured as much. One thing that I did wonder about: what causes sendError to be invoked? I think that this is Jetty code. Can/should that sendError be prevented, given that the response is already in committed state?

The java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms while invoking onTimeout listener org.jivesoftware.openfire.http.HttpSession is telling you that the idle timeout of 30,000ms triggered, and Jetty called org.jivesoftware.openfire.http.HttpSession$1.onTimeout(AsyncEvent) (which appears to be a servlet AsyncListener), but the onTimeout() call produced an IOException.

The wording "Idle timeout expired: 30000/30000 ms while invoking onTimeout listener" (emphasis mine) suggests that there is a timeout happening when the onTimeout listener is already being invoked (most likely as a result of a different timeout). Is this just me interpreting the wording wrong?

Is there a way to get the stacktrace for that IOException?

[joakime]

Is there a way to get the stacktrace for that IOException?

Turn on DEBUG level logging for the named logger org.eclipse.jetty.ee8.nested.HttpChannelState.
That will output the full stacktrace when that specific event occurs.

[joakime]

You can also put a breakpoint in org.eclipse.jetty.ee8.nested.HttpChannelState.onTimeout() in the catch statement for the listener.onTimeout(event); and see the stacktrace that way.

[guusdk]

Turns out that this problem is triggered only after a restart of Jetty (without restarting the JVM), where our restart routine did not properly restart all contexts, leaving the subsystem in a weird state between started and stopped.