Some DB Issues (SQL Server) with 4.7.1

Hey,

i have setup a new instance of OF 4.7.1 and changed the routers/firewall etc. to point to this new fresh instance.
DB was also new but using sharedrosters.
The clients were not changed… so only server was changed to new instance (but same xmpp domain,…)
Clients: Conversations / Gajim
My problem is that the logs are flooded with

2022.04.05 13:19:34 org.jivesoftware.openfire.pubsub.DefaultPubSubPersistenceProvider - An exception occurred while creating an affiliation (org.jivesoftware.openfire.pubsub.NodeAffiliate@6ee9e336 - JID: USER_B@DOMAIN - Affiliation: none) to a node (UniqueIdentifier{serviceId='USER_A@DOMAIN', nodeId='USER_A@DOMAIN'}) in the database.
java.sql.SQLException: Violation of PRIMARY KEY constraint 'ofPubsubAffiliation_pk'. Cannot insert duplicate key in object 'ofPubsubAffiliation'. The duplicate key value is (USER_A@DOMAIN, USER_A@DOMAIN, USER_B@DOMAIN).
	at net.sourceforge.jtds.jdbc.SQLDiagnostic.addDiagnostic(SQLDiagnostic.java:372) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.TdsCore.tdsErrorToken(TdsCore.java:2988) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2421) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.TdsCore.getMoreResults(TdsCore.java:671) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.JtdsStatement.processResults(JtdsStatement.java:613) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQL(JtdsStatement.java:572) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeUpdate(JtdsPreparedStatement.java:727) ~[jtds-1.3.1.jar:1.3.1]
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136) ~[commons-dbcp2-2.9.0.jar:2.9.0]
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136) ~[commons-dbcp2-2.9.0.jar:2.9.0]
	at org.jivesoftware.openfire.pubsub.DefaultPubSubPersistenceProvider.createAffiliation(DefaultPubSubPersistenceProvider.java:1021) ~[xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.pubsub.CachingPubsubPersistenceProvider.process(CachingPubsubPersistenceProvider.java:383) ~[xmppserver-4.7.1.jar:4.7.1]
	at java.util.ArrayList.forEach(ArrayList.java:1541) [?:?]
	at org.jivesoftware.openfire.pubsub.CachingPubsubPersistenceProvider.flushPendingNodes(CachingPubsubPersistenceProvider.java:143) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.pubsub.CachingPubsubPersistenceProvider.flushPendingChanges(CachingPubsubPersistenceProvider.java:540) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.pubsub.CachingPubsubPersistenceProvider$1.run(CachingPubsubPersistenceProvider.java:94) [xmppserver-4.7.1.jar:4.7.1]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]

and

2022.04.05 13:19:34 org.jivesoftware.openfire.pubsub.DefaultPubSubPersistenceProvider - An exception occurred while creating a subscription (org.jivesoftware.openfire.pubsub.NodeSubscription@5d1a3001 - JID: USER_A@DOMAIN - State: subscribed) to a node (UniqueIdentifier{serviceId='USER_B@DOMAIN', nodeId='USER_B@DOMAIN'}) in the database.
java.sql.SQLException: Violation of PRIMARY KEY constraint 'ofPubsubSubscription_pk'. Cannot insert duplicate key in object 'ofPubsubSubscription'. The duplicate key value is (USER_B@DOMAIN, USER_B@DOMAIN, 47PG9v55Ye5ZiMdDo4qf2gSjUqtgnxIXR4yIoF9s).
	at net.sourceforge.jtds.jdbc.SQLDiagnostic.addDiagnostic(SQLDiagnostic.java:372) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.TdsCore.tdsErrorToken(TdsCore.java:2988) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2421) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.TdsCore.getMoreResults(TdsCore.java:671) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.JtdsStatement.processResults(JtdsStatement.java:613) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQL(JtdsStatement.java:572) ~[jtds-1.3.1.jar:1.3.1]
	at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeUpdate(JtdsPreparedStatement.java:727) ~[jtds-1.3.1.jar:1.3.1]
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136) ~[commons-dbcp2-2.9.0.jar:2.9.0]
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136) ~[commons-dbcp2-2.9.0.jar:2.9.0]
	at org.jivesoftware.openfire.pubsub.DefaultPubSubPersistenceProvider.createSubscription(DefaultPubSubPersistenceProvider.java:1123) ~[xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.pubsub.CachingPubsubPersistenceProvider.process(CachingPubsubPersistenceProvider.java:395) ~[xmppserver-4.7.1.jar:4.7.1]
	at java.util.ArrayList.forEach(ArrayList.java:1541) [?:?]
	at org.jivesoftware.openfire.pubsub.CachingPubsubPersistenceProvider.flushPendingNodes(CachingPubsubPersistenceProvider.java:143) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.pubsub.CachingPubsubPersistenceProvider.findDirectlySubscribedNodes(CachingPubsubPersistenceProvider.java:260) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.pep.PEPServiceManager.findSubscribedNodes(PEPServiceManager.java:379) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.pep.PEPServiceManager.entityCapabilitiesChanged(PEPServiceManager.java:337) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.entitycaps.EntityCapabilitiesManager.dispatch(EntityCapabilitiesManager.java:673) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.entitycaps.EntityCapabilitiesManager.registerCapabilities(EntityCapabilitiesManager.java:570) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.entitycaps.EntityCapabilitiesManager.process(EntityCapabilitiesManager.java:229) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:142) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.PresenceRouter.route(PresenceRouter.java:79) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:84) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.net.StanzaHandler.processPresence(StanzaHandler.java:387) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.net.ClientStanzaHandler.processPresence(ClientStanzaHandler.java:102) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:280) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:198) [xmppserver-4.7.1.jar:4.7.1]
	at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandler.java:183) [xmppserver-4.7.1.jar:4.7.1]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:1015) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:650) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:49) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1128) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:122) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:650) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:49) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1128) [mina-core-2.1.6.jar:?]
	at org.apache.mina.filter.codec.ProtocolCodecFilter$ProtocolDecoderOutputImpl.flush(ProtocolCodecFilter.java:418) [mina-core-2.1.6.jar:?]
	at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:257) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:650) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:49) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1128) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:106) [mina-core-2.1.6.jar:?]
	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:89) [mina-core-2.1.6.jar:?]
	at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(OrderedThreadPoolExecutor.java:763) [mina-core-2.1.6.jar:?]
	at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(OrderedThreadPoolExecutor.java:755) [mina-core-2.1.6.jar:?]
	at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(OrderedThreadPoolExecutor.java:695) [mina-core-2.1.6.jar:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]

and

2022.04.05 12:58:02 org.jivesoftware.openfire.pubsub.DefaultPubSubPersistenceProvider - Subscription found for a non-existent affiliate: USER_A@DOMAIN in node: UniqueIdentifier{serviceId='USER_B@DOMAIN', nodeId='USER_B@DOMAIN'}

In the same time the log is flooding, the cpu cores are working on maximum levels…

Wasn’t there a change in the PEP service implementation after version 4.5?

This issue produces 10000+ Exceptions per hour… -.-

I have craeated this PR: fix: prevent inserting affiliations and subscriptions to db if allready exists by mightymop · Pull Request #2043 · igniterealtime/Openfire · GitHub and will test it now and will come back with results…

EDIT: it seems to fix the issue

Hi - sorry for being so late to respond. How can I reproduce this problem? I’d like to find the root cause, and not so much allow data that is supposed to be unique to be overwritten. If we’re unlucky, data corruption is introduced that way.

The issue only occurs on our production system but not on the testsystem… so hard to say what is causing it… the difference is the amount of users currently logged in but they are mostly not more then 400!?
I saw in the code (in one class) that you allready had a member variable to check if the object is allready in the db or not and i clonded the checks for the other classes too.
The PR fixes the issue on my system. Maybe it is a timing problem between flushing/clearing the cache and writing data to DB

PS:
i am using SQL Server

I have created a new JIRA issue for this problem: [OF-2437] - Ignite Realtime Jira

A workaround for this issue is to replace the pubsub persistence provider (which defaults to org.jivesoftware.openfire.pubsub.CachingPubsubPersistenceProvider in a non-clustered environment) with org.jivesoftware.openfire.pubsub.DefaultPubSubPersistenceProvider.

This can be done by configuring the property provider.pubsub-persistence.className with value org.jivesoftware.openfire.pubsub.DefaultPubSubPersistenceProvider