Open kbr-scylla opened 6 months ago
kbr-scylla
commented
6 months ago Note: in the above run, the query failed with
E cassandra.cluster.NoHostAvailable: ('Unable to complete the operation against any hosts', {<Host: 127.167.175.35:9042 datacenter1>: ConnectionException('Host has been marked down or removed')})Perhaps a workaround in the tests would be to first wait for all nodes to see the restarted node as UP, and only then do the wait_for_cql. This way, by the time select * from system.local succeeds, there should be no notifications from Scylla any more, thus no driver reconnects...
Except I'm not sure. It may be true that the notifications are sent as nodes observe the restarted node as UP -- but they may be received by the driver much later, I don't think there's an ordering guarantee. I'm 99.999% sure there's not --- if we wanted such guarantee, the /gossiper/endpoint/live Scylla API would have to keep returning DOWN until all notifications to all driver sessions are delivered. I doubt gossiper is blocking on drivers, it would be too much of external dependency of internal Scylla behavior.
Still, the workaround could potentially minimize the probability of the issue.
Another workaround is to recreate the driver session every time we restart a node, and this was applied to some tests already (big story here: https://github.com/scylladb/scylladb/issues/14746)
Unfortunately IIRC it's not a 100% workaround, and the driver may still decide to reconnect again (perhaps the newly created driver session is again receiving notifications from Scylla), although the probability is much smaller.
Also, dtests likely don't have this problem because instead of using a single cluster-wide session, they are using "exclusive" sessions i.e. every node has its own session connected to it, and using a policy, the driver is not connecting to other nodes (?). If that's the case, there should be no notifications from other nodes. But I'm not sure if using an execution profile or policy actually prevents a session from connecting to other nodes? Or it only prevents from querying the nodes, but the pool is still established? (cc @fruch -- maybe you could confirm or deny my reasoning about how dtests use the driver)
kbr-scylla
commented
6 months ago cc @kostja @nyh
fruch
commented
6 months ago Perhaps a workaround in the tests would be to first wait for all nodes to see the restarted node as UP, and only then do the
wait_for_cql. This way, by the timeselect * from system.localsucceeds, there should be no notifications from Scylla any more, thus no driver reconnects...Except I'm not sure. It may be true that the notifications are sent as nodes observe the restarted node as UP -- but they may be received by the driver much later, I don't think there's an ordering guarantee. I'm 99.999% sure there's not --- if we wanted such guarantee, the
/gossiper/endpoint/liveScylla API would have to keep returning DOWN until all notifications to all driver sessions are delivered. I doubt gossiper is blocking on drivers, it would be too much of external dependency of internal Scylla behavior.Still, the workaround could potentially minimize the probability of the issue.
Another workaround is to recreate the driver session every time we restart a node, and this was applied to some tests already (big story here: scylladb/scylladb#14746)
Unfortunately IIRC it's not a 100% workaround, and the driver may still decide to reconnect again (perhaps the newly created driver session is again receiving notifications from Scylla), although the probability is much smaller.
Also, dtests likely don't have this problem because instead of using a single cluster-wide session, they are using "exclusive" sessions i.e. every node has its own session connected to it, and using a policy, the driver is not connecting to other nodes (?). If that's the case, there should be no notifications from other nodes. But I'm not sure if using an execution profile or policy actually prevents a session from connecting to other nodes? Or it only prevents from querying the nodes, but the pool is still established? (cc @fruch -- maybe you could confirm or deny my reasoning about how dtests use the driver)
this last paragraph about dtest isn't completely accurate, we have "exclusive" connections, but test are using both "exclusive" and connection which are not.
up until not that long ago, restart of a node was taking quite a long time cause of wait_for_gossip and it's friends, some test are till today suffering for similar issues to what you are describing, @temichus was trying to address it, with a similar direction to you suggested workaround. we seen it in cases where all of the nodes were taken down. this is something very rare in dtest tests, if only one node is down, we don't notices such issues.
Also to note, dtest doesn't use the same session across tests, and in lot of places uses session context manager, i.e. it's being closed right after the usage is done.
as for the pool in exclusive move, it's hold just that nodes which are whitelisted, it happened during listing the nodes from system tables, so when it work in that mode, it's blind to all other nodes complectly, it doesn't open connection to them, and not getting notification from them. (might be getting notification about them, UP/DOWN and such, but shouldn't be opening connections based on those)
as for the actual issue, the test you are referring to are running with smp=2 or more ? cause it might be that the we have one connection to a node up and ready, which the 2nd cpu connection isn't ready yet, and if a query is executed at that time, it might reach into a connection that going to be replaced cause of the shard aware logic, i.e. driver doesn't know which cpu isn't connecting, and hence closes and reopen connections till it hits the right cpu, all that is happening in the background, and this might be the cause of it.
are you disabling shared-aware ports in those tests ? (using shard aware port might minimize that dance of opening/closing connections)
fruch
commented
6 months ago @kbr-scylla
see https://github.com/search?q=repo%3Ascylladb%2Fscylla-dtest%20wait_reconnection&type=code which kind of equivalent to wait_for_cql, and it's used only in 4 specific tests in dtest
kbr-scylla
commented
6 months ago as for the actual issue, the test you are referring to are running with smp=2 or more ?
Yes, smp=2
cause it might be that the we have one connection to a node up and ready, which the 2nd cpu connection isn't ready yet, and if a query is executed at that time, it might reach into a connection that going to be replaced cause of the shard aware logic, i.e. driver doesn't know which cpu isn't connecting, and hence closes and reopen connections till it hits the right cpu, all that is happening in the background, and this might be the cause of it.
are you disabling shared-aware ports in those tests ? (using shard aware port might minimize that dance of opening/closing connections)
The shard aware port is enabled.
But you did point out an important fact, that doing select * from system.local is not enough, as this will only test connection to one shard, while connection to the other shard might not even be established yet... And the following query may go to the other shard. So we also have a problem in test.py, we need some better way to test that connections are established which would check all shards. Not sure if it's possible, we may need better guarantees / API from the driver after all. Also, this doesn't change the fact that the driver seems to be reconnecting like crazy, if it was only one reconnect per shard I would understand, but the logs show more.
sylwiaszunejko
commented
6 months ago @kbr-scylla I wrote the test to reproduce the issue https://github.com/sylwiaszunejko/scylladb/tree/multiple_driver_reconnections, but it did not occur for me. I run it many times. Maybe there is something wrong with the test, could you look at it at give some advice?
avelanarius
commented
6 months ago The cause of this issue could be the same as https://github.com/scylladb/scylladb/issues/16709. However, reproducing the issue is very tough (@sylwiaszunejko managed to reproduce it once every 1h or less often). @kbr-scylla ping, do you happen to know a good reproducer?
kbr-scylla
commented
6 months ago The cause of this issue could be the same as https://github.com/scylladb/scylladb/issues/16709.
Seems unlikely, because the symptoms are completely opposite --- here we have too many reconnects and in that other issue we have 0 reconnects (i.e. https://github.com/scylladb/python-driver/issues/230).
But who knows, maybe it's related.
However, reproducing the issue is very tough (@sylwiaszunejko managed to reproduce it once every 1h or less often). @kbr-scylla ping, do you happen to know a good reproducer?
No.
kbr-scylla
commented
5 months ago @avelanarius @sylwiaszunejko one test that is failing often in CI is here https://github.com/scylladb/scylladb/issues/17353 but it's a bit different situation, it's a single-node test and we don't restart the node, but disable and re-enable the CQL server, which causes driver reconnection. The test then waits until driver reconnects and executes a query. Unfortunately driver may reconnect again (?) causing query to fail... Or perhaps the query is attempted on a different shard that hasn't connected yet?
kbr-scylla
commented
5 months ago We have a good reproducer https://github.com/scylladb/scylladb/issues/17353#issuecomment-1970969872
kbr-scylla
commented
5 months ago Branch: https://github.com/kbr-scylla/scylladb/tree/connection-reconnect-repro compile in debug mode and run
./test.py --mode debug --cpus=0,1 --jobs=32 test_native_transport --repeat 100note: this is a single-node test
kbr-scylla
commented
5 months ago Updated the branch, reducing shard number on Scylla to 1 run with
./test.py --mode debug --cpus=0 --jobs=32 test_native_transport --repeat 100it reproduces even more often!
So apparently, it's not (only) the problem of having connections to multiple shards. Even with single shard the driver is still dropping connection
kbr-scylla
commented
5 months ago Note: The reproducer mentioned above is for a single-node case, where the node disables the CQL server and re-enables it. We bisected the regression for that single-node case to d735957e3a7b7178f4fff26f6dbae588e58cf314.
However, originally, this issue was reported due to https://github.com/scylladb/scylladb/issues/14746#issuecomment-1713739316
There it was a rolling restart of the entire cluster. But that was reported on Jul 18 --- so before d735957e3a7b7178f4fff26f6dbae588e58cf314.
So d735957e3a7b7178f4fff26f6dbae588e58cf314 cannot be the root cause of https://github.com/scylladb/scylladb/issues/14746#issuecomment-1713739316 which triggered this issue originally.
avelanarius
commented
5 months ago Reopening the issue since there still might a problem for multi-node clusters
kbr-scylla
commented
2 months ago This is reproducing as can be seen in https://github.com/scylladb/scylladb/issues/19154#issuecomment-2163506387
In fact, it happens even if, after restarting nodes, we start a completely new driver session and verify that it can perform queries with wait_for_cql_and_get_hosts -- the new session decides to recreate connection pools immediately after, causing subsequent queries to fail.
This is probably caused by notifications arising from Scylla.
The driver should be sufficiently smart to recognize obsolete notifications -- i.e. if it gets a notification about node restart, but it has already reconnected after that restart, then it should not reconnect again.
If this requires the notification messages originating at Scylla to be augmented with some additional info, we can discuss this and perhaps open new feature request in Scylla. But perhaps it's not necessary. Maybe there is a way on the driver side to compare order of events based on already available information.
In test.py tests, after restarting a node, we're often using the utility function
wait_for_cql(orwait_for_cql_and_get_hosts) on a pre-existing driver session (which is created at the beginning of the test and connected to the cluster), to wait for that session to be able to query the restarted node.This is the logic:
In short, we're waiting until
select * from system.localsucceeds on thatHost.wait_for_cql_and_get_hostsadditionally translates an IP address in the form of a string into an object of theHosttype (defined by the driver).Then a test may attempt to perform a query -- immediately after calling
wait_for_cql/wait_for_cql_and_get_hosts.Unfortunately, that query may fail.
The reason is (judging from driver logs), that even after the driver reconnected and
select * from system.localsucceeded, the driver may for some reason decide to reconnect again, which involves dropping the existing connections and creating new ones. This might happen in the middle of the next query, causing the query to fail. In fact the driver may reconnect multiple times in this way.Here's a fragment of relevant logs from one of test.py test runs:
We can clearly see that the driver managed to reconnect
but then, for some reason, drops connections...
One curious thing I noticed is this:
this suggest that there is some kind of reconnection logic -- perhaps reacting to events? -- and that logic is supposed to be cancelled. However, reconnection still happens.
I have a suspicion that the driver is perhaps reacting to notifications from Scylla. Different nodes may be noticing that our node is UP at different times, and sending notifications to the driver (additionally, these notifications can also be delayed for whatever reason). Whenever the driver receives such a notification, this triggers reconnection.
But -- perhaps that reconnection logic should be cancelled when the driver first manages to reconnect? The message above suggests such mechanism being already in place, but apparently it's not, or it doesn't work. Or, perhaps upon receiving such notification, the driver should first check that the existing connections (if present) are alive (exchange a packet back and forth?), and only if they're not, attempt reconnection?