ObjectDisposeException of DataFlowConnectionPool

thinh-ng · June 29, 2021, 7:18pm

Hi everyone,

Recently I’ve encounter a problem during load testing our apps, which uses Couchbase .NET SDK 3.1.0 and net core 3.1
The stack trace looks like this

System.ObjectDisposedException:
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.EnsureNotDisposed (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.SendAsync (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.Core.ClusterNode+<>c.<ExecuteOp>b__119_0 (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.Core.ClusterNode+<ExecuteOp>d__117.MoveNext (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.Core.ClusterNode+<SendAsync>d__116.MoveNext (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.CouchbaseBucket+<SendAsync>d__14.MoveNext (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.CouchbaseBucket+<SendAsync>d__14.MoveNext (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.Core.Retry.RetryOrchestrator+<RetryAsync>d__4.MoveNext (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.Core.BucketBase+<RetryAsync>d__68.MoveNext (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.KeyValue.CouchbaseCollection+<RetryUntilTimeoutOrSuccessAsync>d__30.MoveNext (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Couchbase.KeyValue.CouchbaseCollection+<UpsertAsync>d__29`1.MoveNext (Couchbase.NetClient, Version=3.1.0.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2)
   at Marvin.SortingHat.Subscriber.Infrastructure.PlayerTagsDataHandler+<UpsertAsync>d__5.MoveNext (Marvin.SortingHat.Subscriber, Version=1.0.0.0, Culture=neutral, PublicKeyToken=nullMarvin.SortingHat.Subscriber, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: /src/src/Marvin.SortingHat.Subscriber/Infrastructure/PlayerTagsDataHandler.csMarvin.SortingHat.Subscriber, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: 42)
   at Polly.AsyncPolicy+<>c__DisplayClass40_0+<<ImplementationAsync>b__0>d.MoveNext (Polly, Version=7.0.0.0, Culture=neutral, PublicKeyToken=c8a3ffc3f8f825cc)
   at Polly.Retry.AsyncRetryEngine+<ImplementationAsync>d__0`1.MoveNext (Polly, Version=7.0.0.0, Culture=neutral, PublicKeyToken=c8a3ffc3f8f825cc)
   at Polly.AsyncPolicy+<ExecuteAsync>d__12.MoveNext (Polly, Version=7.0.0.0, Culture=neutral, PublicKeyToken=c8a3ffc3f8f825cc)
   at Marvin.SortingHat.Subscriber.MessageHandlers.PlayerTagsMessageHandler+<HandleAsync>d__5.MoveNext (Marvin.SortingHat.Subscriber, Version=1.0.0.0, Culture=neutral, PublicKeyToken=nullMarvin.SortingHat.Subscriber, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: /src/src/Marvin.SortingHat.Subscriber/MessageHandlers/PlayerTagsMessageHandler.csMarvin.SortingHat.Subscriber, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: 54)

I registered couchbase cluster and bucket according to the docs, the code was following example in
this section to register cluster and this section for usage.
The code was calling UpsertAsync in the collection.

Is this a known issue? Would adding retry helps in this case?

jmorris · June 30, 2021, 6:45pm

@thinh-ng -

An ObjectDisposeException being logged by the connection pool can be an expected behavior given the circumstance. For example in a swap/rebalance on the cluster side or if another app thread disposes of the cluster or bucket object while another thread is making a request.

Internally the SDK already retries depending upon the condition.

Jeff

thinh-ng · July 2, 2021, 6:00am

@jmorris That doesn’t sound like the case because the exception is throwing non-stop, like thousands of them, and it won’t stop until I restarted my VM, then it completely gone. Data is (nearly) the same since it coming from load testing

thinh-ng · July 2, 2021, 6:39am

@jmorris How many times does the it retry on this type of exception? Is it retry forever?
For more information, the debug log show NotMyVBucketException is thrown, which is an exception that subject to retry forever, so it may leads to ObjectDisposedException eventually

jmorris · July 2, 2021, 5:16pm

This makes me think that your app is disposing the bucket or cluster object somehow. Can you provide SDK logs of this behavior?

Also, which server version are you using and have you tried upgrading to the latest SDK?

-Jeff

thinh-ng · July 5, 2021, 4:18am

@jmorris

I can see the debug log keep retrying on NotMyVBucketException

Debug 2021-07-05 04:03:54.571 +00:00 - Receiving new map revision 25315
Debug 2021-07-05 04:03:54.572 +00:00 - Op failed: Couchbase.Core.IO.Operations.Set`1[System.String]: Couchbase.KeyValue.NotMyVBucketException: Exception of type 'Couchbase.KeyValue.NotMyVBucketException' was thrown.
   at Couchbase.Core.ClusterNode.ExecuteOp(Func`4 sender, IOperation op, Object state, CancellationToken token)
-----------------------Context Info---------------------------
{"DispatchedFrom":null,"DispatchedTo":null,"DocumentKey":"sh:1178129","ClientContextId":"730","Cas":0,"Status":7,"BucketName":"mvmx_hk_trunk","CollectionName":"_default","ScopeName":"_default","Message":"KV Error: {Name=\"NOT_MY_VBUCKET\", Description=\"Server does not know about this vBucket\", Attributes=\"fetch-config,invalid-input\"}"}

Debug 2021-07-05 04:03:54.573 +00:00 - Retrying op 730/"sh:1178129" because KvNotMyVBucket and always retry.
Debug 2021-07-05 04:03:54.635 +00:00 - Updating new map revision 25315
Debug 2021-07-05 04:03:54.638 +00:00 - Publishing config revision 25317 to subscribers for processing.
Debug 2021-07-05 04:03:54.641 +00:00 - Current revision for "mvmx_hk_trunk" is rev#25317
Debug 2021-07-05 04:03:54.644 +00:00 - Receiving new map revision 25315
Debug 2021-07-05 04:03:54.647 +00:00 - Updating new map revision 25315
Debug 2021-07-05 04:03:54.650 +00:00 - Publishing config revision 25317 to subscribers for processing.
Debug 2021-07-05 04:03:54.652 +00:00 - Current revision for "mvmx_hk_trunk" is rev#25317
Debug 2021-07-05 04:03:54.655 +00:00 - Receiving new map revision 25315
Debug 2021-07-05 04:03:54.658 +00:00 - Updating new map revision 25315
Debug 2021-07-05 04:03:54.659 +00:00 - Executing op Set on "10.112.64.109:11210" with key "sh:1178370" and opaque 732.
Debug 2021-07-05 04:03:54.661 +00:00 - Publishing config revision 25317 to subscribers for processing.
Debug 2021-07-05 04:03:54.662 +00:00 - Server "10.112.64.109:11210" returned VBucketBelongsToAnotherServer for op Set with key "sh:1178370" and opaque 732.
Debug 2021-07-05 04:03:54.664 +00:00 - Current revision for "mvmx_hk_trunk" is rev#25317
Debug 2021-07-05 04:03:54.667 +00:00 - {"NetworkResolution":"auto","SurrogateHost":null,"rev":25315,"name":"mvmx_hk_trunk","uri":"/pools/default/buckets/mvmx_hk_trunk?bucket_uuid=e3f065a1c1d63567ee19f21ba8bedcde","streamingUri":"/pools/default/bucketsStreaming/mvmx_hk_trunk?bucket_uuid=e3f065a1c1d63567ee19f21ba8bedcde","nodes":[{"couchApiBase":"http://10.112.64.108:8092/mvmx_hk_trunk%2Be3f065a1c1d63567ee19f21ba8bedcde","couchApiBaseHttps":"https://$HOST:18092/default","hostname":"10.112.64.108:8091","ports":{"direct":11210,"proxy":11211,"sslDirect":11207,"httpsCAPI":18092,"httpsMgmt":18091},"services":null,"version":null},{"couchApiBase":"http://10.112.64.109:8092/mvmx_hk_trunk%2Be3f065a1c1d63567ee19f21ba8bedcde","couchApiBaseHttps":"https://$HOST:18092/default","hostname":"10.112.64.109:8091","ports":{"direct":11210,"proxy":11211,"sslDirect":11207,"httpsCAPI":18092,"httpsMgmt":18091},"services":null,"version":null},{"couchApiBase":"http://10.112.64.110:8092/mvmx_hk_trunk%2Be3f065a1c1d63567ee19f21ba8bedcde","couchApiBaseHttps":"https://$HOST:18092/default","hostname":"10.112.64.110:8091","ports":{"direct":11210,"proxy":11211,"sslDirect":11207,"httpsCAPI":18092,"httpsMgmt":18091},"services":null,"version":null}],"nodesExt":[{"thisNode":false,"services":{"mgmt":8091,"mgmtSSL":18091,"indexAdmin":9100,"indexScan":9101,"indexHttp":9102,"indexStreamInit":9103,"indexStreamCatchup":9104,"indexStreamMaint":9105,"indexHttps":19102,"kv":11210,"kvSSL":11207,"capi":8092,"capiSSL":18092,"projector":9999,"n1ql":8093,"n1qlSSL":18093,"cbas":8095,"cbasSSL":18095,"fts":8094,"ftsSSL":18094,"moxi":11211},"hostname":"10.112.64.108","alternateAddresses":null,"HasAlternateAddress":false},{"thisNode":true,"services":{"mgmt":8091,"mgmtSSL":18091,"indexAdmin":9100,"indexScan":9101,"indexHttp":9102,"indexStreamInit":9103,"indexStreamCatchup":9104,"indexStreamMaint":9105,"indexHttps":19102,"kv":11210,"kvSSL":11207,"capi":8092,"capiSSL":18092,"projector":9999,"n1ql":8093,"n1qlSSL":18093,"cbas":8095,"cbasSSL":18095,"fts":8094,"ftsSSL":18094,"moxi":11211},"hostname":"10.112.64.109","alternateAddresses":null,"HasAlternateAddress":false},{"thisNode":false,"services":{"mgmt":8091,"mgmtSSL":18091,"indexAdmin":9100,"indexScan":9101,"indexHttp":9102,"indexStreamInit":9103,"indexStreamCatchup":9104,"indexStreamMaint":9105,"indexHttps":19102,"kv":11210,"kvSSL":11207,"capi":8092,"capiSSL":18092,"projector":9999,"n1ql":8093,"n1qlSSL":18093,"cbas":8095,"cbasSSL":18095,"fts":8094,"ftsSSL":18094,"moxi":11211},"hostname":"10.112.64.110","alternateAddresses":null,"HasAlternateAddress":false}],"nodeLocator":"vbucket","uuid":"e3f065a1c1d63567ee19f21ba8bedcde","ddocs":{"uri":"/pools/default/buckets/mvmx_hk_trunk/ddocs"},"vBucketServerMap":{"hashAlgorithm":"CRC","numReplicas":2,"serverList":["10.112.64.108:11210","10.112.64.109:11210","10.112.64.110:11210"],"vBucketMap":[[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[2,0,1],[2,0,1],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[2,0,1],[0,1,2],[0,1,2],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[2,0,1],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[0,1,2],[0,1,2],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[2,0,1],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,1,2],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[2,0,1],[2,0,1],[2,0,1],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[1,2,0],[1,2,0],[2,0,1],[2,0,1],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,2,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,2,1],[0,2,1],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[0,2,1],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[2,0,1],[2,0,1],[2,0,1],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,1,2],[0,2,1],[2,1,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,2,0],[0,2,1],[0,2,1],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[2,1,0],[2,1,0],[2,1,0],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,1,2],[0,1,2],[0,2,1],[0,2,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[1,0,2],[2,1,0],[2,1,0],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,1,2],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,1,0],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[1,2,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[0,1,2],[0,1,2],[0,1,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[1,0,2],[1,0,2],[1,0,2],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,2,1],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,2,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[0,1,2],[0,1,2],[0,1,2],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,2,0],[1,2,0],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[0,1,2],[0,1,2],[0,2,1],[0,1,2],[0,1,2],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,1,2],[1,0,2],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[0,2,1],[0,2,1],[0,2,1],[1,0,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[1,0,2],[1,0,2],[1,0,2],[0,2,1],[0,2,1],[1,2,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,2,0],[1,2,0],[1,2,0],[2,1,0],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[2,1,0],[2,1,0],[2,1,0],[0,2,1],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,0,2],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,0,2],[1,0,2],[1,2,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[0,2,1],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,1,0],[2,1,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[1,0,2],[1,0,2],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[1,0,2],[1,0,2],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,1,0],[0,1,2],[0,1,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,2,0],[1,2,0],[1,2,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,2,1],[0,2,1],[1,0,2],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[1,0,2],[1,0,2],[1,0,2],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,2,0],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[2,0,1],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[2,0,1],[2,0,1],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[2,0,1],[2,0,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,0,2],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[1,0,2],[0,1,2],[0,1,2],[0,1,2],[0,1,2],[1,2,0],[1,2,0],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,2,1],[1,2,0],[1,2,0],[1,2,0],[2,1,0],[1,0,2],[1,0,2],[1,0,2],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[0,2,1],[2,0,1],[2,0,1],[2,1,0],[0,2,1],[2,0,1],[2,0,1],[2,0,1],[0,1,2],[0,1,2],[0,1,2],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[1,2,0],[0,1,2]],"vBucketMapForward":[]},"bucketCapabilitiesVer":"","bucketCapabilities":["couchapi","xattr","dcp","cbhello","touch","cccp","xdcrCheckpointing","nodesExt"],"clusterCapabilitiesVer":null,"clusterCapabilities":null,"VBucketMapChanged":false,"ClusterNodesChanged":false}

Upgrade to SDK 3.1.7 cause this problem in this issue for me: "Only the default Scope is supported by Memcached Buckets" Error

This is the code I’m using, I don’t think bucket/cluster is dispose anywhere

var bucket = await _playerTagsBucketProvider.GetBucketAsync(); //INamedBucketProvider
var collection = bucket.DefaultCollection();
await collection.UpsertAsync(...);

And finally, SDK version is 3.1.0 and server version is Enterprise Edition 6.0.3 build 2895

thinh-ng · July 6, 2021, 4:16pm

Here more log when that occurred

Debug 2021-07-06 14:35:36.136 +00:00 - Fetching collection "_default".
Debug 2021-07-06 14:35:36.136 +00:00 - CB: Current state is Closed.
Debug 2021-07-06 14:35:36.136 +00:00 - CB: Sending 141 to "10.112.64.109:11210".
Debug 2021-07-06 14:35:36.136 +00:00 - Executing op Set on "10.112.64.109:11210" with key "sh:337170" and opaque 141.
Debug 2021-07-06 14:35:36.137 +00:00 - Op failed: Couchbase.Core.IO.Operations.Set`1[System.String]: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'DataFlowConnectionPool'.
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.EnsureNotDisposed()
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.SendAsync(IOperation operation, CancellationToken cancellationToken)
   at Couchbase.Core.ClusterNode.<>c.<ExecuteOp>b__119_0(IOperation op2, Object state, CancellationToken effectiveToken)
   at Couchbase.Core.ClusterNode.ExecuteOp(Func`4 sender, IOperation op, Object state, CancellationToken token)
Information 2021-07-06 14:35:36.140 +00:00 - v=84YCQZYgAt8WU0xhfsJBlMxUc4E=
Information 2021-07-06 14:35:36.140 +00:00 - v=2xYIiSqpOFaFnZyaAZg2MZlRM5o=
Debug 2021-07-06 14:35:36.140 +00:00 - Connection for "10.112.64.110:11210" has been started.
Debug 2021-07-06 14:35:36.140 +00:00 - Connection for "10.112.64.110:11210" has been started.
Debug 2021-07-06 14:35:36.140 +00:00 - Starting connection pool monitor on "10.112.64.110:11210", idle timeout 00:01:00, back pressure threshold 8
Debug 2021-07-06 14:35:36.140 +00:00 - Connection pool for "10.112.64.110:11210" initialized with 2 connections.
Debug 2021-07-06 14:35:36.141 +00:00 - Adding node "10.112.64.110:11210" to [].
Debug 2021-07-06 14:35:36.141 +00:00 - Added node "10.112.64.110:11210" to ["10.112.64.110:11210-93fb9c71-5925-445e-ad6e-944d36b89ab4"]
Debug 2021-07-06 14:35:36.141 +00:00 - Executing op SelectBucket on "10.112.64.110:11210" with key "mvmx_hk_trunk" and opaque 144.
Debug 2021-07-06 14:35:36.141 +00:00 - Executing op SelectBucket on "10.112.64.110:11210" with key "mvmx_hk_trunk" and opaque 145.
Debug 2021-07-06 14:35:36.142 +00:00 - Completed executing op "10.112.64.110:11210" on SelectBucket with key "mvmx_hk_trunk" and opaque 144
Debug 2021-07-06 14:35:36.142 +00:00 - Completed executing op "10.112.64.110:11210" on SelectBucket with key "mvmx_hk_trunk" and opaque 145
Debug 2021-07-06 14:35:36.142 +00:00 - Executing op GetClusterConfig on "10.112.64.110:11210" with key "" and opaque 147.
Debug 2021-07-06 14:35:36.143 +00:00 - Completed executing op "10.112.64.110:11210" on GetClusterConfig with key "" and opaque 147
Information 2021-07-06 14:35:36.145 +00:00 - NetworkResolution [auto] using default 10.112.64.108
Debug 2021-07-06 14:35:36.145 +00:00 - The node already exists for the endpoint "10.112.64.108:11210" using rev#26182 for bucket "mvmx_hk_trunk".
Information 2021-07-06 14:35:36.145 +00:00 - NetworkResolution [auto] using default 10.112.64.109
Debug 2021-07-06 14:35:36.145 +00:00 - The node already exists for the endpoint "10.112.64.109:11210" using rev#26182 for bucket "mvmx_hk_trunk".
Information 2021-07-06 14:35:36.145 +00:00 - NetworkResolution [auto] using default 10.112.64.110
Debug 2021-07-06 14:35:36.145 +00:00 - The node already exists for the endpoint "10.112.64.110:11210" using rev#26182 for bucket "mvmx_hk_trunk".
Debug 2021-07-06 14:35:36.145 +00:00 - ExistingEndpoints: ["10.112.64.108:11210", "10.112.64.109:11210", "10.112.64.110:11210"], revision 26182.
Debug 2021-07-06 14:35:36.145 +00:00 - RemovedEndpoints: [], revision 26182
Debug 2021-07-06 14:35:36.146 +00:00 - The subject has successfully bootstrapped.
Warning 2021-07-06 14:35:36.140 +00:00 - Couchbase retry "00:00:00.1000000": "Cannot access a disposed object.\nObject name: 'DataFlowConnectionPool'."
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'DataFlowConnectionPool'.
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.EnsureNotDisposed()
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.SendAsync(IOperation operation, CancellationToken cancellationToken)
   at Couchbase.Core.ClusterNode.<>c.<ExecuteOp>b__119_0(IOperation op2, Object state, CancellationToken effectiveToken)
   at Couchbase.Core.ClusterNode.ExecuteOp(Func`4 sender, IOperation op, Object state, CancellationToken token)
   at Couchbase.Core.ClusterNode.SendAsync(IOperation op, CancellationToken token)
   at Couchbase.CouchbaseBucket.SendAsync(IOperation op, CancellationToken token)
   at Couchbase.CouchbaseBucket.SendAsync(IOperation op, CancellationToken token)
   at Couchbase.Core.Retry.RetryOrchestrator.RetryAsync(BucketBase bucket, IOperation operation, CancellationToken token)
   at Couchbase.Core.BucketBase.RetryAsync(IOperation operation, CancellationToken token)
   at Couchbase.KeyValue.CouchbaseCollection.RetryUntilTimeoutOrSuccessAsync(Nullable`1 token, Nullable`1 timeout, IOperation op)
   at Couchbase.KeyValue.CouchbaseCollection.UpsertAsync[T](String id, T content, UpsertOptions options)
   at Marvin.SortingHat.Subscriber.Infrastructure.PlayerTagsDataHandler.UpsertAsync(Int64 psaId, IEnumerable`1 playerTags, CancellationToken cancellationToken) in /src/src/Marvin.SortingHat.Subscriber/Infrastructure/PlayerTagsDataHandler.cs:line 37
   at Polly.AsyncPolicy.<>c__DisplayClass40_0.<<ImplementationAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Polly.Retry.AsyncRetryEngine.ImplementationAsync[TResult](Func`3 action, Context context, CancellationToken cancellationToken, ExceptionPredicates shouldRetryExceptionPredicates, ResultPredicates`1 shouldRetryResultPredicates, Func`5 onRetryAsync, Int32 permittedRetryCount, IEnumerable`1 sleepDurationsEnumerable, Func`4 sleepDurationProvider, Boolean continueOnCapturedContext)
Debug 2021-07-06 14:35:36.260 +00:00 - Fetching collection "_default".
Debug 2021-07-06 14:35:36.260 +00:00 - CB: Current state is Closed.
Debug 2021-07-06 14:35:36.260 +00:00 - CB: Sending 148 to "10.112.64.109:11210".
Debug 2021-07-06 14:35:36.260 +00:00 - Executing op Set on "10.112.64.109:11210" with key "sh:337170" and opaque 148.
Debug 2021-07-06 14:35:36.261 +00:00 - Op failed: Couchbase.Core.IO.Operations.Set`1[System.String]: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'DataFlowConnectionPool'.
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.EnsureNotDisposed()
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.SendAsync(IOperation operation, CancellationToken cancellationToken)
   at Couchbase.Core.ClusterNode.<>c.<ExecuteOp>b__119_0(IOperation op2, Object state, CancellationToken effectiveToken)
   at Couchbase.Core.ClusterNode.ExecuteOp(Func`4 sender, IOperation op, Object state, CancellationToken token)
Warning 2021-07-06 14:35:36.261 +00:00 - Couchbase retry "00:00:00.1000000": "Cannot access a disposed object.\nObject name: 'DataFlowConnectionPool'."
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'DataFlowConnectionPool'.
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.EnsureNotDisposed()
   at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.SendAsync(IOperation operation, CancellationToken cancellationToken)
   at Couchbase.Core.ClusterNode.<>c.<ExecuteOp>b__119_0(IOperation op2, Object state, CancellationToken effectiveToken)
   at Couchbase.Core.ClusterNode.ExecuteOp(Func`4 sender, IOperation op, Object state, CancellationToken token)
   at Couchbase.Core.ClusterNode.SendAsync(IOperation op, CancellationToken token)
   at Couchbase.CouchbaseBucket.SendAsync(IOperation op, CancellationToken token)
   at Couchbase.CouchbaseBucket.SendAsync(IOperation op, CancellationToken token)
   at Couchbase.Core.Retry.RetryOrchestrator.RetryAsync(BucketBase bucket, IOperation operation, CancellationToken token)
   at Couchbase.Core.BucketBase.RetryAsync(IOperation operation, CancellationToken token)
   at Couchbase.KeyValue.CouchbaseCollection.RetryUntilTimeoutOrSuccessAsync(Nullable`1 token, Nullable`1 timeout, IOperation op)
   at Couchbase.KeyValue.CouchbaseCollection.UpsertAsync[T](String id, T content, UpsertOptions options)
   at Marvin.SortingHat.Subscriber.Infrastructure.PlayerTagsDataHandler.UpsertAsync(Int64 psaId, IEnumerable`1 playerTags, CancellationToken cancellationToken) in /src/src/Marvin.SortingHat.Subscriber/Infrastructure/PlayerTagsDataHandler.cs:line 37
   at Polly.AsyncPolicy.<>c__DisplayClass40_0.<<ImplementationAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Polly.Retry.AsyncRetryEngine.ImplementationAsync[TResult](Func`3 action, Context context, CancellationToken cancellationToken, ExceptionPredicates shouldRetryExceptionPredicates, ResultPredicates`1 shouldRetryResultPredicates, Func`5 onRetryAsync, Int32 permittedRetryCount, IEnumerable`1 sleepDurationsEnumerable, Func`4 sleepDurationProvider, Boolean continueOnCapturedContext)

Odd thing is when I ran it locally (on Windows and Linux container on Docker) these issues don’t happen, but running on kubernetes pod then it happened

jmorris · July 14, 2021, 8:15pm

A NMVB exception is something I would expect to see in a failover/swap/rebalance scenario as the cluster map has changed but the client hasn’t yet completed the update - I see rev 25315 changed to 25317 - so this make sense. The SDK will retry this until it either succeeds or times out.

Notice how this comes after the first ObjectDisposedException? The SDK hasn’t completed bootstrapping and its being used by the app. I am guessing the client application is using the cluster before its been fully provisioned in k8s.

Try waiting until the cluster is fully provisioned before having the app start - additionally, try calling bucket.WaitUntilReadyAsync(..) is this should make the SDK wait before sending ops.

Jeff

svengr · December 9, 2021, 6:53pm

Hi,

We have the same issue.

Something went wrong: System.ObjectDisposedException: Cannot access a disposed object.\nObject name: ‘DataFlowConnectionPool’.\n at Couchbase.Utils.ThrowHelper.ThrowObjectDisposedException(String objectName)\n at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.EnsureNotDisposed()\n at Couchbase.Core.IO.Connections.DataFlow.DataFlowConnectionPool.SendAsync(IOperation operation, CancellationToken cancellationToken)\n at Couchbase.Core.ClusterNode.<>c.b__118_0(IOperation op2, Object state, CancellationToken effectiveToken)\n at Couchbase.Core.ClusterNode.ExecuteOp(Func`4 sender, IOperation op, Object state, CancellationTokenPair tokenPair)\n at Couchbase.CouchbaseBucket.SendAsync(IOperation op, CancellationTokenPair tokenPair)\n at Couchbase.Core.Retry.RetryOrchestrator.RetryAsync(BucketBase bucket, IOperation operation, CancellationTokenPair tokenPair)\n at Couchbase.KeyValue.CouchbaseCollection.UpsertAsync[T](String id, T content, UpsertOptions options)\n at …

We are able to identify that the code works without errors upto 3.1.2 and starts failing in 3.1.3

Other important facts: Our couchbase server is running inside a k8s cluster on docker - desktop /windows
The server image is CB_PACKAGE=couchbase-server-enterprise_6.6.1-ubuntu18.04_amd64.deb CB_RELEASE_URL=https://packages.couchbase.com/releases/6.6.1

mdomashchenko · February 28, 2022, 11:43pm

I had the same issue with System.ObjectDisposedException, debugged it a bit and I think you have a race condition in ClusterContext.GetOrCreateBucketAsync()

The ClusterContext.Buckets is a ConcurrentDictionary, no problems with the object itselt. When the bucket is already there, everything works fine and there are no threading issues.

Now, if the bucket haven’t been initialized yet and multiple requests for the same bucket enter this method and get to the nested loops in line 392, the method starts initializing a new instance of a bucket for each request, since that new instance is not placed into the Buckets concurrent dictionary until it’s connected.

So, there are multiple instances created and since ClusterNode instances are managed independently, it happens sometimes that Nodes collection inside a bucket instance shares ClusterNode objects with another instance of a bucket.

Now, after all the buckets initialize connections to the cluster, each opening sockets and the whole nine yards, only one lucky instance gets into ClusterContext.Buckets. Still, due to some rooted references, other bucket instances stay around in memory and keep those sockets open, wasting server’s resources.

Also, in some cases a ClusterNode inside a CouchbaseBucket referenced by ClusterContext.Buckets would get disposed. We have 3 nodes, I’ve collected a dump file from a process that was throwing System.ObjectDisposedExceptions and found that one of the nodes was indeed marked as disposed. I saw the log statement about it being disposed as well.

When this happens, the process never recovers on its own. Since I needed a quick fix, I just created my own wrapper for ICluster.BucketAsync() with a lock statement around the call.

I verified process dumps after the change - only saw a single instance of CouchbaseBucket per name, as expected and only 3 ClusterNode instances inside where previously I’ve seen six.

This is a rather crude solution, though, I hope you can fix it in a more elegant way

As it is, it’s not thread-safe and the documentation doesn’t mention this either.

Let me know if you’d like additional details.

github.com

couchbase/couchbase-net-client/blob/21576324f60e33a196a956291dbaaa4bfb48bc85/src/Couchbase/Core/ClusterContext.cs#L392

      
        
                }
            }
            
            
public async ValueTask<IBucket> GetOrCreateBucketAsync(string name)
            {
                if (Buckets.TryGetValue(name, out var bucket))
                {
                    return bucket;
                }
            
            
    foreach (var server in ClusterOptions.ConnectionStringValue.GetBootstrapEndpoints(ClusterOptions.EnableTls))
                {
                    foreach (var type in Enum.GetValues(typeof(BucketType)))
                    {
                        try
                        {
                            bucket = await CreateAndBootStrapBucketAsync(name, server, (BucketType) type)
                                .ConfigureAwait(false);
            
            
                if ((bucket is Bootstrapping.IBootstrappable bootstrappable) && bootstrappable.IsBootstrapped)
                                return bucket;

jmorris · February 28, 2022, 11:57pm

@mdomashchenko

The expected creation pattern will always keep this from happening (using DI or APPLICATION_START). That being said, BucketAsync should be synchronized to avoid this race condition. I created a ticket for fixing this: NCBC-3149

Thanks for sharing your analysis!

Jeff

mdomashchenko · March 2, 2022, 8:14pm

found out that I was not careful enough with my lock statement. Can’t have await inside lock and without that it doesn’t lock enough.

Had to change to AsyncLock as described here Building Async Coordination Primitives, Part 6: AsyncLock - .NET Parallel Programming (microsoft.com)