Query failed. See inner exception for details. ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.

[Ido Ben Ari]

Hi,
I am using build 3660 in our production environment on Amzon AWS.
Few times a day, across multiple servers and multiple application types  (not necessarily in the same time) , I get exceptions similar to the one below.
I used fiddler to capture requests. No long duration calls to db.
Could you please give guide me - what's the best approach to investigate this?

Thank you!
Ido


The exception:


System.InvalidOperationException: Query failed. See inner exception for details. ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Raven.Client.Extensions.TaskExtensions2.ResultUnwrap[T](Task`1 task) in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Extensions\TaskExtensions2.cs:line 59
   at Raven.Client.Connection.ServerClient.Query(String index, IndexQuery query, String[] includes, Boolean metadataOnly, Boolean indexEntriesOnly) in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Connection\ServerClient.cs:line 395
   --- End of inner exception stack trace ---
   at Raven.Client.Connection.ServerClient.Query(String index, IndexQuery query, String[] includes, Boolean metadataOnly, Boolean indexEntriesOnly) in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Connection\ServerClient.cs:line 404
   at Raven.Client.Document.AbstractDocumentQuery`2.ExecuteActualQuery() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Document\AbstractDocumentQuery.cs:line 665
   at Raven.Client.Document.AbstractDocumentQuery`2.ExecuteQueryOperation(Int32 take) in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Document\AbstractDocumentQuery.cs:line 1074
   at Raven.Client.Document.AbstractDocumentQuery`2.FirstOrDefault() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Document\AbstractDocumentQuery.cs:line 1054
   at Raven.Client.Linq.RavenQueryProviderProcessor`1.GetQueryResult[TProjection](IDocumentQuery`1 finalQuery) in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Linq\RavenQueryProviderProcessor.cs:line 1686
   at Raven.Client.Linq.RavenQueryProviderProcessor`1.ExecuteQuery[TProjection]() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Linq\RavenQueryProviderProcessor.cs:line 1623
   at Raven.Client.Linq.RavenQueryProvider`1.System.Linq.IQueryProvider.Execute[S](Expression expression) in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Linq\RavenQueryProvider.cs:line 191
   at System.Linq.Queryable.FirstOrDefault[TSource](IQueryable`1 source)
   at OTAGenericAPI.OTAGenericFlow.PullOTA_HotelRatePlanRQ(OTA_HotelRatePlanRQ req) in c:\NewCode\PIBranches\OnGoing\OTAFlowManager\OTAGenericFlow.cs:line 696

[Oren Eini (Ayende Rahien)]

This is usually an indication of a timeout on the part of the query (on the client side).

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Ido Ben Ari]

Thanks for the prompt reply Oren.
Do you mean a time-out in the client side before the said query was even sent to the db?
(In the fiddler I can't see any long duration calls).

Ido

[Oren Eini (Ayende Rahien)]

The error doesn't indicate a server side response.

It may be a long time in answering, or short timeout in the client. Note that it is possible that a global state affects this for the client.

[Ido Ben Ari]

I think that if any request would have been sent to the db I would see it in Fiddler, so I think I can rule out long time in answering.
Short time-out in the client - the error comes from Raven code, and it's not inside any async thread I explicitly started.
Global state - it's  possible, but the it happens across multiple machines and application types. I can't rule it out but doesn't seem to be the case.
I will try to add some logs before and after the call to the db and take times.
Please let me know if you have any other idea how to debug it.

Thanks,
Ido

[Oren Eini (Ayende Rahien)]

Do you have anything that might be setting the http request timeout? 

[Ido Ben Ari]

Not explicitly.
The applications are WCF web services.
The only special thing is that In one of them I have :

  <system.net>
    <settings>
      <servicePointManager expect100Continue="false"/>

But it happens also in the other application so I don't think it's related.

[Oren Eini (Ayende Rahien)]

Can you check if this happens on specific queries, or all?

[Oren Eini (Ayende Rahien)]

Is this reproducible?

[Ido Ben Ari]

It isn't.
I am adding logs trying to get more information next time it happens. It's not a specific scenario since it happens in various parts of the code.
Under the current load on the system it happens once or twice per day, few requests every time

[Oren Eini (Ayende Rahien)]

What happens if you manually simulate higher load?

[Oren Eini (Ayende Rahien)]

Also check if this is something that happens when dns may be refreshing, or something like that.

[Ido Ben Ari]

Thanks.
It didn't happen during load tests I performed in the past. I will run some more load test to try to reproduce.
I will check the direction of DNS refresh.
Will keep you posted.

[Oren Eini (Ayende Rahien)]

Check the timing of the error from start of request to the error.

Also check the RequestTimeout property on the JsonRequestFactory

[Ido Ben Ari]

An update:
I measured the duration before the db query and after, and the long duration is always in the db call (see it below).
However, it's not reflected in fiddler, hence the problem is not in the server side or in the network itself.
I suspected the problem was related to requests pending in a queue. I reduced db calls (removed logs writings to db) and increased the maxconnection per the db IP.
<connectionManagement>
      <add address = "http://10.0.x.x:8080" maxconnection = "30" />

 the original problem is not reproduced anymore.
What I see now, is that from time to time some of the db calls duration takes >15 sec. Once again, not reflected in fiddler call.
On load tests (even on production server) , performance is excellent under heavy load.



Query to DB:
  var rtcFullQuery = dbSession.Query<PI.Domain.DataStructures.RoomTypeContract>()
                             .Where(rp => rp.RoomTypeID.HotelCode == hotelCode && rp.RoomTypeRates.RatePerDateList.Any(x => x.Date >= checkIn && x.Date < checkOut))

                           .TransformWith<RoomTypesContractWithRoomTypeTranformerFull, RoomTypesContractWithRoomTypeTranformerFull.Result>()
                           .AddTransformerParameter("dates", checkIn.ToString("yyyy-MM-dd") + "," + checkOut.ToString("yyyy-MM-dd"))
                           .AddTransformerParameter("avlByRP", availabilityByRp)
                           .AddTransformerParameter("interfaceName",interfaceId.ToString())
                           .ToList();

[Oren Eini (Ayende Rahien)]

It is possible that you have a high number of concurrent calls, so this is actually stalling waiting for a connection?

and so when you increased the number of connections, you resolved that bottleneck