Closed connections and deleted subscriptions on sleekxmpp/openfire.

[aepace]

Hi All: 

This is a cross-post of this post (https://discourse.igniterealtime.org/t/closed-connection-and-deleted-subscriptions-on-openfire-4-2-3/) to a more sleekxmpp-centric audience. 

I’ve been having a persistent issue with SleekXMPP and Openfire since upgrading my server (openfire) and client (now build on sleekxmpp, formally pyxmpp). 

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.

Here's what i'm seeing in openfire:

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

I turned on debugging in my sleekxmpp client, and here's what I'm seeing in the debug logs:

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/NAME_OF_LIBRARY/NAME_OF_PACKAGE/__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)

...

...

My questions are:

• What is going on? Could there be some error where exceptions are thrown into the XML stream that it causing openfire to freak out?
  
• 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.