Long delay to open the ports after server startup with cluster mode enabled (#1563)

Wojciech Kapcia (Tigase) opened 11 months ago

There is a ~15s delay between Tigase finishes starting up and actually starts listening on the ports. This mechanism was introduced to prevent data inconsistency when adding new node while not being correctly and fully connected to the cluster. However it looks like the logic detecting that state is not working correctly. On my local machine with single Tigase instance there is a long delay:

[2025-06-27 15:52:14:676] [INFO    ] [                  main ] XMPPServer.start()               : Server finished starting up in (11s) and (if there wasn't any error) is ready to use

[2025-06-27 15:52:14:677] [INFO    ] [      pool-1-thread-14 ] SchemaVersionCheckerLogger.printSnapshotInformation():

	It's possible that following data sources are out of date:
		* http-api (JDBCFileUploadRepository) ~ version in database: 2.5.0-SNAPSHOT-b584, required version: 2.5.0-SNAPSHOT-b589)
		* message-archiving (JDBCMessageArchiveRepository) ~ version in database: 3.3.0-SNAPSHOT-b352, required version: 3.3.0-SNAPSHOT-b352)
		* pubsub (PubSubDAOJDBC) ~ version in database: 5.3.0-SNAPSHOT-b858, required version: 5.3.0-SNAPSHOT-b858)
		* server (TigaseCustomAuth) ~ version in database: 8.5.0-SNAPSHOT-b6443, required version: 8.5.0-SNAPSHOT-b6447)
	Please upgrade the installation by running:
		$ ./scripts/tigase.sh upgrade-schema etc/tigase.conf

	(this warning is printed each time SNAPSHOT version is started, you can ignore this
	message if you've just run above command)

[2025-06-27 15:52:32:312] [INFO    ] [      pool-1-thread-21 ] JettyStandaloneHttpServer.startupServer(): Starting listening on ports of HTTP server
[2025-06-27 15:52:32:312] [INFO    ] [      pool-1-thread-20 ] BoshConnectionClustered.lambda$start$0(): Starting listening on ports of component: bosh
[2025-06-27 15:52:32:312] [INFO    ] [      pool-1-thread-24 ] WebSocketClientConnectionClustered.lambda$start$0(): Starting listening on ports of component: ws2s
[2025-06-27 15:52:32:313] [INFO    ] [      pool-1-thread-22 ] ClientConnectionClustered.lambda$start$0(): Starting listening on ports of component: c2s

Wich cluster mode off ('cluster-mode' = 'false') Listening is immediate (though there is no information that the prots stated already, IMHO we could/shoud add it as well):

[2025-06-27 15:54:12:886] [INFO    ] [       pool-1-thread-7 ] SchemaVersionCheckerLogger.printSnapshotInformation():

	It's possible that following data sources are out of date:
		* http-api (JDBCFileUploadRepository) ~ version in database: 2.5.0-SNAPSHOT-b584, required version: 2.5.0-SNAPSHOT-b589)
		* message-archiving (JDBCMessageArchiveRepository) ~ version in database: 3.3.0-SNAPSHOT-b352, required version: 3.3.0-SNAPSHOT-b352)
		* pubsub (PubSubDAOJDBC) ~ version in database: 5.3.0-SNAPSHOT-b858, required version: 5.3.0-SNAPSHOT-b858)
		* server (TigaseCustomAuth) ~ version in database: 8.5.0-SNAPSHOT-b6443, required version: 8.5.0-SNAPSHOT-b6447)
	Please upgrade the installation by running:
		$ ./scripts/tigase.sh upgrade-schema etc/tigase.conf

	(this warning is printed each time SNAPSHOT version is started, you can ignore this
	message if you've just run above command)

[2025-06-27 15:54:14:872] [INFO    ] [  ConnectionOpenThread ] SocketThread.<clinit>()          : 41 socketReadThreads started.
[2025-06-27 15:54:14:883] [INFO    ] [  ConnectionOpenThread ] SocketThread.<clinit>()          : 41 socketWriteThreads started.

Detailed log

[2025-06-27 15:57:14:305] [CONFIG  ] [         cluster-nodes ] ConfigRepository.addItemNoStore(): Calling itemUpadted for: atlantiscity.local:0634ec4c541a176ee82b7f2fb14730211629e02213861d5857575a77e1736467:5277:17
51032634290:95.87962:37.883476:atlantiscity
[2025-06-27 15:57:14:311] [FINE    ] [      pool-1-thread-18 ] SeeOtherHostDualIP.clusterRepoItemEvent(): Procesing ClusterRepoItemEvent: item=atlantiscity.local:0634ec4c541a176ee82b7f2fb14730211629e02213861d585757
5a77e1736467:5277:1751032634290:95.87962:37.883476:atlantiscity, action=UPDATED
[2025-06-27 15:57:14:311] [FINE    ] [      pool-1-thread-19 ] SeeOtherHostDualIP.clusterRepoItemEvent(): Procesing ClusterRepoItemEvent: item=atlantiscity.local:0634ec4c541a176ee82b7f2fb14730211629e02213861d585757
5a77e1736467:5277:1751032634290:95.87962:37.883476:atlantiscity, action=UPDATED
[2025-06-27 15:57:14:311] [FINE    ] [      pool-1-thread-17 ] SeeOtherHostDualIP.clusterRepoItemEvent(): Procesing ClusterRepoItemEvent: item=atlantiscity.local:0634ec4c541a176ee82b7f2fb14730211629e02213861d585757
5a77e1736467:5277:1751032634290:95.87962:37.883476:atlantiscity, action=UPDATED
[2025-06-27 15:57:14:312] [FINE    ] [      pool-1-thread-18 ] SeeOtherHostDualIP.clusterRepoItemEvent(): Redirection item :: hostname: atlantiscity.local, secondary: atlantiscity, added/updated! Replaced: null
[2025-06-27 15:57:14:312] [FINE    ] [      pool-1-thread-17 ] SeeOtherHostDualIP.clusterRepoItemEvent(): Redirection item :: hostname: atlantiscity.local, secondary: atlantiscity, added/updated! Replaced: null
[2025-06-27 15:57:14:312] [FINE    ] [      pool-1-thread-19 ] SeeOtherHostDualIP.clusterRepoItemEvent(): Redirection item :: hostname: atlantiscity.local, secondary: atlantiscity, added/updated! Replaced: null
[2025-06-27 15:57:29:289] [FINER   ] [      pool-1-thread-20 ] ConnectionManager.connectWaitingTasks(): Connecting waitingTasks: []
[2025-06-27 15:57:29:291] [FINEST  ] [      pool-1-thread-20 ] ConnectionManager$PortConfigBean.beanConfigurationChanged(): connectionManager: tigase.cluster.WebSocketClientConnectionClustered@77d695f2, changedFiel
ds: [], props: {remote-host=localhost, port-no=5290, new-connections-throttling=200, ifc=[Ljava.lang.String;@9cd7eef, socket=plain, type=accept}
[2025-06-27 15:57:29:291] [FINE    ] [      pool-1-thread-20 ] ConnectionManager.startService() : Starting service: {remote-host=localhost, port-no=5290, new-connections-throttling=200, ifc=[Ljava.lang.String;@9cd7
eef, socket=plain, type=accept}
[2025-06-27 15:57:29:292] [INFO    ] [      pool-1-thread-20 ] WebSocketClientConnectionClustered.lambda$start$0(): Starting listening on ports of component: ws2s
[2025-06-27 15:57:29:293] [FINEST  ] [  ConnectionOpenThread ] ConnectionOpenThread.run()       : Selected: 0 from selector: sun.nio.ch.KQueueSelectorImpl@18206935
[2025-06-27 15:57:29:294] [INFO    ] [      pool-1-thread-23 ] JettyStandaloneHttpServer.startupServer(): Starting listening on ports of HTTP server
[2025-06-27 15:57:29:294] [FINEST  ] [  ConnectionOpenThread ] ConnectionOpenThread.addISA()    : Setting up throttling for the port 5,290 to 200 connections per second. isa: 0.0.0.0/0.0.0.0:5290
[2025-06-27 15:57:29:297] [FINEST  ] [  ConnectionOpenThread ] ConnectionOpenThread.addISA()    : Setting up 'accept' channel...
[2025-06-27 15:57:29:298] [FINER   ] [      pool-1-thread-24 ] ConnectionManager.connectWaitingTasks(): Connecting waitingTasks: []

Activities

Wojciech Kapcia (Tigase) commented 10 months ago

Possibly related to #1228 (result of #1119) and atom#293
Andrzej Wójcik (Tigase) commented 2 weeks ago

I've analyzed the issue and prepared a fix for it. It is in server-1563 branch. In this fix, I've speed up reload of the cluster nodes repository items, so they are now available faster. Then I've delayed notifications of connections managers, that they can open as cluster nodes are connected, until server startup is finished.

With those changes, when all connections are ready and when server startup is completed, then connection managers will start listening in the cluster mode.
Andrzej Wójcik (Tigase) changed state to 'In QA' 2 weeks ago
Previous Value Current Value
Open

In QA
Wojciech Kapcia (Tigase) commented 2 weeks ago

Looks OK.

Rebased & merged.
Wojciech Kapcia (Tigase) changed state to 'Closed' 2 weeks ago
Previous Value Current Value
In QA

Closed
Login to comment

Previous Value	Current Value
Open	In QA

Previous Value	Current Value
In QA	Closed

Type	Improvement
Priority	Normal
Assignee	Wojciech Kapcia (Tigase)
Version	8.5.0
Sprints	n/a
Customer	n/a

Iterations

tigase-server-8.5.0 Open

Issue Votes (0)

Watchers (3)

Reference

tigase/_server/server-core#1563