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

Wojciech Kapcia (Tigase) opened 3 hours 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

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 (2)

Reference

tigase/_server/server-core#1563