Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Active Failover Issue, Driver version 6.6 #342

Closed
hamc17 opened this issue May 7, 2020 · 2 comments · Fixed by #381
Closed

Active Failover Issue, Driver version 6.6 #342

hamc17 opened this issue May 7, 2020 · 2 comments · Fixed by #381
Labels

Comments

@hamc17
Copy link

hamc17 commented May 7, 2020

I have an Active Failover cluster which an application is trying to connect to.
The application is using an ArangoDBAsync instance with acquireHostList set to true, and is passed a connection string containing all (3) hosts in the cluster.
However, it seems that the initialisation does not work unless the cluster leader is the first of the 3 hosts in the connection string.

Taking a look at the logs, it looks to me like a connection is opened to the first host, which may be a follower and in this case was, but the log is displaying the leader in the received message.
Only one connection is open, and that's to the follower in this case.
I would expect a new connection to be created to connect with the leader which is returned in the received message but that doesn't seem to be the case.

I'm not sure what I'm missing here. Logs below, in which;
192.168.0.179 - leader.
192.168.0.169, 192.168.0.142 - followers.

14:58:15.039 [main] DEBUG com.arangodb.internal.net.HostSet - Added Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.169,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.169,port=8529], markforDeletion=false] - now 1 Hosts in List
14:58:15.040 [main] DEBUG com.arangodb.internal.net.HostSet - Added Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.179,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.179,port=8529], markforDeletion=false] - now 2 Hosts in List
14:58:15.040 [main] DEBUG com.arangodb.internal.net.HostSet - Added Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.142,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.142,port=8529], markforDeletion=false] - now 3 Hosts in List
14:58:15.041 [main] DEBUG c.a.internal.InternalArangoDBBuilder - HostHandler is FallbackHostHandler
14:58:15.093 [pool-1-thread-1] DEBUG c.a.i.v.internal.VstConnection - Connection connection_1588863495093_0.5599501596211068 created
14:58:15.094 [pool-1-thread-1] DEBUG c.a.i.v.internal.VstConnection - Open connection to host[addr=192.168.0.169,port=8529]
14:58:15.105 [pool-1-thread-1] DEBUG c.a.i.v.internal.VstConnection - Connected to Socket[addr=/192.168.0.169,port=8529,localport=44926]
14:58:15.106 [pool-1-thread-1] DEBUG c.a.i.v.internal.VstConnection - Send velocystream protocol header to Socket[addr=/192.168.0.169,port=8529,localport=44926]
14:58:15.107 [pool-2-thread-1] DEBUG c.a.i.v.internal.VstConnection - Start Callable for connection_1588863495093_0.5599501596211068
14:58:15.159 [pool-1-thread-1] DEBUG c.a.a.i.v.VstCommunicationAsync - Send Message (id=1, head=[1,1000,"plain","test","test"], body={})
14:58:15.166 [pool-1-thread-1] DEBUG c.a.i.v.internal.VstConnection - Send chunk 1:1 from message 1
14:58:15.173 [pool-2-thread-1] DEBUG c.a.i.v.internal.VstConnection - Received chunk 1:1 from message 1
14:58:15.173 [pool-2-thread-1] DEBUG c.a.i.v.internal.VstConnection - Responsetime for Message 1 is -1
14:58:15.176 [pool-2-thread-1] DEBUG c.a.i.v.internal.MessageStore - Received Message (id=1, head=[1,2,200,{"X-Arango-Potential-Dirty-Read":"true","X-Arango-Endpoint":"http:\/\/192.168.0.179:8529"}], body={"error":false,"errorNum":0,"errorMessage":"auth successful","code":200})
14:58:15.179 [pool-1-thread-1] DEBUG c.a.a.i.v.VstCommunicationAsync - Send Message (id=2, head=[1,1,"test",1,"\/_api\/database\/current",{},{}], body={})
14:58:15.180 [pool-1-thread-1] DEBUG c.a.i.v.internal.VstConnection - Send chunk 1:1 from message 2
14:58:15.180 [pool-2-thread-1] DEBUG c.a.i.v.internal.VstConnection - Received chunk 1:1 from message 2
14:58:15.180 [pool-2-thread-1] DEBUG c.a.i.v.internal.VstConnection - Responsetime for Message 2 is 0
14:58:15.181 [pool-2-thread-1] DEBUG c.a.i.v.internal.MessageStore - Received Message (id=2, head=[1,2,503,{"X-Arango-Potential-Dirty-Read":"true","X-Arango-Endpoint":"http:\/\/192.168.0.179:8529"}], body={"error":true,"errorNum":1496,"errorMessage":"not a leader","code":503})
14:58:15.184 [main] WARN  z.c.a.s.g.r.AppInitializer$$anon$1 - Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'arangoRepoConfig': Invocation of init method failed; nested exception is java.util.concurrent.ExecutionException: com.arangodb.ArangoDBException: Response: 503, Error: 1496 - not a leader
14:58:15.184 [main] DEBUG com.arangodb.internal.net.HostSet - Close all Hosts in Set
14:58:15.184 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.169,port=8529], maxConnections=1, connections=1, current=3, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.169,port=8529], markforDeletion=false]
14:58:15.193 [main] DEBUG c.a.i.v.internal.VstConnection - Close connection Socket[addr=/192.168.0.169,port=8529,localport=44926]
14:58:15.193 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.179,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.179,port=8529], markforDeletion=false]
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.142,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.142,port=8529], markforDeletion=false]
14:58:15.194 [pool-2-thread-1] DEBUG c.a.i.v.internal.VstConnection - Stop Callable for connection_1588863495093_0.5599501596211068
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Close all Hosts in Set
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.169,port=8529], maxConnections=1, connections=0, current=3, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.169,port=8529], markforDeletion=false]
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.179,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.179,port=8529], markforDeletion=false]
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.142,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.142,port=8529], markforDeletion=false]
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Close all Hosts in Set
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.169,port=8529], maxConnections=1, connections=0, current=3, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.169,port=8529], markforDeletion=false]
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.179,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.179,port=8529], markforDeletion=false]
14:58:15.194 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.142,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.142,port=8529], markforDeletion=false]
14:58:15.195 [main] DEBUG com.arangodb.internal.net.HostSet - Close all Hosts in Set
14:58:15.195 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.169,port=8529], maxConnections=1, connections=0, current=3, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.169,port=8529], markforDeletion=false]
14:58:15.195 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.179,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.179,port=8529], markforDeletion=false]
14:58:15.195 [main] DEBUG com.arangodb.internal.net.HostSet - Try to close Host HostImpl [connectionPool=ConnectionPoolImpl [host=host[addr=192.168.0.142,port=8529], maxConnections=1, connections=0, current=0, factory=VstConnectionFactoryAsync], description=host[addr=192.168.0.142,port=8529], markforDeletion=false]
14:58:15.205 [main] ERROR o.s.web.context.ContextLoader - Context initialization failed
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'arangoRepoConfig': Invocation of init method failed; nested exception is java.util.concurrent.ExecutionException: com.arangodb.ArangoDBException: Response: 503, Error: 1496 - not a leader```
@rashtao rashtao added the bug label May 15, 2020
@rashtao
Copy link
Collaborator

rashtao commented May 15, 2020

This bug is caused by some design limitations in the Java asynchronous driver.
Such scenario will be supported in the next reactive driver rewrite and it has been already implemented. Eg. here you can check the related test:

@ParameterizedTest
@EnumSource(ArangoProtocol.class)
void acquireHostList(ArangoProtocol protocol) {
ArangoCommunication communication = ArangoCommunication.create(config
.protocol(protocol)
.hosts(hosts.subList(0, 1))
.build()).block();
assertThat(communication).isNotNull();
ArangoCommunicationImpl communicationImpl = ((ArangoCommunicationImpl) communication);
ActiveFailoverConnectionPool connectionPool = (ActiveFailoverConnectionPool) communicationImpl.getConnectionPool();
Map<HostDescription, List<ArangoConnection>> currentHosts = connectionPool.getConnectionsByHost();
assertThat(currentHosts).hasSize(hosts.size());
assertThat(currentHosts.keySet()).containsExactlyInAnyOrderElementsOf(hosts);
HostDescription leader = connectionPool.getLeader();
assertThat(hosts).contains(leader);
// check if every connection is connected
currentHosts.forEach((key, value) -> value.forEach(connection -> {
assertThat(connection.isConnected().block()).isTrue();
}));
CommunicationTestUtils.executeRequest(communication);
communication.close().block();
}

@rashtao
Copy link
Collaborator

rashtao commented Apr 6, 2021

It should be fixed by #381

@rashtao rashtao linked a pull request Apr 7, 2021 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants