Possible deadlock and memory leak during connection timeouts

[ankurmittal]

Hi,
Today we faced a issue where of of our couchbase client host started failing with connection timeout (2.5s, our wrapper logic where we drop the future) for 4 hours. The memory grew overtime to 1.4GB and when we investigated we found that 1.25 gb of memory was taken by mpsc::channel

batch_upsert → buffer_unordered → upsert → Collection::upsert_raw
→ tokio::time::timeout → couchbase SDK upsert_raw
→ CrudComponent::upsert → orchestrate_retries → orchestrate_simple_crud
→ OpsCrud::set → StdKvClient::set
→ Client::dispatch
→ tokio::sync::mpsc::bounded::channel ← 1.25GB HERE
→ mpsc::block::Block::new
→ alloc

Upon further investigation we believe that there was a deadlock due to block-on in drop which can basically block the sender code from completing because receiver is on the same thread

I see you already mitigated it here 5bebfe0. Do you think we can mitigate the issue by updating to this PR? Also client never refreshed the bad connection. Do you have any insight on why that will happen? Is it because of the same issue? We are currently on commit be74b7a

[chvck]

Hi @ankurmittal thanks for reporting this. Yes I think that SHA should fix this issue.

Also client never refreshed the bad connection. Do you have any insight on why that will happen? Is it because of the same issue?

I'm unsure when this bug was introduced but I believe that I have a fix that I have just merged. Our extended test framework identified this issue recently too and this fix caused those tests to start passing.

[chvck]

Actually I'm uncertain that the deadlock/memory leak will be fixed by that SHA. I'll run some tests first thing next and come back to you.

[ankurmittal]

thanks. Also it happens on only one node out of many, so should be a rare race condition when the future is dropped by client due to custom timeout

[gu0keno0]

@chvck :

After reading the code a bit more, I suspect this is a race between the connection management and config pooling: basically, config polling might block forever when the client is trying to use a client that's closed around the same time.

I'll post more details and a UT that can potentially demonstrate it soon.

[ankurmittal]

over the weekend we had this issue multiple times (still on old code) and according to logs if connection to one node (out of 5) becomes dead then couchbase SDK does not have a mechanism to time that connection out and start a new one. Was that fixed in the commit you mentioned in comment 2?

[ankurmittal]

Looked at your commit from comment 2. Will that work if remote explicitly does not close the connection, still the connection is half dead? I guess we don't have any health checks in couchbase SDK for a connection? Also no kv operations timeout so couchbase SDK does not really know if a connection is misbehaving?

[ankurmittal]

should we also do a selective timeout (only if we have pending ops) here https://github.com/couchbaselabs/couchbase-rs/blob/2b423863b14183004504adf7900b7a2d0b58e9db/sdk/couchbase-core/src/memdx/client.rs#L178 so that we know when to refresh the connection

[chvck]

Was that fixed in the commit you mentioned in comment 2?

I think so, in our extended SDK testing framework we have a test which tests that on a connection being broken by the remote then the SDK recreates that connection. The scenario is slightly different but the net effect the same I think.

Looked at your commit from comment 2. Will that work if remote explicitly does not close the connection, still the connection is half dead?

How are you defining half dead here? Recreating a connection against a poorly behaving node is unlikely to actually help much as the new connection will encounter the same issue, I imagine the same is true of a poorly behaving network. As far as I'm aware other Couchbase SDKs will not close a connection based on operation level timeouts either, certainly Go does not. The SDKs will recreate connections as soon as the connection is broken for any reason.

I guess we don't have any health checks in couchbase SDK for a connection?

Not that are executed internally. There is some functionality such as ping for an application to use. We do also set a keepalive time on the connections which should detect a broken connection if there are no operations being executed.

Also no kv operations timeout so couchbase SDK does not really know if a connection is misbehaving?

It sounds a little bit like you might be looking for circuit breaker functionality? Although I don't think that would exactly solve your issue as that wouldn't close the connection but it would instead fast fail any operations going to that node. This is functionality we are looking at adding after 1.0.0 as there are challenges fitting that in around how the rust language is commonly used.

[ankurmittal]

How are you defining half dead here? Recreating a connection against a poorly behaving node is unlikely to actually help much as the new connection will encounter the same issue, I imagine the same is true of a poorly behaving network. As far as I'm aware other Couchbase SDKs will not close a connection based on operation level timeouts either, certainly Go does not. The SDKs will recreate connections as soon as the connection is broken for any reason.

We tried your change, even though it decreases the occurrence of this greatly and eliminates memory leak, it does not completely fix it. We believe sometimes OS does not close the channel and leaves connection as dead, and on reconnection attempt by couchbase, it will starts working again. We are trying a local fork with timeout I proposed and will let you know if it eliminates the issue for us.

[chvck]

I would expect the connect to be closed by the OS when we attempt to write to the socket anyway? Are those requests just getting written to the socket but then not going anywhere?

[ankurmittal]

I would expect the connect to be closed by the OS when we attempt to write to the socket anyway? Are those requests just getting written to the socket but then not going anywhere?

Seems like it, i turned on trace logs and write does not return any error, but we never get response and also server never gets those writes, killing and restarting the process works. Currently deploying read timeout change

[chvck]

Are you certain that the operations are actually getting written to the network? I'm wondering if we have a bug somewhere in the client logic which is actually preventing the operations getting written in the first place. Although if you see dispatch logs then there isn't a lot of space in which it could go wrong but we do have a lock after that and the channel itself could be doing some odd (although that seems unlikely).

[ankurmittal]

I did not see any dispatch errors in logs, so not sure why this is happening.

On a aide note i was writing some tests which use ss to kill connection. in those tests we do get dispatch error and according to claude

when `close()` is called due to a dispatch error, it CAS-sets closed = true but never notifies the babysitter. The babysitter only reconnects when it receives on_close_tx. Without
  notification, the babysitter is stuck — fast_client still points to the dead connection, and no reconnect happens.

It is asking me to add this to close(), and my tests fail without it.

if let Some(on_close_tx) = &self.on_close_tx {
      if let Err(e) = on_close_tx.send(()).await { ... }
 }

Without this change the tests fail (sometimes) as it does not reconnect

[chvck]

Ahh does that also explain the behaviour you see where operations don't complete? I'm rather reluctant to add a mechanism to reconnect connections based on how long operations are taking - other Couchbase SDKs do not do this and it would create a discrepancy that could lead to issues in the future. Given that other Couchbase SDKs also don't have this but don't see this issue it makes me think it's probably a SDK bug and we're at risk of masking the bug with this mechanism.

[ankurmittal]

This is definitely a different race condition because when this happens in test we start seeing dispatch errors on write.

As for the other race condition, yeah it can be a bug in the sdk, but I am not sure what is the code path and it happens very rarely. Before your fix client timeout was happening every couple of hours on different nodes, but after your fix it only happened once in a week across 100s of nodes