Improving performance ("Error loading stacks" message)
Edreih opened this issue · 10 comments
Edreih commented
Hi,
I'm looking to get some thoughts on how to improve performance on a self-hosted installation of Exceptionless. The instance is running one a single node of Elasticsearch.
We have about 5 million messages total. Fetching all messages for "All Time" is fast. The slowness happens when trying to fetch "Stacks" or "Most Frequent" messages.
I've tried increasing the resources on the machine and setting the Elasticsearch JVM heap size to use 16GB (half of the total servers memory), with no luck.
Any ideas on how performance can be increased? Is a multi-node cluster configuration required to see better performance?
Any help is appreciated. Thank you.
niemyjski commented
What is the error you are seeing in the response? Do you have lots of deleted, discarded or ignored stacks?
Edreih commented
So here's the error I'm seeing in the Exceptionless app logs...
[08:20:24 ERR] Error while searching
Original: [TaskCanceledException] The request was canceled due to the configured HttpClient.Timeout of 60 seconds elapsing.
[null] POST /prod-stacks/_search?typed_keys=true&ignore_unavailable=true
System.Threading.Tasks.TaskCanceledException: The request was canceled due to the configured HttpClient.Timeout of 60 seconds elapsing.
---> System.TimeoutException: The operation was canceled.
---> System.Threading.Tasks.TaskCanceledException: The operation was canceled.
---> System.IO.IOException: Unable to read data from the transport connection: The I/O operation has been aborted because of either a thread exit or an application request..
---> System.Net.Sockets.SocketException (995): The I/O operation has been aborted because of either a thread exit or an application request.
--- End of inner exception stack trace ---
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
--- End of inner exception stack trace ---
at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Net.Http.HttpClient.SendAsyncCore(HttpRequestMessage request, HttpCompletionOption completionOption, Boolean async, Boolean emitTelemetryStartStop, CancellationToken cancellationToken)
--- End of inner exception stack trace ---
--- End of inner exception stack trace ---
at System.Net.Http.HttpClient.SendAsyncCore(HttpRequestMessage request, HttpCompletionOption completionOption, Boolean async, Boolean emitTelemetryStartStop, CancellationToken cancellationToken)
at Elasticsearch.Net.HttpConnection.RequestAsync[TResponse](RequestData requestData, CancellationToken cancellationToken)
[08:20:24 ERR] An error has occurred. Please check your search filter.
System.ApplicationException: Original: ( - TaskCanceledException) The request was canceled due to the configured HttpClient.Timeout of 60 seconds elapsing.
And in the elasticsearch logs, I see this...
[2022-02-24T05:00:56,889][WARN ][r.suppressed ] [SERVERNAME] path: /prod-stacks/_search, params: {typed_keys=true, ignore_unavailable=true, index=prod-stacks}
org.elasticsearch.action.search.SearchPhaseExecutionException: all shards failed
at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseFailure(AbstractSearchAsyncAction.java:568) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:324) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseDone(AbstractSearchAsyncAction.java:603) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.onShardFailure(AbstractSearchAsyncAction.java:400) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.access$100(AbstractSearchAsyncAction.java:70) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.search.AbstractSearchAsyncAction$1.onFailure(AbstractSearchAsyncAction.java:258) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.search.SearchExecutionStatsCollector.onFailure(SearchExecutionStatsCollector.java:73) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.ActionListenerResponseHandler.handleException(ActionListenerResponseHandler.java:59) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.search.SearchTransportService$ConnectionCountingHandler.handleException(SearchTransportService.java:408) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.transport.TransportService$6.handleException(TransportService.java:640) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleException(TransportService.java:1181) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.transport.TransportService$DirectResponseChannel.processException(TransportService.java:1290) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1264) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:61) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.transport.TransportChannel.sendErrorResponse(TransportChannel.java:56) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.support.ChannelActionListener.onFailure(ChannelActionListener.java:51) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.ActionRunnable.onFailure(ActionRunnable.java:88) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:39) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:44) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:737) [elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-7.10.0.jar:7.10.0]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.elasticsearch.tasks.TaskCancelledException: cancelled
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:132) ~[elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.search.SearchService.executeFetchPhase(SearchService.java:462) ~[elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:438) ~[elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.search.SearchService.access$500(SearchService.java:141) ~[elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.search.SearchService$2.lambda$onResponse$0(SearchService.java:401) ~[elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58) ~[elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73) ~[elasticsearch-7.10.0.jar:7.10.0]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-7.10.0.jar:7.10.0]
... 6 more
We have 4 stacks that are marked as ignored. There are no stacks that are deleted, discarded, snoozed.
niemyjski commented
I've never seen a timeout like that, how many stacks do you have across the 5 million events? Is it better if you filter by one project? We'd recommend scaling out to a three or more node setup for all prod instances.
Edreih commented
Thanks Blake. We have approx. 32k stacks across 5m events. I'll take the recommendation and try scaling everything up.
Edreih commented
@niemyjski yes, thank you. Scaling has helped a lot. We are able to fetch and search individual messages quickly now.
However... the issue with fetching "Stacks" is persisting on our prod instance of Exceptionless.
It's odd because in our Exceptionless instance which holds dev/test data, we are able to fetch 34k stacks for all time just fine.
For our prod instance we cannot get it to return 39k stacks for all time. On this instance we do have some stacks marked as ignored, if that matters.
Digging further, I see this HTTP timeout message in the logs. If there is a way to increase the HttpClient.Timeout... do you recommend increasing this?
[11:25:35 INF] HTTP GET /api/v2/events?filter=(status:open+OR+status:regressed)&limit=15&mode=stack_new&offset=-300m responded 400 in 115649.3484 ms
[11:25:36 INF] Processing post: id=6e24250662084df3a132c91a74b7b810 path=q\151\151db1461a844ffb95966bbeafdf7c47.payload project=6196aedf9a732b1f3402256a ip=xxxx v=2 agent=exceptionless-js/1.6.3
[11:25:40 ERR] Error while searching
Original: [TaskCanceledException] The request was canceled due to the configured HttpClient.Timeout of 60 seconds elapsing.
[null] POST /prod-stacks/_search?typed_keys=true&ignore_unavailable=true
System.Threading.Tasks.TaskCanceledException: The request was canceled due to the configured HttpClient.Timeout of 60 seconds elapsing.
---> System.TimeoutException: The operation was canceled.
---> System.Threading.Tasks.TaskCanceledException: The operation was canceled.
---> System.IO.IOException: The response ended prematurely.
at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
--- End of inner exception stack trace ---
at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Net.Http.HttpClient.SendAsyncCore(HttpRequestMessage request, HttpCompletionOption completionOption, Boolean async, Boolean emitTelemetryStartStop, CancellationToken cancellationToken)
--- End of inner exception stack trace ---
--- End of inner exception stack trace ---
at System.Net.Http.HttpClient.SendAsyncCore(HttpRequestMessage request, HttpCompletionOption completionOption, Boolean async, Boolean emitTelemetryStartStop, CancellationToken cancellationToken)
at Elasticsearch.Net.HttpConnection.RequestAsync[TResponse](RequestData requestData, CancellationToken cancellationToken)
[11:25:40 ERR] An error has occurred. Please check your search filter.
System.ApplicationException: Original: ( - TaskCanceledException) The request was canceled due to the configured HttpClient.Timeout of 60 seconds elapsing.
niemyjski commented
Thanks for the update, If you turn on verbose logging you can see the queries being run and you could help identify the last query being run that caused the timeout. Also if you could provide a breakdown by stack status that would be a huge help (run a agg terms query on stack status).
Edreih commented
Hello,
I've collected more logs and ran the agg query. My findings are below... any help or next steps for troubleshooting are greatly appreciated.
With verbose logging enabled, I'm identifying this query causing the timeout:
GET /api/v2/events?filter=type:error+(status:open+OR+status:regressed)&limit=15&mode=stack_new&offset=-300m
If I put that same GET request into Postman, I am getting an error 400 Bad Request:
"An error has occurred. Please limit your search criteria."
Here is a dump (partial) of the Exceptionless log:
[12:28:25 ERR] An error has occurred. Please limit your search criteria.
Exceptionless.Core.Repositories.Base.DocumentLimitExceededException: Please limit your search criteria.
at Exceptionless.Core.Repositories.Queries.EventStackFilterQueryBuilder.BuildAsync[T](QueryBuilderContext`1 ctx) in /app/src/Exceptionless.Core/Repositories/Queries/EventStackFilterQuery.cs:line 119
at Foundatio.Repositories.Elasticsearch.Queries.Builders.ElasticQueryBuilder.BuildAsync[T](QueryBuilderContext`1 ctx)
at Foundatio.Repositories.Elasticsearch.Queries.Builders.ElasticQueryBuilderExtensions.BuildQueryAsync[T](IElasticQueryBuilder builder, IRepositoryQuery query, ICommandOptions options, SearchDescriptor`1 search)
at Foundatio.Repositories.Elasticsearch.Queries.Builders.ElasticQueryBuilderExtensions.ConfigureSearchAsync[T](IElasticQueryBuilder builder, IRepositoryQuery query, ICommandOptions options, SearchDescriptor`1 search)
at Foundatio.Repositories.Elasticsearch.ElasticReadOnlyRepositoryBase`1.ConfigureSearchDescriptorAsync(SearchDescriptor`1 search, IRepositoryQuery query, ICommandOptions options)
at Foundatio.Repositories.Elasticsearch.ElasticReadOnlyRepositoryBase`1.CountAsync(IRepositoryQuery query, ICommandOptions options)
at Exceptionless.Web.Controllers.EventController.GetUserCountByProjectIdsAsync(ICollection`1 stacks, AppFilter sf, DateTime utcStart, DateTime utcEnd) in /app/src/Exceptionless.Web/Controllers/EventController.cs:line 1253
at Exceptionless.Web.Controllers.EventController.GetStackSummariesAsync(List`1 stacks, IReadOnlyCollection`1 stackTerms, AppFilter sf, TimeInfo ti) in /app/src/Exceptionless.Web/Controllers/EventController.cs:line 1231
at Exceptionless.Web.Controllers.EventController.GetInternalAsync(AppFilter sf, TimeInfo ti, String filter, String sort, String mode, Int32 page, Int32 limit, String after, Boolean usesPremiumFeatures) in /app/src/Exceptionless.Web/Controllers/EventController.cs:line 323
[12:28:25 INF] Executed action method Exceptionless.Web.Controllers.EventController.GetAsync (Exceptionless.Web), returned result Microsoft.AspNetCore.Mvc.BadRequestObjectResult in 2067.8971ms.
[12:28:25 VRB] Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[12:28:25 VRB] Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[12:28:25 VRB] Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[12:28:25 VRB] Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[12:28:25 VRB] Action Filter: After executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Filters.ControllerActionFilter.
[12:28:25 VRB] Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
[12:28:25 VRB] Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
[12:28:25 VRB] Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ProducesAttribute.
[12:28:25 VRB] Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ProducesAttribute.
[12:28:25 VRB] Before executing action result Microsoft.AspNetCore.Mvc.BadRequestObjectResult.
[12:28:25 DBG] List of registered output formatters, in the following order: ["Microsoft.AspNetCore.Mvc.Formatters.HttpNoContentOutputFormatter", "Microsoft.AspNetCore.Mvc.Formatters.StringOutputFormatter", "Microsoft.AspNetCore.Mvc.Formatters.StreamOutputFormatter", "Microsoft.AspNetCore.Mvc.Formatters.NewtonsoftJsonOutputFormatter"]
[12:28:25 DBG] No information found on request to perform content negotiation.
[12:28:25 DBG] Attempting to select the first output formatter in the output formatters list which supports a content type from the explicitly specified content types '["application/json"]'.
[12:28:25 DBG] Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.NewtonsoftJsonOutputFormatter' and content type 'application/json' to write the response.
[12:28:25 VRB] Start save stack event counts.
[12:28:25 INF] Executing BadRequestObjectResult, writing value of type 'System.String'.
[12:28:25 VRB] Removed value from set with cache key: usage:occurrences
[12:28:25 VRB] RemoveAllAsync: Removing key: usage:occurrences:min:61f991af25ce232ba489704d
[12:28:25 VRB] RemoveAllAsync: Removing key: usage:occurrences:max:61f991af25ce232ba489704d
[12:28:25 VRB] After executing action result Microsoft.AspNetCore.Mvc.BadRequestObjectResult.
[12:28:25 VRB] Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ProducesAttribute.
[12:28:25 VRB] Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ProducesAttribute.
[12:28:25 VRB] Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
[12:28:25 VRB] Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
[12:28:25 INF] Executed action Exceptionless.Web.Controllers.EventController.GetAsync (Exceptionless.Web) in 2069.5756ms
[12:28:25 INF] Executed endpoint 'Exceptionless.Web.Controllers.EventController.GetAsync (Exceptionless.Web)'
[12:28:25 INF] HTTP GET /api/v2/events?filter=(status:open+OR+status:regressed)&limit=15&mode=stack_new&offset=-300m responded 400 in 2070.2941 ms
[12:28:25 VRB] DoMaintenance
[12:28:25 DBG] Removing expired cache entry lock:throttled:StackEventCountJob:637951445000000000
[12:28:25 INF] Request finished HTTP/2 GET https://exceptionlessprd.XXXX.com/api/v2/events?filter=(status:open+OR+status:regressed)&limit=15&mode=stack_new&offset=-300m - - - 400 59 application/json;+charset=utf-8 2070.5063ms
[12:28:25 VRB] RemoveAsync: Removing key: Stack:61f991af25ce232ba489704d
[12:28:25 VRB] Schedule delayed message: Foundatio.Repositories.Models.EntityChanged, Foundatio.Repositories (1500ms)
[12:28:25 VRB] Increment event count 1 for organization:6196aedf9a732b1f34022569 project:6196aedf9a732b1f3402256a stack:61f991af25ce232ba489704d with Min Date:08/03/2022 17:28:23 Max Date:08/03/2022 17:28:23
[12:28:25 VRB] Finished save stack event counts.
[12:28:25 DBG] Job run StackEventCountJob succeeded.
[12:28:25 VRB] Queue OnMessage prod-EventPost: 03aaff831e2544d1918feef51f1b8fae
[12:28:25 VRB] Waited for dequeue: 00:00:00.4077993
[12:28:25 VRB] List value: <null>
[12:28:25 VRB] Waiting to dequeue item...
[12:28:26 VRB] Sending delayed message scheduled for 2022-08-03T17:28:26.0502531Z for type Foundatio.Repositories.Models.EntityChanged
[12:28:26 VRB] Message Publish: Foundatio.Repositories.Models.EntityChanged, Foundatio.Repositories
[12:28:26 VRB] OnMessage(prod-messages)
[12:28:26 VRB] Found 1 subscribers for message type Foundatio.Repositories.Models.EntityChanged, Foundatio.Repositories.
[12:28:26 VRB] Done enqueueing message to 1 subscribers for message type Foundatio.Repositories.Models.EntityChanged, Foundatio.Repositories.
[12:28:26 VRB] Calling subscriber action: 734d5509-a289-4f4d-94aa-8c388dc06dce
[12:28:26 VRB] Sending PersistentEvent message to organization: 6196aedf9a732b1f34022569
[12:28:26 VRB] Finished calling subscriber action: 734d5509-a289-4f4d-94aa-8c388dc06dce
[12:28:26 VRB] Sending delayed message scheduled for 2022-08-03T17:28:26.0705120Z for type Foundatio.Repositories.Models.EntityChanged
[12:28:26 VRB] Message Publish: Foundatio.Repositories.Models.EntityChanged, Foundatio.Repositories
[12:28:26 VRB] OnMessage(prod-messages)
[12:28:26 VRB] Found 1 subscribers for message type Foundatio.Repositories.Models.EntityChanged, Foundatio.Repositories.
[12:28:26 VRB] Done enqueueing message to 1 subscribers for message type Foundatio.Repositories.Models.EntityChanged, Foundatio.Repositories.
[12:28:26 VRB] Calling subscriber action: 734d5509-a289-4f4d-94aa-8c388dc06dce
[12:28:26 VRB] Sending PersistentEvent message to organization: 6196aedf9a732b1f34022569
[12:28:26 VRB] Finished calling subscriber action: 734d5509-a289-4f4d-94aa-8c388dc06dce
[12:28:26 INF] Request starting HTTP/2 GET https://exceptionlessprd.XXXX.com/api/v2/events/count?aggregations=date:(date%5E-300m+cardinality:stack+sum:count~1)+cardinality:stack+terms:(first+@include:true)+sum:count~1&filter=(status:open+OR+status:regressed)&offset=-300m - -
[12:28:26 VRB] All hosts are allowed.
[12:28:26 DBG] The request path /api/v2/events/count does not match a supported file type
[12:28:26 DBG] The request path /api/v2/events/count does not match a supported file type
[12:28:26 DBG] 3 candidate(s) found for the request path '/api/v2/events/count'
[12:28:26 DBG] Endpoint 'Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web)' with route pattern 'api/v2/events/count' is valid for the request path '/api/v2/events/count'
[12:28:26 DBG] Endpoint 'Exceptionless.Web.Controllers.EventController.GetAsync (Exceptionless.Web)' with route pattern 'api/v2/events/{id:objectid}' was rejected by constraint 'id':'Exceptionless.Web.Utility.ObjectIdRouteConstraint' with value 'count' for the request path '/api/v2/events/count'
[12:28:26 DBG] Endpoint 'Exceptionless.Web.Controllers.EventController.GetAsync (Exceptionless.Web)' with route pattern 'api/v2/events/{id:objectid}' is not valid for the request path '/api/v2/events/count'
[12:28:26 DBG] Endpoint 'Fallback {**slug:nonfile}' with route pattern '{**slug:nonfile}' is valid for the request path '/api/v2/events/count'
[12:28:26 DBG] Request matched endpoint 'Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web)'
[12:28:26 VRB] Cache hit: type=Token key=q7DfOyg9bfi03R5sE0ANzBtA6tTGjcZbG4lreFh1
[12:28:26 VRB] Cache hit: type=Token key=q7DfOyg9bfi03R5sE0ANzBtA6tTGjcZbG4lreFh1
[12:28:26 VRB] Cache hit: type=User key=6196ad319a732b1f34022565
[12:28:26 VRB] Cache hit: type=User key=6196ad319a732b1f34022565
[12:28:26 DBG] AuthenticationScheme: ApiKey was successfully authenticated.
[12:28:26 INF] Authorization was successful.
[12:28:26 DBG] Static files was skipped as the request already matched an endpoint.
[12:28:26 VRB] DoMaintenance
[12:28:26 INF] Executing endpoint 'Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web)'
[12:28:26 INF] Route matched with {action = "GetCount", controller = "Event"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.ActionResult`1[Foundatio.Repositories.Models.CountResult]] GetCountAsync(System.String, System.String, System.String, System.String) on controller Exceptionless.Web.Controllers.EventController (Exceptionless.Web).
[12:28:26 DBG] Execution plan of authorization filters (in the following order): ["None"]
[12:28:26 DBG] Execution plan of resource filters (in the following order): ["None"]
[12:28:26 DBG] Execution plan of action filters (in the following order): ["Microsoft.AspNetCore.Mvc.Filters.ControllerActionFilter (Order: -2147483648)", "Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000)", "Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter (Order: -2000)"]
[12:28:26 DBG] Execution plan of exception filters (in the following order): ["Exceptionless.Web.Utility.Handlers.ApiExceptionFilter (Order: 0)"]
[12:28:26 DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter (Order: -2000)", "Microsoft.AspNetCore.Mvc.ProducesAttribute (Order: 0)"]
[12:28:26 DBG] Executing controller factory for controller Exceptionless.Web.Controllers.EventController (Exceptionless.Web)
[12:28:26 DBG] Executed controller factory for controller Exceptionless.Web.Controllers.EventController (Exceptionless.Web)
[12:28:26 DBG] Attempting to bind parameter 'filter' of type 'System.String' ...
[12:28:26 DBG] Attempting to bind parameter 'filter' of type 'System.String' using the name 'filter' in request data ...
[12:28:26 DBG] Done attempting to bind parameter 'filter' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'filter' of type 'System.String'.
[12:28:26 DBG] Attempting to validate the bound parameter 'filter' of type 'System.String' ...
[12:28:26 DBG] Done attempting to validate the bound parameter 'filter' of type 'System.String'.
[12:28:26 DBG] Attempting to bind parameter 'aggregations' of type 'System.String' ...
[12:28:26 DBG] Attempting to bind parameter 'aggregations' of type 'System.String' using the name 'aggregations' in request data ...
[12:28:26 DBG] Done attempting to bind parameter 'aggregations' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'aggregations' of type 'System.String'.
[12:28:26 DBG] Attempting to validate the bound parameter 'aggregations' of type 'System.String' ...
[12:28:26 DBG] Done attempting to validate the bound parameter 'aggregations' of type 'System.String'.
[12:28:26 DBG] Attempting to bind parameter 'time' of type 'System.String' ...
[12:28:26 DBG] Attempting to bind parameter 'time' of type 'System.String' using the name '' in request data ...
[12:28:26 DBG] Could not find a value in the request with name '' for binding parameter 'time' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'time' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'time' of type 'System.String'.
[12:28:26 DBG] Attempting to validate the bound parameter 'time' of type 'System.String' ...
[12:28:26 DBG] Done attempting to validate the bound parameter 'time' of type 'System.String'.
[12:28:26 DBG] Attempting to bind parameter 'offset' of type 'System.String' ...
[12:28:26 DBG] Attempting to bind parameter 'offset' of type 'System.String' using the name 'offset' in request data ...
[12:28:26 DBG] Done attempting to bind parameter 'offset' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'offset' of type 'System.String'.
[12:28:26 DBG] Attempting to validate the bound parameter 'offset' of type 'System.String' ...
[12:28:26 DBG] Done attempting to validate the bound parameter 'offset' of type 'System.String'.
[12:28:26 VRB] Action Filter: Before executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Filters.ControllerActionFilter.
[12:28:26 VRB] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[12:28:26 VRB] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[12:28:26 VRB] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[12:28:26 VRB] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[12:28:26 INF] Executing action method Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web) - Validation state: Valid
[12:28:26 VRB] Executing action method Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web) with arguments (["(status:open OR status:regressed)", "date:(date^-300m cardinality:stack sum:count~1) cardinality:stack terms:(first @include:true) sum:count~1", "", "-300m"])
[12:28:26 VRB] Cache hit: type=Organization key=6196aedf9a732b1f34022569, 6196ae6c9a732b1f34022567
[12:28:26 VRB] Cached mapping (not found): status=<null>
[12:28:26 VRB] Cached mapping (not found): status=<null>
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached mapping (not found): @include=<null>
[12:28:26 VRB] Cached mapping (not found): @include=<null>
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Stack filter: (status:open OR status:regressed) Invert Success: True Inverted: (is_deleted:true OR (NOT (status:open OR status:regressed)))
[12:28:26 VRB] Cached mapping: status=status:keyword
[12:28:26 VRB] Cached mapping: status=status:keyword
[12:28:26 VRB] Cached mapping: is_deleted=is_deleted:boolean
[12:28:26 VRB] [200] POST /prod-stacks/_search?typed_keys=true&ignore_unavailable=true
[12:28:26 VRB] Setting stack filter with 7 ids
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached mapping (not found): @include=<null>
[12:28:26 VRB] Cached mapping (not found): @include=<null>
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 INF] Request starting HTTP/2 GET https://exceptionlessprd.XXXX.com/api/v2/events/count?aggregations=date:(date%5E-300m+cardinality:stack+sum:count~1)+cardinality:stack+terms:(first+@include:true)+sum:count~1&filter=type:error+(status:open+OR+status:regressed)&offset=-300m - -
[12:28:26 VRB] All hosts are allowed.
[12:28:26 DBG] The request path /api/v2/events/count does not match a supported file type
[12:28:26 DBG] The request path /api/v2/events/count does not match a supported file type
[12:28:26 DBG] 3 candidate(s) found for the request path '/api/v2/events/count'
[12:28:26 DBG] Endpoint 'Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web)' with route pattern 'api/v2/events/count' is valid for the request path '/api/v2/events/count'
[12:28:26 DBG] Endpoint 'Exceptionless.Web.Controllers.EventController.GetAsync (Exceptionless.Web)' with route pattern 'api/v2/events/{id:objectid}' was rejected by constraint 'id':'Exceptionless.Web.Utility.ObjectIdRouteConstraint' with value 'count' for the request path '/api/v2/events/count'
[12:28:26 DBG] Endpoint 'Exceptionless.Web.Controllers.EventController.GetAsync (Exceptionless.Web)' with route pattern 'api/v2/events/{id:objectid}' is not valid for the request path '/api/v2/events/count'
[12:28:26 DBG] Endpoint 'Fallback {**slug:nonfile}' with route pattern '{**slug:nonfile}' is valid for the request path '/api/v2/events/count'
[12:28:26 DBG] Request matched endpoint 'Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web)'
[12:28:26 VRB] Cache hit: type=Token key=q7DfOyg9bfi03R5sE0ANzBtA6tTGjcZbG4lreFh1
[12:28:26 VRB] Cache hit: type=Token key=q7DfOyg9bfi03R5sE0ANzBtA6tTGjcZbG4lreFh1
[12:28:26 VRB] Cache hit: type=User key=6196ad319a732b1f34022565
[12:28:26 VRB] Cache hit: type=User key=6196ad319a732b1f34022565
[12:28:26 DBG] AuthenticationScheme: ApiKey was successfully authenticated.
[12:28:26 INF] Authorization was successful.
[12:28:26 DBG] Static files was skipped as the request already matched an endpoint.
[12:28:26 INF] Executing endpoint 'Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web)'
[12:28:26 INF] Route matched with {action = "GetCount", controller = "Event"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.ActionResult`1[Foundatio.Repositories.Models.CountResult]] GetCountAsync(System.String, System.String, System.String, System.String) on controller Exceptionless.Web.Controllers.EventController (Exceptionless.Web).
[12:28:26 DBG] Execution plan of authorization filters (in the following order): ["None"]
[12:28:26 DBG] Execution plan of resource filters (in the following order): ["None"]
[12:28:26 DBG] Execution plan of action filters (in the following order): ["Microsoft.AspNetCore.Mvc.Filters.ControllerActionFilter (Order: -2147483648)", "Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000)", "Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter (Order: -2000)"]
[12:28:26 DBG] Execution plan of exception filters (in the following order): ["Exceptionless.Web.Utility.Handlers.ApiExceptionFilter (Order: 0)"]
[12:28:26 DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter (Order: -2000)", "Microsoft.AspNetCore.Mvc.ProducesAttribute (Order: 0)"]
[12:28:26 DBG] Executing controller factory for controller Exceptionless.Web.Controllers.EventController (Exceptionless.Web)
[12:28:26 DBG] Executed controller factory for controller Exceptionless.Web.Controllers.EventController (Exceptionless.Web)
[12:28:26 DBG] Attempting to bind parameter 'filter' of type 'System.String' ...
[12:28:26 DBG] Attempting to bind parameter 'filter' of type 'System.String' using the name 'filter' in request data ...
[12:28:26 DBG] Done attempting to bind parameter 'filter' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'filter' of type 'System.String'.
[12:28:26 DBG] Attempting to validate the bound parameter 'filter' of type 'System.String' ...
[12:28:26 DBG] Done attempting to validate the bound parameter 'filter' of type 'System.String'.
[12:28:26 DBG] Attempting to bind parameter 'aggregations' of type 'System.String' ...
[12:28:26 DBG] Attempting to bind parameter 'aggregations' of type 'System.String' using the name 'aggregations' in request data ...
[12:28:26 DBG] Done attempting to bind parameter 'aggregations' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'aggregations' of type 'System.String'.
[12:28:26 DBG] Attempting to validate the bound parameter 'aggregations' of type 'System.String' ...
[12:28:26 DBG] Done attempting to validate the bound parameter 'aggregations' of type 'System.String'.
[12:28:26 DBG] Attempting to bind parameter 'time' of type 'System.String' ...
[12:28:26 DBG] Attempting to bind parameter 'time' of type 'System.String' using the name '' in request data ...
[12:28:26 DBG] Could not find a value in the request with name '' for binding parameter 'time' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'time' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'time' of type 'System.String'.
[12:28:26 DBG] Attempting to validate the bound parameter 'time' of type 'System.String' ...
[12:28:26 DBG] Done attempting to validate the bound parameter 'time' of type 'System.String'.
[12:28:26 DBG] Attempting to bind parameter 'offset' of type 'System.String' ...
[12:28:26 DBG] Attempting to bind parameter 'offset' of type 'System.String' using the name 'offset' in request data ...
[12:28:26 DBG] Done attempting to bind parameter 'offset' of type 'System.String'.
[12:28:26 DBG] Done attempting to bind parameter 'offset' of type 'System.String'.
[12:28:26 DBG] Attempting to validate the bound parameter 'offset' of type 'System.String' ...
[12:28:26 DBG] Done attempting to validate the bound parameter 'offset' of type 'System.String'.
[12:28:26 VRB] Action Filter: Before executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Filters.ControllerActionFilter.
[12:28:26 VRB] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[12:28:26 VRB] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[12:28:26 VRB] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[12:28:26 VRB] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[12:28:26 INF] Executing action method Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web) - Validation state: Valid
[12:28:26 VRB] Executing action method Exceptionless.Web.Controllers.EventController.GetCountAsync (Exceptionless.Web) with arguments (["type:error (status:open OR status:regressed)", "date:(date^-300m cardinality:stack sum:count~1) cardinality:stack terms:(first @include:true) sum:count~1", "", "-300m"])
[12:28:26 VRB] Cache hit: type=Organization key=6196aedf9a732b1f34022569, 6196ae6c9a732b1f34022567
[12:28:26 VRB] Cached mapping (not found): status=<null>
[12:28:26 VRB] Cached mapping (not found): status=<null>
[12:28:26 VRB] Cached mapping: type=type:text
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached mapping: date=date:date
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached alias mapping: first=first:alias
[12:28:26 VRB] Cached mapping: is_first_occurrence=is_first_occurrence:boolean
[12:28:26 VRB] Cached mapping (not found): @include=<null>
[12:28:26 VRB] Cached mapping (not found): @include=<null>
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached mapping: count=count:integer
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Cached alias mapping: stack=stack:alias
[12:28:26 VRB] Cached mapping: stack_id=stack_id:keyword
[12:28:26 VRB] Stack filter: type:error (status:open OR status:regressed) Invert Success: True Inverted: (is_deleted:true OR (type:error NOT (status:open OR status:regressed)))
[12:28:26 VRB] Cached mapping: status=status:keyword
[12:28:26 VRB] Cached mapping: status=status:keyword
[12:28:26 VRB] Cached mapping: type=type:keyword
[12:28:26 VRB] Cached mapping: is_deleted=is_deleted:boolean
And here is the breakdown of stack status (agg query):
GET http://{{elasticsearch_server}}/*/_search
Body:
{
"aggs": {
"my-agg-name": {
"terms": {
"field": "status"
}
}
}
}
It returns:
"aggregations": {
"my-agg-name": {
"doc_count_error_upper_bound": 0,
"sum_other_doc_count": 0,
"buckets": [
{
"key": "open",
"doc_count": 118003
},
{
"key": "ignored",
"doc_count": 7
},
{
"key": "fixed",
"doc_count": 1
}
]
}
}
ejsmith commented
@Edreih just to confirm. Are you running into this issue on the latest version of the code? I've made changes recently that should be improving the stack limit issue. In general though, we have to do application side joins from events to stacks since Elasticsearch doesn't support joins. So there is a limit to how wide open your event filter criteria can be with regards to how many related stacks there are. In the current code, that limit is 20,000 stacks. If you are still hitting that limit then I'd suggest figuring out a way to narrow down your filter maybe by time or maybe by the number of projects that are included?