datalust / seq-tickets

Issues, design discussions and feature roadmap for the Seq log server
https://datalust.co/seq
98 stars 5 forks source link

Unhandled error when retrieving events in a particular date range #2290

Closed jorgenfries closed 1 month ago

jorgenfries commented 1 month ago

Describe the bug

When we choose a specific minute in the timepicker we get Could not load events An unhandled error occurred while serving the request (token: 89680a5599504908aa55c31397370266).

To Reproduce Steps to reproduce the behavior:

  1. We can reproduce it, however it is probably dependent on our dataset
  2. In this case we choose endtime 18:27:00 and we can consistently reproduce the error: image
  3. If we choose another endtime(eg. 18:28:00) it works fine, and we get data including events during the 18:27:00 minute image

Expected behavior Expect SEQ to load the logs without errors

Screenshots See above

Environment (please complete the following information):

Additional context Add any other context about the problem here. SEQ service logs shows the following entry:

{ "@t": "2024-10-08T07:41:22.9647485Z", "@sp": "b6c055078703058a", "@tr": "b089b1fa571358c12ed9faf124191bf0", "@mt": "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms", "@r": [ "7.7254" ], "@l": "Error", "@x": "System.Collections.Generic.KeyNotFoundException: The key was not found in the property set.\r\n at Seq.Engine.Structured.PropertySchema.GetValue(Object[] values, String key)\r\n at Seq.Engine.Flat.EventEncoder.Decode(Key key, IReadOnlyDictionary2 value)\r\n at Seq.Engine.Queries.DataStore.Get(EventStoreRange range, RetrievalStatistics statistics, CancellationToken cancel)+MoveNext()\r\n at System.Linq.Enumerable.EnumerablePartition1.ToArray()\r\n at Seq.Engine.Queries.DataStore.Search(Int32 count, DateTimeRangeBounds bounds, String filter, IndexExpression indexExpression, Nullable1 startFrom, Nullable1 startAfter, Nullable1 shortCircuitAfter, TraversalDirection direction, Boolean background, CancellationToken& cancel)\r\n at Seq.Server.Web.Api.EventsController.<>c__DisplayClass20_0.<SearchEvents>b__1(CancellationToken ct)\r\n at Seq.Engine.Workers.WorkerPool.<>c__DisplayClass7_01.<Run>g__DoWork|0()\r\n at System.Threading.Tasks.Task1.InnerInvoke()\r\n at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)\r\n--- End of stack trace from previous location ---\r\n at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)\r\n at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)\r\n--- End of stack trace from previous location ---\r\n at Seq.Server.Web.Api.EventsController.SearchEvents(IndexedFilter indexedFilter)\r\n at Seq.Server.Web.Api.EventsController.InSignal(EvaluationContext evaluationContext, Boolean excludeStats)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(ActionContext actionContext, IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask1 actionResultValueTask)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|25_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)\r\n at Microsoft.AspNetCore.RateLimiting.RateLimitingMiddleware.InvokeInternal(HttpContext context, EnableRateLimitingAttribute enableRateLimitingAttribute)\r\n at Seq.Server.Web.Middleware.WebSocketAcceptMiddleware.Invoke(HttpContext context)\r\n at Seq.Server.Web.Middleware.RequestAuthenticationMiddleware.Invoke(HttpContext httpContext)\r\n at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)\r\n at Seq.Server.Web.Middleware.HstsMiddleware.Invoke(HttpContext context)\r\n at Seq.Server.Web.Middleware.ServerStatusMiddleware.Invoke(HttpContext context)\r\n at Seq.Server.Web.Middleware.UniversalHeadersMiddleware.Invoke(HttpContext context)\r\n at Seq.Server.Web.Middleware.RequestCompletionMiddleware.Invoke(HttpContext httpContext)", "RequestMethod": "POST", "RequestPath": "/api/events/signal", "StatusCode": 500, "Elapsed": 7.7254, "ErrorToken": "d21db117361d43b2ae851e862f239312", "RequestProtocol": "HTTP/2", "RequestHost": "**REMOVED**", "RequestHeaders": { "User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:131.0) Gecko/20100101 Firefox/131.0", "Content-Type": "application/json;charset=utf-8", "Content-Length": "225" }, "SourceContext": "Seq.Server.Web.Middleware.RequestCompletionMiddleware", "RequestId": "0HN6MC3FR37HO:00001D07", "ConnectionId": "0HN6MC3FR37HO" }

KodrAus commented 1 month ago

Thanks for the report @jorgenfries. It looks like there's a specific event in that minute that's triggering this. We'll take a look and see what could be triggering it.

nblumhardt commented 1 month ago

Hi @jorgenfries; we believe we have a fix for this, which we'll roll into the next patch. It may be a little while before that's ready for a full public release - would you like us to send a build privately that you can apply to the affected server in the meantime? If so, mailing support@datalust.co is the easiest way for us to get this to you.

Thanks again for the report!

jorgenfries commented 1 month ago

Thanks @nblumhardt

It is not breaking for us, so we have no need for an urgent patch. However if you want us to verify your patch is working, we can apply it and test it out.

nblumhardt commented 1 month ago

Thanks for the kind offer, @jorgenfries. We're considering shipping a public patch with a few fixes fairly soon, I'll loop back here when we have a timeline, it might be easiest just to apply the patch and follow up from there if any problems remain (we're confident that the fix does address at least one bug on this code path, even if it's not precisely the same one).

nblumhardt commented 4 weeks ago

Hi @jorgenfries; 2024.3.12680 should resolve this one; if you still run into any trouble on the new version, please let us know. Thanks again for the report!