.NET client / AspNet Exceptions

.NET SDK
, , , ,
1

During a load test, we were seeing this:
{“timestamp”:“2017-01-13T13:26:47.0455387-05:00”,“message”:{“Key”:“devprod::Events::header::nxi3hlcvil1o5mpw0a40myrz”,“Status”:“NodeUnavailable”,“Message”:“The node ww.xx.yy.zz:11210 that the key was mapped to is either down or unreachable. The SDK will continue to try to connect every 1000ms. Until it can connect every operation routed to it will fail with this exception.”,“Exception”:{“ClassName”:“Couchbase.Core.NodeUnavailableException”,“Message”:“The node ww.xx.yy.zz:11210 that the key was mapped to is either down or unreachable. The SDK will continue to try to connect every 1000ms. Until it can connect every operation routed to it will fail with this exception.”,“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:null,“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:null,“HResult”:-2146233088,“Source”:null,“WatsonBuckets”:null}},“logger”:“Couchbase.AspNet.SessionState.SessionStateItem”,“level”:“WARN”,“thread”:“195”,“domain”:"/LM/W3SVC/4/ROOT/application-1-131287399073920547",“username”:“CORE\lwr-iisman”,“log4net:locationInfo”:{“class”:“Couchbase.AspNet.SessionState.SessionStateItem”,“method”:“Load”,“file”:null,“line”:“0”}}

other exception:
{“timestamp”:“2017-01-13T14:11:39.8878279-05:00”,“message”:“System.ObjectDisposedException: Cannot access a disposed object.\r\nObject name: ‘System.Net.Sockets.SocketAsyncEventArgs’.\r\n at System.Net.Sockets.SocketAsyncEventArgs.StartConfiguring()\r\n at System.Net.Sockets.SocketAsyncEventArgs.SetBufferInternal(Byte buffer, Int32 offset, Int32 count)\r\n at System.Net.Sockets.SocketAsyncEventArgs.SetBuffer(Int32 offset, Int32 count)\r\n at Couchbase.IO.Connection.Receive(Socket socket, SocketAsyncEventArgs e)\r\n at Couchbase.IO.Connection.OnCompleted(Object sender, SocketAsyncEventArgs args)”,“logger”:“Couchbase.IO.ConnectionBase”,“level”:“WARN”,“thread”:“271”,“domain”:"/LM/W3SVC/4/ROOT/application-1-131287399295295629",“username”:“CORE\lwr-iisman”,“log4net:locationInfo”:{“class”:“Couchbase.IO.Connection”,“method”:“OnCompleted”,“file”:null,“line”:“0”}}

And also:
{“timestamp”:“2017-01-13T13:20:22.3936474-05:00”,“message”:“Failed to read cache from couchbase. This could be a temporary failure. An abundance of errors in a single application is probably an issue with couchbase-bucket-object in AppSettings”,“logger”:“Company.Common.Caching.CacheManager”,“exception_msg”:“Thread was being aborted.”,“exception”:“System.Threading.ThreadAbortException: Thread was being aborted. NEWLINETOKEN at Couchbase.Core.Server.Send[T](IOperation1 operation) NEWLINETOKEN at Couchbase.Core.Buckets.CouchbaseRequestExecuter.SendWithRetry[T](IOperation1 operation) NEWLINETOKEN at Couchbase.CouchbaseBucket.Get[T](String key) NEWLINETOKEN at Couchbase.CouchbaseBucket.GetDocument[T](String id) NEWLINETOKEN at Company.Common.Caching.CacheManager.GetItemDataFromCouchbaseBinary[T](ILocatable itemLocator)”,“level”:“ERROR”,“thread”:“163”,“domain”:"/LM/W3SVC/4/ROOT/application-1-131287399021339295",“username”:“CORE\lwr-iisman”,“log4net:locationInfo”:{“class”:“Company.Common.Caching.CacheManager”,“method”:“GetItemDataFromCouchbaseBinary”,“file”:null,“line”:“0”}}

2

I’m sure @jmorris will have some thoughts, but incidentally, what version of the client? Can you indicate your config of the client too? In particular, were you using the default (pooled) or muxio?

3

Hi @unhuman -

The first exception (NodeUnavailableException) indicates that the client has temporarily stopped sending operations to a specific node because the ClientConfiguration.IOErrorCheckThreshold (default 500ms) has been reached within the ClientConfiguration.IOErrorCheckInterval (default 10). The client will then start polling the node at the interval provided by the ClientConfiguration.NodeAvailableCheckInterval (1 second default) setting. If client can connect, the client will start sending operations to that node again. The purpose is to determine if a node is just temporarily available or had permanently gone offline without slowing the other operations down.

Now the question is what caused the client to get into that state? Likely its a side-effect of the load test - possibly the server refusing connections, but I cannot tell from what I see here - not enough info. In general its not necessarily bad, but indicates that something may be causing problems (configuration adjustment, need for larger, more powerful node, etc.).

The 2nd exception is (ObjectDisposedException) is a minor bug in the SDK where the connection abstraction is being disposed and the underlying SocketAsyncEevntArgs object has already been disposed (actually the buffer its using). This happens on the tear down of a connection and a new one has already replaced it. We should have a patch shortly, but it should have no impact on your application.

The 3rd exception is a bit tougher because we don’t know what aborted the thread. For example, it could be ASP.NET or even IIS (or whatever app server you are using).

-Jeff

1 Like
4

@ingenthr
We run a variety of clients, but these problems are coming out of 2.3.8, as we’re experimenting with trying to figure out what’s going on AspNet. We are using default configuration. We have not yet begun to experiment with muxio (but @jmorris did generally recommend we look at it when I met him at Connect.) I’m looking for documentation for this feature now.

@jmorris
Thanks for the explanation. For the first case, what could we look for to indicate what is the problem on the server side? We are not seeing any high CPU usage, out of memory warnings, or anything else obvious to me…

5

@unhuman -

Enabling logging (Debug level) on the client should help us to establish what type of errors the SDK is responding to before going into a “Node Unavailable” state. It might be better to create an NCBC and attach them to the Jira ticket or just pull out just the exceptions that are logged.

You can also check the Couchbase server logs and see what you can gleem from them.

-Jeff

6

Is there any documentation on muxio? I haven’t found any…
Nevermind: Here it is: https://blog.couchbase.com/couchbase-net-sdk-2-2-4-now-available/

7

@jmorris

Another log:
{ [-]
domain: /LM/W3SVC/4/ROOT/application-1-131291069747280885
level: WARN
log4net:locationInfo: { [-]
class: Couchbase.AspNet.SessionState.SessionStateItem
file: null
line: 0
method: Load
}
logger: Couchbase.AspNet.SessionState.SessionStateItem
message: { [-]
Exception: { [-]
ClassName: Couchbase.IO.ConnectionUnavailableException
Data: null
ExceptionMethod: 8
Acquire
Couchbase.NetClient, Version=2.3.8.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2
Couchbase.IO.ConnectionPool1 T Acquire() HResult: -2146233088 HelpURL: null InnerException: null Message: Failed to acquire a pooled client connection on 172.21.52.29:11210 after 5 tries. RemoteStackIndex: 0 RemoteStackTraceString: null Source: Couchbase.NetClient StackTraceString: at Couchbase.IO.ConnectionPool1.Acquire()
at Couchbase.IO.ConnectionPool1.Acquire() at Couchbase.IO.ConnectionPool1.Acquire()
at Couchbase.IO.ConnectionPool1.Acquire() at Couchbase.IO.ConnectionPool1.Couchbase.IO.IConnectionPool.Acquire()
at Couchbase.IO.Services.PooledIOService.Execute[T](IOperation1 operation) at Couchbase.Core.Server.Send[T](IOperation1 operation)
WatsonBuckets: null
}
Key: devprod::Application::header::xlpvjysfgj5c2wge40jkinnd
Message: Failed to acquire a pooled client connection on 172.21.52.29:11210 after 5 tries.
Status: ClientFailure
}
thread: 11
timestamp: 2017-01-17T09:27:13.1956837-05:00
}

8

@unhuman -

I was expected an IO exception; that exception (ConnectionUnavailableException) indicates you need to increase the number of connections in the pool: increasing PoolConfiguration.MaxSizeuntil you no longer encounter that error will resolve it. Additionally, muxio will also resolve the issue because it doesn’t currently use connection pooling.

-Jeff

1 Like
9

Is it resolved for you @unhuman?

1 Like
10

We have not resolved this issue yet. We have evaluated DEBUG level logging in isolation, but are concerned about the volume of logs that will result when we run the load testing that reproduces the errors. Can you suggest more focused namespaces in which to scope the debug level, rather than the catch-all Couchbase.*?

11

@mhostetler -

Couchbase.IO is likely the namespace in question. Have you tried the other two recommendations (increase MaxSize or use muxio) above?

-Jeff

12

@jmorris

We tried both upping connections and Muxio.

For connections, we’re already at 5 min / 5 max…

We’ve started to experiment with Muxio. Client v2.3.8. We’re getting thousands of new errors (load testing):

message: { [-]
Exception: { [-]
ClassName: System.InvalidOperationException
Data: null
ExceptionMethod: 8
StartConfiguring
System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
System.Net.Sockets.SocketAsyncEventArgs
Void StartConfiguring()
HResult: -2146233079
HelpURL: null
InnerException: null
Message: “An asynchronous socket operation is already in progress using this SocketAsyncEventArgs instance.”;
RemoteStackIndex: 0
RemoteStackTraceString: null
Source: System
StackTraceString: at System.Net.Sockets.SocketAsyncEventArgs.StartConfiguring()
at System.Net.Sockets.SocketAsyncEventArgs.SetBufferInternal(Byte buffer, Int32 offset, Int32 count)
at System.Net.Sockets.SocketAsyncEventArgs.SetBuffer(Int32 offset, Int32 count)
at Couchbase.IO.Connection.Send(Byte buffer)
at Couchbase.IO.Services.PooledIOService.Execute[T](IOperation`1 operation)
WatsonBuckets: null
}
Key: Application::header::yqri0ngzpoo32fauqmsk32nj
Message: “An asynchronous socket operation is already in progress using this SocketAsyncEventArgs instance.”;
Status: ClientFailure
}

Additionally, we got a single occurrence of:

{ [-]
domain: /LM/W3SVC/4/ROOT/application-1-131296854937066797
level: WARN
log4net:locationInfo: { [-]
class: Couchbase.IO.Connection
file: null
line: 0
method: OnCompleted
}
logger: Couchbase.IO.ConnectionBase
message: System.ObjectDisposedException: Cannot access a disposed object.
Object name: ‘System.Net.Sockets.SocketAsyncEventArgs’.
at System.Net.Sockets.SocketAsyncEventArgs.StartConfiguring()
at System.Net.Sockets.SocketAsyncEventArgs.SetBufferInternal(Byte buffer, Int32 offset, Int32 count)
at System.Net.Sockets.SocketAsyncEventArgs.SetBuffer(Int32 offset, Int32 count)
at Couchbase.IO.Connection.Receive(Socket socket, SocketAsyncEventArgs e)
at Couchbase.IO.Connection.OnCompleted(Object sender, SocketAsyncEventArgs args)
thread: 41
timestamp: 2017-01-24T08:40:29.2312859-05:00
username: CORE\lwr-iisman
}

13

You can bump the MaxSize up to 10, 15, 20, etc. until the pool exhaustion issues go away. Ideally, you set a fairly low MinSize and then a much higher MaxSize so that the app can tune itself. If you do both high MaxSize and high MinSize, you’ll find that the app start-up time increases because all of those connections will have to be created and authenticated upfront.

Your problem here is that the configuration is not quite right; your still using pooled io: Couchbase.IO.Services.PooledIOService.Execute[T](IOperation1 operation)`

if you post your configuration I can help, otherwise double check the blog post and make sure your config is correct. Note that in 2.4.0 (soon to be released) the default IO service is muxio…to use pooling you have to enable it.

The last exception could be a side-effect of not having the IO service configuration correct, I can’t tell.

-Jeff

14

We’re using the MuxIO configuration elements we copied directly from the blog post:

  <couchbase>
    <servers>
      <add uri="" />
    </servers>
    <buckets>
      <add name="" password="" useSsl="false">
        <connectionPool name="custom" maxSize="2" minSize="2" waitTimeout="5000" shutdownTimeout="3000"></connectionPool>
      </add>
      <add name="" password="" useSsl="false">
        <connectionPool name="custom" maxSize="2" minSize="2" waitTimeout="5000" shutdownTimeout="3000"></connectionPool>
      </add>
    </buckets>
	<connectionPool name="custom" type="Couchbase.IO.ConnectionPool`1[Couchbase.IO.MultiplexingConnection], Couchbase.NetClient" />
    <ioService name="multiplexio" type="Couchbase.IO.Services.MultiplexingIOService, Couchbase.NetClient" />
  </couchbase>
15

Actually stand by I think I see where the misconfiguration is happening.

16

@mhostetler -

You can also configure it programmatically:

var config = new ClientConfiguration
{
    Servers = new List<Uri>
    {
        new Uri(ConfigurationManager.AppSettings["bootstrapUrl"])
    }
};
config.ConnectionPoolCreator = ConnectionPoolFactory.GetFactory<ConnectionPool<MultiplexingConnection>>();
config.IOServiceCreator = IOServiceFactory.GetFactory<MultiplexingIOService>();
ClusterHelper.Initialize(config);

Ref: Couchbase .NET SDK 2.3.3 Now Available! - The Couchbase Blog

-Jeff

17

We prefer to keep it configuration-based. Along those lines I’ve updated the configuration to

  <couchbase>
    <servers>
      <add uri="" />
    </servers>
    <buckets>
      <add name="" password="" useSsl="false" />
      <add name="" password="" useSsl="false" />
    </buckets>
	<connectionPool name="custom" type="Couchbase.IO.ConnectionPool`1[Couchbase.IO.MultiplexingConnection], Couchbase.NetClient" />
    <ioService name="multiplexio" type="Couchbase.IO.Services.MultiplexingIOService, Couchbase.NetClient" />
  </couchbase>

But when testing this locally I’m seeing entries in the log such as the following, which makes it look like it’s still doing pooling. Can you confirm whether our configuration is accurate?

  "message": "Trying to acquire new connection!",
  "logger": "Couchbase.IO.ConnectionPool`1[[Couchbase.IO.IConnection, Couchbase.NetClient, Version=2.3.8.0, Culture=neutral, PublicKeyToken=05e9c6b5a9ec94c2]]",
18

@jmorris: When you have a minute ^. Thanks!

19

@jmorris we’d still like a quick confirmation on the appropriate way to declare the MuxIO configuration. A couple attempts have left us with the impression that it’s still falling back to connection pooling.

20

@mhostetler, @unhuman -

Here is an example:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <sectionGroup name="couchbaseClients">
      <section name="multiplexio" type="Couchbase.Configuration.Client.Providers.CouchbaseClientSection,     Couchbase.NetClient" />
    </sectionGroup>
  </configSections>
  <couchbaseClients>
    <multiplexio enableConfigHeartBeat="false" useSsl="false">
      <buckets>
        <add name="default" useEnhancedDurability="true">
          <connectionPool name="default" />
     </add>
    <add name="travel-sample" useEnhancedDurability="true">
      <connectionPool name="default" />
    </add>
  </buckets>
  <connectionPool name="custom" type="Couchbase.IO.ConnectionPool`1[Couchbase.IO.MultiplexingConnection], Couchbase.NetClient"></connectionPool>
  <ioService name="multiplexio" type="Couchbase.IO.Services.MultiplexingIOService, Couchbase.NetClient" />
</multiplexio>
</couchbaseClients>
</configuration>

To use it:

var config = new ClientConfiguration((CouchbaseClientSection)ConfigurationManager.GetSection("couchbaseClients/multiplexio"));

Or like this:

var cluster = new Cluster("couchbaseClients/multiplexio")

-Jeff