System.TimeoutException: Could not acquire a server

We are seeing this error rather frequently in our automated testing environment, and I am not sure what it means or how to remedy it. This is occurring when we attempt to insert documents via the .NET SDK using the ClusterHelper to obtain a reference to the bucket.

When we see this error, the cluster nodes are hovering around 50 ops/second, and everything seems to be responsive and healthy from the admin console.

What are the recommended app.config settings for timeouts and connections, etc? Here is what we are currently using:

  <couchbaseClients>
    <couchbase useSsl="false" operationLifespan="1000">
      <servers>
        <add uri="http://node1:8091" />
        <add uri="http://node2:8091" />
      </servers>
      <buckets>
        <add name="default" operationLifespan="5000">
          <connectionPool name="custom" maxSize="30" minSize="5" sendTimeout="12000"></connectionPool>
        </add>
      </buckets>
    </couchbase>
  </couchbaseClients>

Hi @pkramer-

Which SDK version and Couchbase server version are you using? Could you post the entire stacktrace?

-Jeff

We are using 2.3.11.

System.TimeoutException: Could not acquire a server.
at Couchbase.Core.Buckets.CouchbaseRequestExecuter.SendWithRetryAsync[T](IOperation`1 operation, TaskCompletionSource`1 tcs, CancellationTokenSource cts)

@pkramer -

One issue I see is that your operationLifeSpan is set to 1s and over ridden for the default bucket as 5s, but your sendTimeout is 12s. The operationLifeSpan should be greater than the sendTimeout. I would suggest removing those values and just using the defaults. I am not sure that is causing your problems though; i need more information.

-Jeff

I’ll give those a shot and report back. Thanks!

I can reproduce it consistently when I run three of our tests concurrently (even with those settings removed and using the defaults).

2017-08-02 16:02:46,714 [Agent: adapter run thread for test 'ChangeListener_DocumentChangeReceived_Resiliency' with id 'b139b305-f784-4f28-ac6d-ad1b3719b579'] [ZOLL.Core.Couchbase.Performance.BlockTimer] Starting block execution, Block Name: ZOLL.Core.Couchbase.Sync.DocumentChangeListener.StartAsync, Block ID: cff66a0c-6523-46fd-9094-8b893a0a386c, Elapsed: , Elapsed (MS): 
2017-08-02 16:02:46,714 [Agent: adapter run thread for test 'ChangeListener_DocumentChangeReceived_Resiliency' with id 'b139b305-f784-4f28-ac6d-ad1b3719b579'] [ZOLL.Core.Couchbase.Sync.DocumentChangeListener] Looking up last processed sequence number from sequence repository...
2017-08-02 16:02:46,714 [Agent: adapter run thread for test 'ChangeListener_DocumentChangeReceived_Resiliency' with id 'b139b305-f784-4f28-ac6d-ad1b3719b579'] [ZOLL.Core.Couchbase.Sync.DurableSequenceRepository] Fetching last sequence number from Couchbase...
2017-08-02 16:02:46,714 [Agent: adapter run thread for test 'ChangeListener_DocumentChangeReceived_Resiliency' with id 'b139b305-f784-4f28-ac6d-ad1b3719b579'] [ZOLL.Core.Couchbase.Sync.DurableSequenceRepository] Running query: SELECT MAX(sequence) AS sequence FROM bucket WHERE type = 'changeFeedMarker' AND changeFeedName = '5f0ebabf-f1ee-47e6-8eb4-fa1cd2145444' AND processed=true
2017-08-02 16:02:50,809 [Agent: adapter run thread for test 'ChangeListener_DocumentChangeReceived_Resiliency' with id 'b139b305-f784-4f28-ac6d-ad1b3719b579'] [Couchbase.Core.Buckets.CouchbaseRequestExecuter] System.TimeoutException: Could not acquire a server.
   at Couchbase.Core.Buckets.CouchbaseRequestExecuter.<>c__DisplayClass20_0`1.<<SendWithRetryAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at Couchbase.Core.Buckets.CouchbaseRequestExecuter.<RetryQueryEveryAsync>d__7`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at Couchbase.Core.Buckets.CouchbaseRequestExecuter.<SendWithRetryAsync>d__20`1.MoveNext()

The task that is being awaited is this:

        private Task<IQueryResult<JObject>> QueryLastProcessed()
        {
            IBucket bucket = _helper.GetBucket();
            string query = string.Format(_queryFormat, bucket.Name, _changesFeedName);
            IQueryRequest queryRequest = new QueryRequest().Statement(query);

            _log.DebugFormat("Running query: {0}", query);
            return bucket.QueryAsync<JObject>(queryRequest);
        }

@pkramer -

Would it be possible to upgrade to version 2.4.7 of the SDK and see if the issue still exists?

This did not change the behavior.

@pkramer -

I’ll try to reproduce and let you know what I find.

@jmorris Have you had any luck reproducing this issue?

@pkramer -

I couldn’t reproduce this on a two node cluster using the following code:

    static void Main(string[] args)
    {
        ClusterHelper.Initialize(new ClientConfiguration
        {
            Servers = new List<Uri>
            {
                new Uri("http://localhost:8091")
            }
        });       

        var threads = new List<Thread>();
        for (var i = 0; i < 50; i++)
        {
            threads.Add(new Thread(DoWork));
        }

        foreach (var thread in threads)
        {
            thread.Start();
            thread.Join();
        }
        Console.Read();
    }

    public static void DoWork()
    {
        Task.Run(async () =>
        {
            for (var i = 0; i < 10; i++)
            {
                var result = await QueryLastProcessed();
                Console.WriteLine(result.Status);
            }
        });
    }

    private static Task<IQueryResult<JObject>> QueryLastProcessed()
    {
        var bucket = ClusterHelper.GetBucket("default");
        var queryRequest = new QueryRequest().Statement("SELECT * FROM `default`");
        return bucket.QueryAsync<JObject>(queryRequest);
    } 

Perhaps you could enable logging and see what’s going on under the hood?

-Jeff

The logs are kind of lengthy to post as text here. I can still do so if you’d like, or e-mail them to you.

@pkramer - jeffry.morris at couchbase.com