Fail to replicate after creation of a new database in Leader

[angkor-wat]

ArcadeDB Version:

ArcadeDB Server v23.6.1

OS and JDK Version:

Running on Linux 3.10.0-1160.92.1.el7.x86_64 - Java HotSpot(TM) 64-Bit Server VM 11.0.20 (18.9)
CentOS Linux release 7.4.1708 (Core)

Expected behavior

replicate the new database from Leader to Replica

Actual behavior

fail to replicate, with the error log below:

+----------+--------------------+-------+------+-----------------------+-------+--------------+-------+ |SERVER |HOST/PORT |ROLE |STATUS|JOINED ON |LEFT ON|THROUGHPUT |LATENCY| +----------+--------------------+-------+------+-----------------------+-------+--------------+-------+ |server_177|test-arcadedb:2424 |Leader |ONLINE|2023-08-14 19:56:34.044| | | | |server_182|test-arcadedb-2:2424|Replica|ONLINE|2023-08-14 20:01:50.356| |50b (2.00GB/s)| | +----------+--------------------+-------+------+-----------------------+-------+--------------+-------+ <server_177> Error on command execution (PostServerCommandHandler) java.lang.ClassCastException: class com.arcadedb.server.ServerDatabase cannot be cast to class com.arcadedb.server.ha.ReplicatedDatabase (com.arcadedb.server.ServerDatabase and com.arcadedb.server.ha.ReplicatedDatabase are in unnamed module of loader 'app') at com.arcadedb.server.http.handler.PostServerCommandHandler.createDatabase(PostServerCommandHandler.java:179) at com.arcadedb.server.http.handler.PostServerCommandHandler.execute(PostServerCommandHandler.java:69) at com.arcadedb.server.http.handler.AbstractHandler.handleRequest(AbstractHandler.java:124) at io.undertow.server.Connectors.executeRootHandler(Connectors.java:393) at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:859) at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538) at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282) at java.base/java.lang.Thread.run(Thread.java:834)

Steps to reproduce

1. start server server_177 (with ARCADEDB_SETTINGS="-Darcadedb.server.databaseDirectory=/data -Darcadedb.ha.enabled=true -Darcadedb.ha.clusterName=cluster_1 -Darcadedb.ha.serverList=test-arcadedb:2424,test-arcadedb-2:2424 -Darcadedb.server.name=server_177")
2. start server server_182 (with ARCADEDB_SETTINGS="-Darcadedb.server.databaseDirectory=/data -Darcadedb.ha.enabled=true -Darcadedb.ha.clusterName=cluster_1 -Darcadedb.ha.serverList=test-arcadedb:2424,test-arcadedb-2:2424 -Darcadedb.server.name=server_182")
3. open Studio, and create a new database 'test2'

[angkor-wat]

###Additional information

I try to manually trigger replication by click the "Align Database" button on the Cluster page of the studio, and then see the error message as below:
2023-08-14 21:10:49.366 INFO [Replica2LeaderNetworkExecutor] <server_182> Exception during execution of request 5 (shutdown=false name=ArcadeDB-ha-replica2leader/server_182/server_177 error=com.arcadedb.exception.DatabaseOperationException: Database '/data/test2' does not exist) 2023-08-14 21:10:49.369 SEVER [Replica2LeaderNetworkExecutor] <server_182> Error on communication between current replica and the Leader ('server_177'), reconnecting... (error=com.arcadedb.exception.DatabaseOperationException: Database '/data/test2' does not exist)

But the studio popups "Align database execution ok!" after seconds, while the replication fails in fact.

[lvca]

Reproduced the issue. Working for a fix.

[angkor-wat]

Maybe, dropping database meets the same bug. Pls fix them all at 23.7.1. Thanks a lot.

Dear Ivca, thanks for your timely response. I truly realized and believe your goal, and wish to rely on it as the unique database in our ToB SaaS project...

[lvca]

@angkor-wat do you have a stack trace of the exception?

[angkor-wat]

Steps to reproduce

1. Drop database test2 in studio.
2. By checking studio and file path "/data/", I believe that Test2 in Leader is dropped.
3. By checking studio and file path "/data/", I confirm that Test2 in Replica is not dropped.

But no any message , 2 consoles remain silent.

Leader:

023-08-15 15:13:32.992 INFO [ReplicaConnectRequest] <server_177> Hot backup with Replica server 'server_182' is possible (lastReplicationMessageNumber=44)
2023-08-15 15:13:32.999 INFO [HAServer] <server_177> Recovering completed. Sent 2 message(s) to replica 'server_182' (44-45)
2023-08-15 15:13:33.000 INFO [Leader2ReplicaNetworkExecutor$4] <server_177> Replica server 'server_182' is ONLINE
2023-08-15 15:13:33.001 INFO [HAServer] <server_177> NEW CLUSTER CONFIGURATION

+----------+--------------------+-------+------+-----------------------+-------+--------------+-------+
|SERVER |HOST/PORT |ROLE |STATUS|JOINED ON |LEFT ON|THROUGHPUT |LATENCY|
+----------+--------------------+-------+------+-----------------------+-------+--------------+-------+
|server_177|test-arcadedb:2424 |Leader |ONLINE|2023-08-15 15:13:28.585| | | |
|server_182|test-arcadedb-2:2424|Replica|ONLINE|2023-08-15 15:13:33.000| |71b (2.00GB/s)| |
+----------+--------------------+-------+------+-----------------------+-------+--------------+-------+

2023-08-15 15:13:33.001 INFO [HAServer] <server_177> Change election status from LEADER_WAITING_FOR_QUORUM to DONE

Replica:

2023-08-15 15:13:32.940 INFO [Replica2LeaderNetworkExecutor] <server_182> Server connected to the Leader server test-arcadedb:2424, members=[test-arcadedb-3:2424,test-arcadedb-2:2424,test-arcadedb:2424]
2023-08-15 15:13:32.966 INFO [Replica2LeaderNetworkExecutor] <server_182> Server started as Replica in HA mode (cluster=cluster_1 leader=test-arcadedb:2424)
2023-08-15 15:13:32.967 INFO [Replica2LeaderNetworkExecutor] <server_182> Requesting install of databases...
2023-08-15 15:13:32.968 INFO [threads] JBoss Threads version 3.5.0.Final
2023-08-15 15:13:32.998 INFO [Replica2LeaderNetworkExecutor] <server_182> Receiving hot resync (from=44)...
2023-08-15 15:13:33.005 INFO [HAServer] <server_182> Change election status from VOTING_FOR_OTHERS to DONE
2023-08-15 15:13:33.045 INFO [HttpServer] <server_182> - HTTP Server started (host=0.0.0.0 port=2480 httpsPort=2490)
2023-08-15 15:13:33.045 INFO [ArcadeDBServer] <server_182> Available query languages: [sqlscript, mongo, gremlin, java, cypher, js, graphql, sql]
2023-08-15 15:13:33.047 INFO [ArcadeDBServer] <server_182> ArcadeDB Server started in 'development' mode (CPUs=1 MAXRAM=239.75MB)
2023-08-15 15:13:33.064 INFO [ArcadeDBServer] <server_182> Studio web tool available at http://test-arcadedb-2:2480
2023-08-15 15:13:34.728 INFO [HAServer] Abort election process, a Leader (server_177) has been already found (turn=1)

4. Shutdown Replica by Ctrl+C, then comes "..SocketException..":

2023-08-15 15:13:33.047 INFO [ArcadeDBServer] <server_182> ArcadeDB Server started in 'development' mode (CPUs=1 MAXRAM=239.75MB)
2023-08-15 15:13:33.064 INFO [ArcadeDBServer] <server_182> Studio web tool available at http://test-arcadedb-2:2480
2023-08-15 15:13:34.728 INFO [HAServer] Abort election process, a Leader (server_177) has been already found (turn=1)^C
2023-08-15 16:20:49.765 INFO [ArcadeDBServer] Shutting down ArcadeDB Server...
2023-08-15 16:20:49.771 INFO [Replica2LeaderNetworkExecutor] <server_182> Exception during execution of request -1 (shutdown=true name=ArcadeDB-ha-replica2leader/server_182/server_177 error=java.net.SocketException: Socket closed)
2023-08-15 16:20:49.771 INFO [Replica2LeaderNetworkExecutor] <server_182> Replica message thread closed (shutdown=true name=ArcadeDB-ha-replica2leader/server_182/server_177 threadId=29)
2023-08-15 16:20:49.773 INFO [undertow] stopping server: Undertow - 2.3.7.Final
2023-08-15 16:20:49.776 SEVER [CodeUtils] Error closing database 'test2'
2023-08-15 16:20:49.776 SEVER [CodeUtils] Error closing database 'test3'
2023-08-15 16:20:49.776 SEVER [CodeUtils] Error closing database 'test'
2023-08-15 16:20:49.776 INFO [ArcadeDBServer] - Stop JMX Metrics
2023-08-15 16:20:49.776 INFO [ArcadeDBServer] ArcadeDB Server is down[root@test-arcadedb-2 arcadedb-23.6.1]#

5. Shutdown Leader by Ctrl+C:

2023-08-15 16:20:49.772 INFO [Leader2ReplicaNetworkExecutor$4] <server_177> Replica server 'server_182' is OFFLINE
2023-08-15 16:20:50.265 INFO [HAServer] <server_177> NEW CLUSTER CONFIGURATION

+----------+--------------------+-------+-------+-----------------------+-----------------------+----------+-------+
|SERVER |HOST/PORT |ROLE |STATUS |JOINED ON |LEFT ON |THROUGHPUT|LATENCY|
+----------+--------------------+-------+-------+-----------------------+-----------------------+----------+-------+
|server_177|test-arcadedb:2424 |Leader |ONLINE |2023-08-15 15:13:28.585| | | |
|server_182|test-arcadedb-2:2424|Replica|OFFLINE|2023-08-15 15:13:33.000|2023-08-15 16:20:49.772|71b (0b/s)| |
+----------+--------------------+-------+-------+-----------------------+-----------------------+----------+-------+
^C
2023-08-15 16:24:42.049 INFO [ArcadeDBServer] Shutting down ArcadeDB Server...
2023-08-15 16:24:42.054 INFO [undertow] stopping server: Undertow - 2.3.7.Final[root@test-arcadedb arcadedb-23.6.1]#

[lvca]

@angkor-wat do you drop the database by using Studio (therefore HTTP API)? Also, does this still happen with 23.9.1-SNAPSHOT? I pushed a couple of fixes yesterday.

[angkor-wat]

Yes,I dropped database test2 by Studio

…

---- Replied Message ---- | From | Luca ***@***.***> | | Date | 08/15/2023 23:45 | | To | ***@***.***> | | Cc | ***@***.***>***@***.***> | | Subject | Re: [ArcadeData/arcadedb] Fail to replicate after creation of a new database in Leader (Issue #1207) | @angkor-wat do you drop the database by using Studio (therefore HTTP API)? — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.Message ID: ***@***.***>

[angkor-wat]

I do not found 23.9.1-SNAPSHOT. my servers are upgraded to 23.7.1(https://github.com/ArcadeData/arcadedb/releases/download/23.7.1/arcadedb-23.7.1.tar.gz) but 2 issues(create/drop database) still remain with the same behaviors and messages as on 23.6.1. create new database “test6”, log below: 2023-08-16 07:33:22.300 INFO [HAServer] <server_177> NEW CLUSTER CONFIGURATION +----------+--------------------+-------+------+-----------------------+-------+---------------+-------+ |SERVER |HOST/PORT |ROLE |STATUS|JOINED ON |LEFT ON|THROUGHPUT |LATENCY| +----------+--------------------+-------+------+-----------------------+-------+---------------+-------+ |server_177|test-arcadedb:2424 |Leader |ONLINE|2023-08-16 07:33:14.262| | | | |server_182|test-arcadedb-2:2424|Replica|ONLINE|2023-08-16 07:33:22.299| |83b (81.05KB/s)| | +----------+--------------------+-------+------+-----------------------+-------+---------------+-------+ 2023-08-16 07:33:22.301 INFO [HAServer] <server_177> Change election status from LEADER_WAITING_FOR_QUORUM to DONE<server_177> Error on command execution (PostServerCommandHandler) java.lang.ClassCastException: class com.arcadedb.database.EmbeddedDatabase cannot be cast to class com.arcadedb.server.ha.ReplicatedDatabase (com.arcadedb.database.EmbeddedDatabase and com.arcadedb.server.ha.ReplicatedDatabase are in unnamed module of loader 'app') at com.arcadedb.server.http.handler.PostServerCommandHandler.createDatabase(PostServerCommandHandler.java:180) at com.arcadedb.server.http.handler.PostServerCommandHandler.execute(PostServerCommandHandler.java:70) at com.arcadedb.server.http.handler.AbstractHandler.handleRequest(AbstractHandler.java:125) at io.undertow.server.Connectors.executeRootHandler(Connectors.java:393) at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:859) at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1512) at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282) at java.base/java.lang.Thread.run(Thread.java:834) drop database “test2”and shutdown servers, log below: 2023-08-16 07:33:22.299 INFO [HAServer] <server_182> Change election status from VOTING_FOR_OTHERS to DONE 2023-08-16 07:33:23.680 INFO [HAServer] Abort election process, a Leader (server_177) has been already found (turn=1)^C 2023-08-16 07:45:10.492 SEVER [ArcadeDBServer] Received shutdown signal. The server will be halted 2023-08-16 07:45:10.492 INFO [ArcadeDBServer] Shutting down ArcadeDB Server... 2023-08-16 07:45:10.497 INFO [Replica2LeaderNetworkExecutor] <server_182> Exception during execution of request -1 (shutdown=true name=ArcadeDB-ha-replica2leader/server_182/server_177 error=java.net.SocketException: Socket closed) 2023-08-16 07:45:10.497 INFO [Replica2LeaderNetworkExecutor] <server_182> Replica message thread closed (shutdown=true name=ArcadeDB-ha-replica2leader/server_182/server_177 threadId=39) @angkor-wat do you drop the database by using Studio (therefore HTTP API)? — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.Message ID: ***@***.***>