Closed Connection and Deleted Subscriptions on Openfire 4.2.3

Openfire
1

Hi All:

I’ve been having a persistent issue with Openfire since upgrading to 4.2.3 last year, and the issue persists in 4.3.0.

Here’s the scenario: I’m running a custom xmpp client based on sleekxmpp using the xep-0060 (pubsub) protocol. Most of the time, the client runs great and stably. However, if a pubsub listening client somehow throws an exception (the client is written in python), then the client’s connection is terminated AND the client’s pubsub subscriptions are deleted, even to the point where the entries are deleted from the ofPubsubSubscriptions table in Openfire’s database.

If I modify the client with better “try:… except:” exception trapping, then the clients’ connection works just fine.

My questions are:

  1. What is going on? Could there be some error where exceptions are thrown into the XML stream that it causing openfire to freak out?
  2. Are there server versions or settings I can set to make the clients’ connections more robust?

There are unsurprisingly little in the logs, but the below was sound in warn.log as the above behavior was observed. I’ve zero’ed out the source and client IP addresses for privacy.

Thanks all.

2019.01.27 11:58:21 org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection due to exception in session: (0x0000003D: nio socket, server, /XXX.XXX.XXX.XXX:5134 => /YYY.YYY.YYY.YYY:5222)
javax.net.ssl.SSLHandshakeException: SSL handshake failed.
        at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:487)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
        at org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:410)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:710)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:664)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:653)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1124)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: javax.net.ssl.SSLException: Unrecognized SSL message, plaintext connection?
        at sun.security.ssl.EngineInputRecord.bytesInCompletePacket(EngineInputRecord.java:156)
        at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:868)
        at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
        at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
        at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:728)
        at org.apache.mina.filter.ssl.SslHandler.unwrapHandshake(SslHandler.java:666)
        at org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:552)
        at org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:351)
        at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:468)
        ... 15 more
2

I can’t be sure what’s going on, but it may be worth temporarily installing the XML Debugger plugin: https://www.igniterealtime.org/projects/openfire/plugin-archive.jsp?plugin=xmldebugger

It will log (to stdout or file) all the traffic to/from the server, you should at least be able to see what’s going back and forth.

Greg

3

Thanks for the reply. For another data point, I enabled debugging on my client and got the following traceback:

DEBUG    Event triggered: pubsub_publish
ERROR    Error processing event handler: <bound method NAME_OF_OBJECT._pubsub_publish of <NAME_OF_OBJECT object at 0x7f17daa09a50>>
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/sleekxmpp/xmlstream/xmlstream.py", line 1710, in _event_runner
    func(*args)
  File "/usr/lib/python2.7/site-packages/ligo/lvalert/__init__.py", line 170, in _pubsub_publish
    msg['pubsub_event']['items']['item']['payload'].text)
IntegrityError: PRIMARY KEY must be unique (<-- this is the error exception that I create, in this case it's actually from sqlite, but it could be any exception that gets created) 
ERROR    Error handling {jabber:client}message stanza
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/sleekxmpp/xmlstream/xmlstream.py", line 1710, in _event_runner
    func(*args)
  File "/usr/lib/python2.7/site-packages/NAME_OF_LIBRARY/NAME_OF_PACKAGE/__init__.py", line 170, in _pubsub_publish
    msg['pubsub_event']['items']['item']['payload'].text)
...
...
4

Does anyone else have any insight on this? I’ve seen the same behavior with some older pyxmpp-based clients too, so I think it might be related to openfire.