Upgrade from 4.7.5 to 4.8.0 throws exception

Openfire Openfire Dev
1

Hello,

I was using Openfire 4.7.5 running in a docker and for the last 6 months it was working fine.
Today I decided to just change the version of the docker image and to pull the latest 4.8.0.
After login none of my JS clients can connect and I see this error in the logs:

2024.02.29 04:55:11 DEBUG [Jetty-QTP-BOSH-63]: org.jivesoftware.openfire.websocket.WebSocketClientConnectionHandler - Error detected; connection: WebSocketConnection{jid=(null), remotePeer=/172.18.0.1:49206, socket=org.jivesoftware.openfire.websocket.WebSocketClientConnectionHandler@1a9e4280, connectionType=SOCKET_C2S}, session: WebSocketSession[SERVER,to=PT2562047788015H12M55.807S,WSCoreSession@6a610e52{SERVER,WebSocketSessionState@62654001{CLOSED,i=NO-OP,o=NO-OP,c={1011=SERVER_ERROR,org.eclipse.jetty.websocket.core.exception.WebSocketException: WebSocketClientConnectionHandler OPEN method error: Non-posi}},[ws://chat.sugar.deals:0/ws/server,xmpp,false.[permessage-deflate]],af=true,i/o=5242880/5242880,fs=65536}->JettyWebSocketFrameHandler@3b5fad25[org.jivesoftware.openfire.websocket.WebSocketClientConnectionHandler],JettyWebSocketFrameHandler@3b5fad25[org.jivesoftware.openfire.websocket.WebSocketClientConnectionHandler]]
org.eclipse.jetty.websocket.api.exceptions.CloseException: org.eclipse.jetty.websocket.core.exception.WebSocketException: WebSocketClientConnectionHandler OPEN method error: Non-positive period.
    at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.convertCause(JettyWebSocketFrameHandler.java:538) ~[websocket-jetty-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.onError(JettyWebSocketFrameHandler.java:259) ~[websocket-jetty-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.lambda$closeConnection$2(WebSocketCoreSession.java:284) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1451) ~[jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1488) ~[jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.server.internal.AbstractHandshaker$1.handle(AbstractHandshaker.java:212) ~[websocket-core-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.closeConnection(WebSocketCoreSession.java:284) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.lambda$sendFrame$7(WebSocketCoreSession.java:519) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:155) ~[jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.TransformingFlusher.notifyCallbackSuccess(TransformingFlusher.java:197) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.TransformingFlusher$Flusher.process(TransformingFlusher.java:154) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:243) ~[jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) ~[jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.TransformingFlusher.sendFrame(TransformingFlusher.java:77) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.sendFrame(WebSocketCoreSession.java:522) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.close(WebSocketCoreSession.java:239) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.processHandlerError(WebSocketCoreSession.java:371) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.lambda$onOpen$5(WebSocketCoreSession.java:405) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.Callback$3.failed(Callback.java:161) ~[jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.onOpen(JettyWebSocketFrameHandler.java:186) ~[websocket-jetty-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.lambda$onOpen$6(WebSocketCoreSession.java:411) ~[websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1469) [jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1488) [jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.server.internal.AbstractHandshaker$1.handle(AbstractHandshaker.java:212) [websocket-core-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.onOpen(WebSocketCoreSession.java:411) [websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.onOpen(WebSocketConnection.java:551) [websocket-core-common-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.io.AbstractEndPoint.upgrade(AbstractEndPoint.java:451) [jetty-io-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.HttpConnection.upgrade(HttpConnection.java:424) [jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.HttpConnection.onCompleted(HttpConnection.java:455) [jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:959) [jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:489) [jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287) [jetty-server-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314) [jetty-io-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100) [jetty-io-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) [jetty-io-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421) [jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390) [jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277) [jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:199) [jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411) [jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969) [jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194) [jetty-util-10.0.18.jar:10.0.18]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149) [jetty-util-10.0.18.jar:10.0.18]
    at java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: org.eclipse.jetty.websocket.core.exception.CloseException: org.eclipse.jetty.websocket.core.exception.WebSocketException: WebSocketClientConnectionHandler OPEN method error: Non-positive period.
    ... 27 more
Caused by: org.eclipse.jetty.websocket.core.exception.WebSocketException: WebSocketClientConnectionHandler OPEN method error: Non-positive period.
    ... 25 more
Caused by: java.lang.IllegalArgumentException: Non-positive period.
    at java.util.Timer.schedule(Timer.java:259) ~[?:?]
    at org.jivesoftware.util.TaskEngine.schedule(TaskEngine.java:227) ~[xmppserver-4.8.0.jar:4.8.0]
    at org.jivesoftware.openfire.websocket.WebSocketClientConnectionHandler.onConnect(WebSocketClientConnectionHandler.java:115) ~[xmppserver-4.8.0.jar:4.8.0]
    at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.onOpen(JettyWebSocketFrameHandler.java:176) ~[websocket-jetty-common-10.0.18.jar:10.0.18]
    ... 24 more
2

I suspect that you have configured the property ‘xmpp.client.idle’ to a negative value (to disable timeouts). This code does not like that, which is probably a bug in Openfire. Can you try change that property to use a positive value, to see if that fixes ypur problem?

3

I have created a new ticket for this problem: [OF-2809] - Ignite Realtime Jira

4

I tested with a positive value and it works fine. However, I don’t know what implications this will cause because I have clients on mobile phones connected with Strophejs and they might minimize their app for a period longer than 5-6 minutes.

1 Like
5

I’m not sure if simply assuming that those phones are ‘online’ is the best approach. For mobile phones, you might want to look at a combination of XEP-0198 Stream Management (which sadly is also broken in 4.8.0, but for which a fix is available in 4.8.1) and push notifications.

6

Thanks for confirming that this is indeed the problem. A fix will be part of the next release of Openfire (4.8.1).