Case where a machine is up but unreachable about cdrs-tokio HOT 44 CLOSED

Can you see if the latest master partially solves your case? It should not be stuck on reconnecting to downed node and jump to the next one in query plan, but it still is missing marking as temporarily down.

from cdrs-tokio.

After some analysis, looks like the internal reconnection mechanism needs to change a bit. I will close your PR for now, since those changes will make it obsolete.

from cdrs-tokio.

Are you sure the reconnection policy was not triggered? https://github.com/krojew/cdrs-tokio/blob/master/cdrs-tokio/src/cluster/tcp_connection_manager.rs#L58 should ask to jump to the next node if connection was not successful. What reconnection policy was used?

from cdrs-tokio.

It doesn't seem like it get to this error even though we still get the error for timeout. It gets in to the loop.
We tried all reconnection policies available. All haven't handle this issue.

from cdrs-tokio.

O, I'll try to replicate the issue. Can you share the exact error you're getting?

from cdrs-tokio.

The error we got is IO error: Connection timed out (os error 110)
When we limit the connection pool config to 100ms (in order to be able to test it and not wait a whole minute for getting back from this error) we receive the error: Timeout: Timeout waiting for connection to: XX.XX.XXX.XXX:XXXX

It is important to say that we know that this machine can not accept any connection (internal problem) but the problem with the driver (we think) that the status of this machine is still mark as UP and not Down.

from cdrs-tokio.

When I leave the service up for a while, it does get into this lines of error:
https://github.com/krojew/cdrs-tokio/blob/master/cdrs-tokio/src/cluster/tcp_connection_manager.rs#L58
and I print the problematic connection. However, the status of this None is still up instead of mark to be down or unknown.

Also, is there a check for a node which marked as down to be up again once it is fixed?

from cdrs-tokio.

After some testing, I don't think there's any error with handling the timeout itself (OS error 110). It can happen, for whatever reason, but then is caught by the ConnectionManager, which in turn asks the reconnection policy what to do. The only way for the error to be propagated up is for the policy to stop reconnecting.
The other type of timeout is related to connection timeout handled by the ConnectionPool - this one is user-defined and acts as a safety switch irrespective of reconnection policy.
Can you share your code or a minimal example which shows the error?

from cdrs-tokio.

Apparently, the ConnetionManager doesn't catch that one connection is dead and still try to reach it. We found it with regular setting for the TcpSessionBuilder:

let cluster_config = NodeTcpConfigBuilder::new()
        .with_contact_points(seeds)
        .with_authenticator_provider(Arc::new(authenticator))
        .build()
        .await
        .unwrap();

TcpSessionBuilder::new(RoundRobinLoadBalancingStrategy::new(), cluster_config)
        .with_reconnection_policy(Arc::new(ConstantReconnectionPolicy::default()))
        .build()
        .unwrap()

When the connection manager hit the dead connection, we received OS error 110 after 60 second. In order to debug it and remove the waiting time (to 300ms), we set the session as:

let connection_config = ConnectionPoolConfig::new(1, 1, Some(Duration::from_millis(300)));

TcpSessionBuilder::new(
        TopologyAwareLoadBalancingStrategy::new(None, false),
        cluster_config,
    )
    .with_reconnection_policy(Arc::new(ExponentialReconnectionPolicy::default()))
    .with_connection_pool_config(connection_config)
    .build()
    .unwrap()

The PR I sent is ignoring other scenarios, but it handle our case where the connection manager doesn't recognize a dead connection and always try to reach it.

from cdrs-tokio.

Ok, I'll dig some more into this issue. Thanks for the samples!

from cdrs-tokio.

Thank you for the help!

When I print the addr in: https://github.com/krojew/cdrs-tokio/blob/master/cdrs-tokio/src/cluster/tcp_connection_manager.rs#L56-L60
It print the dead address but it still try to reach it when I send requests.

from cdrs-tokio.

It is similar solution to the one I suggested in term of not really solving the problem but having a temporary solution.
I get a response but since I have 6 nodes, on average every 6th request take much longer (depend on the time I set for timeout). We want to mark this node as down and not just skip it every time it reaches it.

from cdrs-tokio.

That is the expected behavior after the latest changes. The next part is to implement the new node state, which should solve everything.

from cdrs-tokio.

I found this in the cpp driver https://github.com/datastax/cpp-driver/blob/07f8adee80845d403ff6fc4fc8dcc6654a97cddd/src/control_connection.cpp

Didn't really get into it, but there is a refresh mechanism which I think should be useful .

from cdrs-tokio.

That is the expected behavior after the latest changes. The next part is to implement the new node state, which should solve everything.

Would love to help if needed

from cdrs-tokio.

Didn't really get into it, but there is a refresh mechanism which I think should be useful .

This seems to be related only to topology changes in the control connection, which is not the case in our situation.

from cdrs-tokio.

I got 'attempt to calculate the remainder with a divisor of zero'

for:
https://github.com/krojew/cdrs-tokio/blob/new-reconnection/cdrs-tokio/src/cluster/connection_pool.rs#L365

from cdrs-tokio.

Right, I was testing with dropping existing connections, rather than having none initially. Should be fixed now.

from cdrs-tokio.

I made some tests.
We have 6 machines (nodes) for our database.
When just one node is down it work perfect. However, when I take another node down, it start marking all of the node as down and out of 1000 request I get response for less than 50. I tried with both ways I mentioned earlier here #158 (comment)

from cdrs-tokio.

That's extremely hard for me to test. Is there a possibility you can add some logging and gather what's going on or debug the internals?

from cdrs-tokio.

I print the node in this function:
https://github.com/krojew/cdrs-tokio/blob/new-reconnection/cdrs-tokio/src/cluster/topology/node.rs#L259

When starting the service, all the nodes are up (even though two of them aren't). after very few request it mark the two dead nodes as down. However, when passing ~20 requests, it looks like it start marking other machines as down, I am not sure why. Eventually, all the machine are down. sometime one or two come back alive for a little then down again.

When I used the cpp driver https://github.com/datastax/cpp-driver/ it could handle it very well.

from cdrs-tokio.

The two dead nodes should be marked as down, but the rest should not. Can you add a breakpoint to Node::mark_down() and see what causes the remaining nodes to go down?

from cdrs-tokio.

Ok, I found the issue - the heartbeat code is missing from this experimental branch...

from cdrs-tokio.

Thank you! please let me know when you commit it.

from cdrs-tokio.

Just merged the hearbeat code. Active connections should not go down anymore. You might need to adjust heartbeat interval in pool config if they still do.

from cdrs-tokio.

@Matansegal have you had a chance to test the changes?

from cdrs-tokio.

I just tried it and it doesn't seem to change the last outcomes. It still mark the live nodes as dead after several requests. I have mechanism to reduce level of consistency but it still does it until eventually I have no live nodes. You can see the log I got below, with two nodes down:

[2023-04-20T00:43:07.805 ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Up), }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Up), }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Up),  }
[2023-04-20T00:43:07.934 ] OUT
[2023-04-20T00:43:07.937 ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Up),  }
[2023-04-20T00:43:08.133 WARN ] Reducing level of consistency due cdrs_tokio::error::Error::Server=UnavailableError { cl: EachQuorum, required: 2, alive: 1 }
[2023-04-20T00:43:08.133 INFO ] Consistency level=Quorum
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Up),  }
[2023-04-20T00:43:08.233 WARN ] Reducing level of consistency due cdrs_tokio::error::Error::Server=UnavailableError { cl: Quorum, required: 2, alive: 1 }
[2023-04-20T00:43:08.233 INFO ] Consistency level=LocalQuorum
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T00:43:08.233 ERROR ] Error accured while impl query; General error: No nodes available in query plan!

from cdrs-tokio.

Did you use the latest version with the heartbeats? If so, maybe try lowering the hearbeat interval. The nodes are going down because you most likely have some kind of proxy dropping idle connections and the reconnection policy takes too long to get them back up. Using lower hearbeat and reconnection intervals should help.

If it happens nevertheless, can you paste the logs with the DEBUG level enabled?

from cdrs-tokio.

I also pushed a change which is less strict in determining if a node is up or down, which might help in such scenarios.

from cdrs-tokio.

I tried it with heartbeat of 1 sec then 300 ms, still got the errors.
The log below is with the DEBUG mode. it print debug line that I cannot put here.
IN is incomming request to the service. OUT is expected output.

[2023-04-20T14:13:51.895 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Up),  }
[2023-04-20T14:13:52.002 ERROR ] the Pool Level database does not contain a row with the deal=FR_RE6115 and period=202010
[2023-04-20T14:13:52.006 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Up),  }
[2023-04-20T14:13:52.108 WARN ] Reducing level of consistency due cdrs_tokio::error::Error::Server=UnavailableError { cl: EachQuorum, required: 2, alive: 1 }
[2023-04-20T14:13:52.109 INFO ] Consistency level=Quorum
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Up),  }
[2023-04-20T14:13:52.214 WARN ] Reducing level of consistency due cdrs_tokio::error::Error::Server=UnavailableError { cl: Quorum, required: 2, alive: 1 }
[2023-04-20T14:13:52.214 INFO ] Consistency level=LocalQuorum
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Up),  }
[2023-04-20T14:13:52.217 WARN ] Reducing level of consistency due cdrs_tokio::error::Error::Server=UnavailableError { cl: LocalQuorum, required: 2, alive: 1 }
[2023-04-20T14:13:52.217 ERROR ] Got to the lowest level of consistency (LocalQuorum) and still failing
[2023-04-20T14:13:52.220 ERROR ] Error accured while impl query; error: ErrorBody { message: "Cannot achieve consistency level LOCAL_QUORUM", ty: Unavailable(UnavailableError { cl: LocalQuorum, required: 2, alive: 1 }) }
[2023-04-20T14:13:52.329 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.339 INFO ] OUT
[2023-04-20T14:13:52.342 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.353 INFO ] OUT
[2023-04-20T14:13:52.380 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.393 INFO ] OUT
[2023-04-20T14:13:52.396 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.406 INFO ] OUT
[2023-04-20T14:13:52.409 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.418 INFO ] OUT
[2023-04-20T14:13:52.421 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Up),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.424 WARN ] Reducing level of consistency due cdrs_tokio::error::Error::Server=UnavailableError { cl: EachQuorum, required: 2, alive: 1 }
[2023-04-20T14:13:52.424 INFO ] Consistency level=Quorum
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.427 ERROR ] Error accured while impl query; General error: No nodes available in query plan!
[2023-04-20T14:13:52.432 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.434 ERROR ] Error accured while impl query; General error: No nodes available in query plan!
[2023-04-20T14:13:52.438 INFO ] IN
Node { broadcast_rpc_address: 11.11.111.111, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.112, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.113, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.114, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.115, state: Atomic(Down),  }
Node { broadcast_rpc_address: 11.11.111.116, state: Atomic(Down),  }
[2023-04-20T14:13:52.439 ERROR ] Error accured while impl query; General error: No nodes available in query plan!

from cdrs-tokio.

There was one more option where the node could have been incorrectly marked as down and I just pushed a fix - can you test it? Also, please make sure you are using the new branch with a reconnection policy (the default one is ok) and there are debug logs - there should be a lot of them when the reconnection policy kicks in: https://github.com/krojew/cdrs-tokio/blob/new-reconnection/cdrs-tokio/src/cluster/connection_pool.rs

from cdrs-tokio.

Still get the same. For some reason I cant see your loggings.

from cdrs-tokio.

Are you absolutely sure you are using this branch and the debug logs are enabled? You should at least see hearbeat errors if a connection is down, which are absent from what you've pasted.

from cdrs-tokio.

I'm talking about the new_reconnection branch. The heartbeat logs should be present for every node down.

from cdrs-tokio.

I am using this branch, we have the logging of the service. I am still trying to get the loggings form the driver.

from cdrs-tokio.

Your logs got me thinking - the only way for a node to be marked as down, ignoring the reconnection policy, is via a server event. If you take a look at cdrs_tokio::error::Error::Server=UnavailableError { cl: EachQuorum, required: 2, alive: 1 } log, it means the cluster cannot find neighboring nodes. This suggest there might be something wrong with the cluster and it does indeed send a node down server event. Could that be the case?

from cdrs-tokio.

I dont think so. Those servers are used by services written in python and cpp and do not have those errors.

from cdrs-tokio.

I see. Well, those debug logs should show what's going on.

from cdrs-tokio.

I'm testing this branch with my small test cluster and everything seems to work:

• no connections are dropped by themselves in time
• killing and restarting nodes bring the connections up per reconnection policy (which is ignored by design if a server event is used to mark a node down)
• inserting a proxy in between and using it to block connections while keeping the node alive (which seems to be your case) also triggers reconnection policy and everything gets back up

I could really use those debug logs, since it seems you stumbled upon some weird edge case, which I cannot reproduce.

from cdrs-tokio.

I found a possible edge case - the cluster might send node down event, while the node is in fact still up and there are active connections (which explains why the reconnection policy is not triggered). I pushed a change which will not mark such node as down, but it suggests something is happening with the cluster itself. Can you check?

from cdrs-tokio.

All my tests show this branch is working. I hope your case if fixed too @Matansegal, but without your confirmation, I can only assume that. I will yank the current version and replace it with this one.

from cdrs-tokio.

Sorry, I missed that.
I will be able to test it later today or tmrw.

from cdrs-tokio.

@Matansegal I've yanked the 8.0.0 due to this case and released 8.1.0. if the nodes are still being marked down, I really need those debug logs to see what the cause. At the moment I'm suspecting the node, to which the control connection is established, looses connection with other nodes and starts sending down events. In the meantime, something (a proxy?) is closing established connections from the driver if the heartbeat takes too long.

from cdrs-tokio.

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

from cdrs-tokio.