AnsweredAssumed Answered

Unable to logon clients with Openfire 4.1

Question asked by Guillaume on Dec 28, 2016
Latest reply on Jun 14, 2017 by Johnny

I updated Openfire this morning from 4.0.4 to 4.1 on Windows 2008 R2 server with Active Directory.

Since the upgrade, no user can logon anymore (using Spark or another client, whatever client version or OS we are using).

We all got the error "Invalid username or password".

With my credentials (i am an admin), i can log on Openfire admin interface and see all the user accounts from active directory.

 

Restarting openfire service or the windows server didn't help.

 

On Openfire side, i got these entries in the logs :

* error.log

java.sql.SQLSyntaxErrorException: object name already exists: OFMUCCONVLOG_MSG_ID in statement [ CREATE INDEX ofMucConvLog_msg_id ON ofMucConversationLog (messageID)]

at org.hsqldb.jdbc.JDBCUtil.sqlException(Unknown Source)

at org.hsqldb.jdbc.JDBCUtil.sqlException(Unknown Source)

at org.hsqldb.jdbc.JDBCPreparedStatement.fetchResult(Unknown Source)

at org.hsqldb.jdbc.JDBCPreparedStatement.execute(Unknown Source)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at org.logicalcobwebs.proxool.ProxyStatement.invoke(ProxyStatement.java:100)

at org.logicalcobwebs.proxool.ProxyStatement.intercept(ProxyStatement.java:57)

at $java.sql.PreparedStatement$$EnhancerByProxool$$d81d3b4d.execute(<generated>)

at org.jivesoftware.database.SchemaManager.executeSQLScript(SchemaManager.java:380 )

at org.jivesoftware.database.SchemaManager.checkSchema(SchemaManager.java:282)

at org.jivesoftware.database.SchemaManager.checkOpenfireSchema(SchemaManager.java: 85)

at org.jivesoftware.database.DbConnectionManager.setConnectionProvider(DbConnectio nManager.java:606)

at org.jivesoftware.database.DbConnectionManager.ensureConnectionProvider(DbConnec tionManager.java:99)

at org.jivesoftware.database.DbConnectionManager.getConnection(DbConnectionManager .java:121)

at org.jivesoftware.util.JiveProperties.loadProperties(JiveProperties.java:357)

at org.jivesoftware.util.JiveProperties.init(JiveProperties.java:88)

at org.jivesoftware.util.JiveProperties.getInstance(JiveProperties.java:66)

at org.jivesoftware.util.JiveGlobals.getProperty(JiveGlobals.java:548)

at org.jivesoftware.util.cache.CacheFactory.<clinit>(CacheFactory.java:94)

at org.jivesoftware.openfire.XMPPServer.initialize(XMPPServer.java:311)

at org.jivesoftware.openfire.XMPPServer.start(XMPPServer.java:414)

at org.jivesoftware.openfire.XMPPServer.<init>(XMPPServer.java:163)

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)

at java.lang.reflect.Constructor.newInstance(Unknown Source)

at java.lang.Class.newInstance(Unknown Source)

at org.jivesoftware.openfire.starter.ServerStarter.start(ServerStarter.java:105)

at org.jivesoftware.openfire.starter.ServerStarter.main(ServerStarter.java:56)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at com.exe4j.runtime.LauncherEngine.launch(LauncherEngine.java:65)

at com.exe4j.runtime.WinLauncher$2.run(WinLauncher.java:96)

Caused by: org.hsqldb.HsqlException: object name already exists: OFMUCCONVLOG_MSG_ID

at org.hsqldb.error.Error.error(Unknown Source)

at org.hsqldb.error.Error.error(Unknown Source)

at org.hsqldb.SchemaObjectSet.checkAdd(Unknown Source)

at org.hsqldb.SchemaManager.checkSchemaObjectNotExists(Unknown Source)

at org.hsqldb.StatementSchema.setOrCheckObjectName(Unknown Source)

at org.hsqldb.StatementSchema.getResult(Unknown Source)

at org.hsqldb.StatementSchema.execute(Unknown Source)

at org.hsqldb.Session.executeCompiledStatement(Unknown Source)

at org.hsqldb.Session.execute(Unknown Source)

... 36 more

 

 

 

 

* warning.log

at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source)

at sun.nio.ch.IOUtil.read(Unknown Source)

at sun.nio.ch.SocketChannelImpl.read(Unknown Source)

at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:273)

at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:44)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoP rocessor.java:690)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPolling IoProcessor.java:664)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPolling IoProcessor.java:653)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPoll ingIoProcessor.java:67)

at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractP ollingIoProcessor.java:1124)

at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

2016.12.28 10:08:35 org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection due to exception in session: (0x0000000A: nio socket, server, /90.65.144.68:51987 => 0.0.0.0/0.0.0.0:5222)

java.io.IOException: Une connexion existante a dû être fermée par l'hôte distant

at sun.nio.ch.SocketDispatcher.read0(Native Method)

at sun.nio.ch.SocketDispatcher.read(Unknown Source)

at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source)

at sun.nio.ch.IOUtil.read(Unknown Source)

at sun.nio.ch.SocketChannelImpl.read(Unknown Source)

at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:273)

at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:44)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoP rocessor.java:690)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPolling IoProcessor.java:664)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPolling IoProcessor.java:653)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPoll ingIoProcessor.java:67)

at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractP ollingIoProcessor.java:1124)

at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

2016.12.28 10:08:35 org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection due to exception in session: (0x00000010: nio socket, server, /90.65.144.68:52024 => 0.0.0.0/0.0.0.0:5222)

java.io.IOException: Une connexion existante a dû être fermée par l'hôte distant

at sun.nio.ch.SocketDispatcher.read0(Native Method)

at sun.nio.ch.SocketDispatcher.read(Unknown Source)

at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source)

at sun.nio.ch.IOUtil.read(Unknown Source)

at sun.nio.ch.SocketChannelImpl.read(Unknown Source)

at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:273)

at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:44)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoP rocessor.java:690)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPolling IoProcessor.java:664)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPolling IoProcessor.java:653)

at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPoll ingIoProcessor.java:67)

at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractP ollingIoProcessor.java:1124)

at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

 

 

 

 

* debug.log

Queue : [MESSAGE_RECEIVED, ]

 

2016.12.28 10:13:03 org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a MESSAGE_RECEIVED for session 2

2016.12.28 10:13:03 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=198 cap=4096: 3C 69 71 20 74 79 70 65 3D 22 65 72 72 6F 72 22...]

2016.12.28 10:13:03 org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 2

Queue : [MESSAGE_SENT, ]

 

2016.12.28 10:13:33 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Message received : HeapBuffer[pos=0 lim=133 cap=256: 17 03 03 00 80 85 12 E8 04 2C 0D 4C BD CC B4 82...]

2016.12.28 10:13:33 org.apache.mina.filter.ssl.SslHandler - Session Server[2](SSL) Processing the received message

2016.12.28 10:13:33 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Processing the SSL Data

2016.12.28 10:13:33 org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_RECEIVED to session 2

Queue : [MESSAGE_RECEIVED, ]

 

2016.12.28 10:13:33 org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a MESSAGE_RECEIVED for session 2

2016.12.28 10:13:33 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=198 cap=4096: 3C 69 71 20 74 79 70 65 3D 22 65 72 72 6F 72 22...]

2016.12.28 10:13:33 org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 2

Queue : [MESSAGE_SENT, ]

 

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: sessions. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: server_bytes. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: muc_occupants. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: proxyTransferRate. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: conversations. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: muc_traffic. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: packet_count. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: muc_rooms. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: server_sessions. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:13:57 org.jivesoftware.openfire.reporting.stats.StatsEngine - Stat: muc_users. Last sample: 1482916320. New sample: 1482916380

2016.12.28 10:14:03 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Message received : HeapBuffer[pos=0 lim=133 cap=256: 17 03 03 00 80 29 98 6F 1B 92 30 3A B5 C1 42 51...]

2016.12.28 10:14:03 org.apache.mina.filter.ssl.SslHandler - Session Server[2](SSL) Processing the received message

2016.12.28 10:14:03 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Processing the SSL Data

2016.12.28 10:14:03 org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_RECEIVED to session 2

Queue : [MESSAGE_RECEIVED, ]

 

2016.12.28 10:14:03 org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a MESSAGE_RECEIVED for session 2

2016.12.28 10:14:03 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=198 cap=4096: 3C 69 71 20 74 79 70 65 3D 22 65 72 72 6F 72 22...]

2016.12.28 10:14:03 org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 2

Queue : [MESSAGE_SENT, ]

 

2016.12.28 10:14:33 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Message received : HeapBuffer[pos=0 lim=133 cap=256: 17 03 03 00 80 5F 08 D4 D1 F3 29 BF 43 00 69 EC...]

2016.12.28 10:14:33 org.apache.mina.filter.ssl.SslHandler - Session Server[2](SSL) Processing the received message

2016.12.28 10:14:33 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Processing the SSL Data

2016.12.28 10:14:33 org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_RECEIVED to session 2

Queue : [MESSAGE_RECEIVED, ]

 

2016.12.28 10:14:33 org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a MESSAGE_RECEIVED for session 2

2016.12.28 10:14:33 org.apache.mina.filter.ssl.SslFilter - Session Server[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=198 cap=4096: 3C 69 71 20 74 79 70 65 3D 22 65 72 72 6F 72 22...]

2016.12.28 10:14:33 org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 2

Queue : [MESSAGE_SENT, ]

 

And on my Spark 2.8.2 debug window :

* Raw sent packets

<stream:stream xmlns='jabber:client' to='lan.domain.com' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='myuser@lan.domain.com' xml:lang='en'>

<starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'></starttls>

<stream:stream xmlns='jabber:client' to='lan.domain.com' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='myuser@lan.domain.com' xml:lang='en'>

<iq to='lan.domain.com' id='385-14' type='result'></iq>

<iq to='lan.domain.com' id='399-16' type='result'></iq>

 

 

 

 

* Raw received packets

<?xml version='1.0' encoding='UTF-8'?><stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" from="lan.domain.com" id="6ef5185w5b" xml:lang="en" version="1.0">

<stream:features><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"></starttls><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>GSSAPI</mechanism></mechani sms><compression xmlns="http://jabber.org/features/compress"><method>zlib</method></compression></stream:features>

<proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>

<?xml version='1.0' encoding='UTF-8'?><stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" from="lan.domain.com" id="6ef5185w5b" xml:lang="en" version="1.0"><stream:features><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>GSSAPI</mechanism></mechani sms><compression xmlns="http://jabber.org/features/compress"><method>zlib</method></compression></stream:features>

<iq type="get" id="385-14" from="lan.domain.com" to="lan.domain.com/6ef5185w5b"><ping xmlns="urn:xmpp:ping"/></iq>

<iq type="get" id="399-16" from="lan.domain.com" to="lan.domain.com/6ef5185w5b"><ping xmlns="urn:xmpp:ping"/></iq>

Any idea ?

Outcomes