Problems after upgrade to 4.6.6

[claude_stabile]

Hi guus I had the problem again this night for one docker instance only. After a restart, back to normal. I did capture openfire logs before re-starting my Docker instance. No clue what is causing this
Problem occor at 4:30 PM PST time
It happens only for one instance today, it looks random and only pidgin + Spark client are freezing
Let me know where i can send you OF logs, if you can check

Thanks in advance for your help

Latest message in error.log, unsure if related is

2021.12.22 16:30:42 org.jivesoftware.openfire.spi.RoutingTableImpl - Primary packet routing failed
org.jivesoftware.openfire.PacketException: Cannot route packet of type IQ or Presence to bare JID: <iq type="error" id="107-3343" to="im.360bcgroup.com" from="ios13push.monal.im"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="D2F16C41-C45C-4F78-B309-24EB7381BC20"><item><notification xmlns="urn:xmpp:push:0"><x xmlns="jabber:x:data" type="form"><field var="FORM_TYPE" type="hidden"><value>urn:xmpp:push:summary</value></field><field var="message-count" type="text-single"><value>1</value></field><field var="last-message-sender" type="text-single"/><field var="last-message-body" type="text-single"><value>New Message</value></field></x></notification></item></publish><publish-options><x xmlns="jabber:x:data" type="submit"><field var="FORM_TYPE"><value>http://jabber.org/protocol/pubsub#publish-options</value></field><field var="secret"><value>bd115e680889e431a013a597dec670c5409478ce477058a6beac87849654550d</value></field></x></publish-options></pubsub><error code="404" type="cancel"><remote-server-not-found xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>
        at org.jivesoftware.openfire.spi.RoutingTableImpl.routeToLocalDomain(RoutingTableImpl.java:329) ~[xmppserver-4.6.6.jar:4.6.6]
        at org.jivesoftware.openfire.spi.RoutingTableImpl.routePacket(RoutingTableImpl.java:262) [xmppserver-4.6.6.jar:4.6.6]
        at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.returnErrorToSender(OutgoingSessionPromise.java:346) [xmppserver-4.6.6.jar:4.6.6]
        at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.run(OutgoingSessionPromise.java:245) [xmppserver-4.6.6.jar:4.6.6]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
        at java.lang.Thread.run(Thread.java:832) [?:?]
2021.12.22 16:30:42 org.jivesoftware.openfire.interceptor.InterceptorManager - Error in interceptor: org.jivesoftware.openfire.plugin.ofmeet.BookmarkInterceptor@24f7003c while intercepting:
<iq type="error" id="864-3345" to="im.360bcgroup.com" from="ios13push.monal.im">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <publish node="D2F16C41-C45C-4F78-B309-24EB7381BC20">
      <item>
        <notification xmlns="urn:xmpp:push:0">
          <x xmlns="jabber:x:data" type="form">
            <field var="FORM_TYPE" type="hidden">
              <value>urn:xmpp:push:summary</value>
            </field>
            <field var="message-count" type="text-single">
              <value>1</value>
            </field>
            <field var="last-message-sender" type="text-single"/>
            <field var="last-message-body" type="text-single">
              <value>New Message</value>
            </field>
          </x>
        </notification>
      </item>
    </publish>
    <publish-options>
      <x xmlns="jabber:x:data" type="submit">
        <field var="FORM_TYPE">
          <value>http://jabber.org/protocol/pubsub#publish-options</value>
        </field>
        <field var="secret">
          <value>bd115e680889e431a013a597dec670c5409478ce477058a6beac87849654550d</value>
        </field>
      </x>
    </publish-options>
  </pubsub>
  <error code="404" type="cancel">
    <remote-server-not-found xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/>
  </error>
</iq>
java.lang.NullPointerException: null
2021.12.22 16:30:42 org.jivesoftware.openfire.spi.RoutingTableImpl - Primary packet routing failed
org.jivesoftware.openfire.PacketException: Cannot route packet of type IQ or Presence to bare JID: <iq type="error" id="864-3345" to="im.360bcgroup.com" from="ios13push.monal.im"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="D2F16C41-C45C-4F78-B309-24EB7381BC20"><item><notification xmlns="urn:xmpp:push:0"><x xmlns="jabber:x:data" type="form"><field var="FORM_TYPE" type="hidden"><value>urn:xmpp:push:summary</value></field><field var="message-count" type="text-single"><value>1</value></field><field var="last-message-sender" type="text-single"/><field var="last-message-body" type="text-single"><value>New Message</value></field></x></notification></item></publish><publish-options><x xmlns="jabber:x:data" type="submit"><field var="FORM_TYPE"><value>http://jabber.org/protocol/pubsub#publish-options</value></field><field var="secret"><value>bd115e680889e431a013a597dec670c5409478ce477058a6beac87849654550d</value></field></x></publish-options></pubsub><error code="404" type="cancel"><remote-server-not-found xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>
        at org.jivesoftware.openfire.spi.RoutingTableImpl.routeToLocalDomain(RoutingTableImpl.java:329) ~[xmppserver-4.6.6.jar:4.6.6]
        at org.jivesoftware.openfire.spi.RoutingTableImpl.routePacket(RoutingTableImpl.java:262) [xmppserver-4.6.6.jar:4.6.6]
        at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.returnErrorToSender(OutgoingSessionPromise.java:346) [xmppserver-4.6.6.jar:4.6.6]
        at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.run(OutgoingSessionPromise.java:232) [xmppserver-4.6.6.jar:4.6.6]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
        at java.lang.Thread.run(Thread.java:832) [?:?]

[Chrees]

Hi, my instance not working today. I restarted. I copied logs before restarted server.
How can I give you these logs?

[claude_stabile]

@guus I have rolled back 2 customers instances to 4.6.3 and no more connection problems. Pidgin Spark disconnect and impossible to re-connect unless OF is restarted. Never observed this with 4.6.3, hope this helps to understand the problem.

I keep 4.6.3 for now with workarround

[Chrees]

@guus ??

[pedimave]

Hi all,

I am suffereing the same issues ones that I have migrated to 4.6.6. I have tried with Beta 4.7 but no luck. Same issues. No issues with 4.6.3.

All seems that works properltly but after X minutes all of our clients start appearing as: “Invalid session/connection”

I have no cluster and diferent clients.

I tried to disabled all related with SSL but no luck:

Errors that I can see in logs:

org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection due to exception in session: (0x00001099: nio socket, server, null => 0.0.0.0/0.0.0.0:5222)
javax.net.ssl.SSLHandshakeException: SSL handshake failed.

org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection due to exception in session: (0x00001996: nio socket, server, null => 0.0.0.0/0.0.0.0:5222)
javax.net.ssl.SSLHandshakeException: SSL handshake failed.

But theses errors still happen when the system is working propertly.

The only way to solve is to change something in the client connections config just to trigger a restart ConnectionListener

022.01.04 11:26:04 INFO [Jetty-QTP-AdminConsole-6342]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Stopped.
2022.01.04 11:26:04 INFO [Jetty-QTP-AdminConsole-6342]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Started.
2022.01.04 11:26:04 INFO [Jetty-QTP-AdminConsole-6342]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Done restarting…

Ones I do this, clients start reconnecting again for another X minutes.

Any ideas about what will be the problem?.

Until find any solution is any way to restart ConnectionListener every X minutes?

Thanks,

[totzkotz]

@guus My old post seems to be gaining in importance. Paying attention to the link to Stackoverflow.

Problem with Openfire 4.6.4

I have debugged around and found out that if the (mina) Connection object in LocalSession is somehow corrupted (network errors or other …) a sess.getHostAddress() in session-row.jspf will fail and results in Invalid session/connection A click on “Close connection” on admin console (session-summary.jsp) allways fails on detached or invalid session because the call of sess.close(); (in session-summary.jsp) fails. It should call the close method of the Session object, but if this is corrupt or…

So the issue could have something to do with SSL/TLS in combination with mina…

Meanwhile i have implemented a little workaround plugin which checks for invalid sessions and
restarts the connection listener for plain connections (5222 for clientsessions)

Release Version 1.1.1 · mightymop/openfire-sessioncheck-plugin

[pedimave]

Thanks @totzkotz for this workaround.

I have installed and configured as:

plugin.sessioncheck.enabled = true
plugin.sessioncheck.interva = 60
plugin.sessioncheck.mintorestart = 5

Keep you informed how it works and waiting at the same time for a final solution

Thanks again.

[pedimave]

@totzkotz Could you confirm that works with Openfire Beta 4.7?
Thanks.

[totzkotz]

nope… did not test it on 4.7 beta, but i cant see why it should not work… if you look into the source it is very simple

mightymop/openfire-sessioncheck-plugin/blob/main/src/java/org/igniterealtime/openfire/plugin/sessioncheck/SessionCheckPlugin.java

[pedimave]

I am not a Java developer, but let me to check It.

What I can see is that it tries to execute:

2022.01.04 16:44:47 INFO [Timer-7]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Checking Sessions…
2022.01.04 16:44:47 WARN [Timer-7]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Found enough invalid sessions to restart Connection Listener!
2022.01.04 16:44:47 INFO [Timer-7]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - done…

But not working.

[totzkotz]

ok seem that it need some more changes to restart ConnectionListener

[pedimave]

I have checked and review your code and I realized that it not the same that compiled one.

Before start doing any other thing it will be better to wait until you check the code.

It you will provided a new one, I can check it again.

Thnaks a lot.

[pedimave]

Hi @Gus, As you can see I can reproduce this problem and @totzkotz is working in a workaround.

If will be really interesting to kown if you have been able to detect where is the main issue related with it.

Thanks a lot.

----As I only have 3 answers I am going to edit this one to response.

Sorry @totzkotz but I get an error:

Excepción:
java.lang.NullPointerException
at org.jivesoftware.openfire.plugin.sessioncheck.sessioncheck_jsp._jspService(sessioncheck_jsp.java:146)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:71)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.jivesoftware.openfire.container.PluginServlet.handleJSP(PluginServlet.java:432)
at org.jivesoftware.openfire.container.PluginServlet.service(PluginServlet.java:122)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1459)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)
at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1626)
at org.jivesoftware.admin.PluginFilter.doFilter(PluginFilter.java:226)
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
at org.jivesoftware.admin.AuthCheckFilter.doFilter(AuthCheckFilter.java:234)
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
at com.opensymphony.sitemesh.webapp.SiteMeshFilter.obtainContent(SiteMeshFilter.java:129)
at com.opensymphony.sitemesh.webapp.SiteMeshFilter.doFilter(SiteMeshFilter.java:77)
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
…

If you confirm that works with 4.6.5, I can rollback to 4.6.6/7 and try it.

Thanks.

[totzkotz]

Release Version 1.1.1 · mightymop/openfire-sessioncheck-plugin

I’ve added an admin page …
If you click on manuel… then you should see sth like

2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Restart Connection Listener now
2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Stopped.
2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Done restarting...
2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Started.
2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Done restarting...
2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s-legacyMode] - Stopped.
2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s-legacyMode] - Done restarting...
2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s-legacyMode] - Started.
2022.01.04 18:21:43 INFO  [Jetty-QTP-AdminConsole-111789]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s-legacyMode] - Done restarting...

in the logs… the button triggers the same method as the timer does…

[totzkotz]

Sorry there was a copy & paste error… i fixed it in 1.1.1
i have it running on 4.5 and 4.6.6
but should work on 4.7 too

[pedimave]

Now there is no error and seems it working. we will see what happen tomorrow.

Thanks a lot @totzkotz for this pluggin. Really usefull.

2022.01.04 19:02:54 INFO [Jetty-QTP-AdminConsole-10082]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Stopped.
2022.01.04 19:02:54 INFO [Jetty-QTP-AdminConsole-10082]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Done restarting…
2022.01.04 19:02:54 INFO [Jetty-QTP-AdminConsole-10082]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Started.
2022.01.04 19:02:54 INFO [Jetty-QTP-AdminConsole-10082]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Done restarting…
2022.01.04 19:02:54 INFO [Jetty-QTP-AdminConsole-10082]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s-legacyMode] - Stopped.
2022.01.04 19:02:54 INFO [Jetty-QTP-AdminConsole-10082]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s-legacyMode] - Done restarting…
2022.01.04 19:02:54 INFO [Jetty-QTP-AdminConsole-10082]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s-legacyMode] - Started.
2022.01.04 19:02:54 INFO [Jetty-QTP-AdminConsole-10082]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s-legacyMode] - Done restarting…

2022.01.04 19:05:09 WARN [Timer-9]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Found 19 invalid sessions

2022.01.04 19:16:09 INFO [Timer-9]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Checking Sessions…
2022.01.04 19:16:09 WARN [Timer-9]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Found invalid session on jid: xxx@jabber.ofisat.net/Spark
2022.01.04 19:16:09 WARN [Timer-9]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Found invalid session on jid: xxxx@jabber.ofisat.net/Spark

2022.01.04 19:16:09 WARN [Timer-9]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Found 19 invalid sessions

[pedimave]

@totzkotz sorry to say that seems that is not working. At least with 4.7 version.

The message appear within log but not really executing the process.

2022.01.05 09:09:09 WARN [Timer-9]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Found 11 invalid sessions
2022.01.05 09:10:09 WARN [Timer-9]:
org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Found 22 invalid sessions

2022.01.05 09:10:58 ^[[32mINFO ^[[m [Jetty-QTP-AdminConsole-16519]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Stopped.
2022.01.05 09:10:58 ^[[32mINFO ^[[m [Jetty-QTP-AdminConsole-16519]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Started.
2022.01.05 09:10:58 ^[[32mINFO ^[[m [Jetty-QTP-AdminConsole-16519]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Done restarting…
2022.01.05 09:10:58 ^[[32mINFO ^[[m [Jetty-QTP-AdminConsole-16519]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Stopped.
2022.01.05 09:10:58 ^[[32mINFO ^[[m [Jetty-QTP-AdminConsole-16519]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Started.
2022.01.05 09:10:58 ^[[32mINFO ^[[m [Jetty-QTP-AdminConsole-16519]: org.jivesoftware.openfire.spi.ConnectionListener[socket_c2s] - Done restarting…

2022.01.05 09:11:09 ^[[33mWARN ^[[m [Timer-9]: org.igniterealtime.openfire.plugin.sessioncheck.SessionCheckPlugin - Found 54 invalid sessions

[totzkotz]

hm i did a test with 4.6.6. When i manually triggered the reconnect via admin console and switched to the sessions tab i could see that clients which where connected to 5222 got the detached state (stream management active). What about 4.7.? Same behavior?

[pedimave]

With 4.7 launched manually or automatically the processes are still appearing as invalid in session tab and the number or Invalid sessions are increasing.

The behaviour using your plugin seems diferent as if I force the “same” process using openfire in the original way.

My only option is to force it manually. Once done in this way the Invalid conection starts disappearing

[totzkotz]

ok i think just stopping and reenabling the Connection Listener is not enough in 4.7.
Strange…
The only thing i can do is to reinit the listener with a configuration…