search

rollbar / Rollbar.NET

Rollbar for .NET
https://docs.rollbar.com/docs/dotnet
MIT License
66 stars 44 forks source link

Rollbar does not work with ASP NET Core 3.1 API calls with complex payloads. #524

Closed opolo closed 3 years ago

opolo commented 4 years ago

Describe the bug When I add app.UseRollbarMiddleware(); to Startup.cs, all calls to APIs with endpoints containing complex data-type parameters fails. If I remove the app.UseRollbarMiddleware(); they work again. GET calls with or without simple data types work, and so does POST calls without parameters.

In other words, calling the following API action methods:

Succeeds: GET -> public async Task<ActionResult> TestAsync() GET -> public async Task<ActionResult> TestAsync(int numberParam) POST -> public async Task<ActionResult> TestAsync()

Fails: POST -> public async Task<ActionResult> TestAsync([FromBody] TestObjectClass testObjectParam)

TestObjectClass class is just a DTO with no methods apart from the constructor.

The error thrown is: System.InvalidOperationException: 'Synchronous operations are disallowed. Call ReadAsync or set AllowSynchronousIO to true instead.'

The stacktrace is:

Rollbar.NetCore.AspNet.RollbarMiddlewareException: The included internal exception processed by the Rollbar middleware
 ---> System.InvalidOperationException: Synchronous operations are disallowed. Call ReadAsync or set AllowSynchronousIO to true instead.
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   at Microsoft.AspNetCore.WebUtilities.HttpRequestStreamReader.ReadIntoBuffer()
   at Microsoft.AspNetCore.WebUtilities.HttpRequestStreamReader.Read(Char[] buffer, Int32 index, Int32 count)
   at Newtonsoft.Json.JsonTextReader.ReadData(Boolean append, Int32 charsRequired)
   at Newtonsoft.Json.JsonTextReader.ParseValue()
   at Newtonsoft.Json.JsonReader.ReadAndMoveToContent()
   at Newtonsoft.Json.JsonReader.ReadForType(JsonContract contract, Boolean hasConverter)
   at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.Deserialize(JsonReader reader, Type objectType, Boolean checkAdditionalContent)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Formatters.NewtonsoftJsonInputFormatter.ReadRequestBodyAsync(InputFormatterContext context, Encoding encoding)
   at Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder.BindModelAsync(ModelBindingContext bindingContext)
   at Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder.BindModelAsync(ActionContext actionContext, IModelBinder modelBinder, IValueProvider valueProvider, ParameterDescriptor parameter, ModelMetadata metadata, Object value)
   at Microsoft.AspNetCore.Mvc.Controllers.ControllerBinderDelegateProvider.<>c__DisplayClass0_0.<<CreateBinderDelegate>g__Bind|0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Serilog.AspNetCore.RequestLoggingMiddleware.Invoke(HttpContext httpContext)
   at Rollbar.NetCore.AspNet.RollbarMiddleware.Invoke(HttpContext context)
   --- End of inner exception stack trace ---
   at Rollbar.NetCore.AspNet.RollbarMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)

HEADERS
=======
Connection: keep-alive
Content-Type: application/json-patch+json
Accept: text/plain
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9,da;q=0.8
Cookie: _ga=GA1.1.1732012640.1557827007; hubspotutk=0d1bc18646dd07bc15a833acf29374c9; MCPopupClosed=yes; _hjDonePolls=412532,421760; _hjid=cba2dbc8-210d-4030-9633-3f516ef405df; mp_a7e73659444814363443161e8485cace_mixpanel=%7B%22distinct_id%22%3A%20%2216e36b00f8820b-0ef6b055ebffb2-b363e65-384000-16e36b00f89430%22%2C%22%24device_id%22%3A%20%2216e36b00f8820b-0ef6b055ebffb2-b363e65-384000-16e36b00f89430%22%2C%22%24initial_referrer%22%3A%20%22http%3A%2F%2Flocalhost%3A3000%2F%22%2C%22%24initial_referring_domain%22%3A%20%22localhost%3A3000%22%7D; _ga_8SG20C7DKN=GS1.1.1575807813.8.1.1575809170.0; consent-is={"answered":true,"dnt":false,"gdpr":true,"stats":false,"ignore":3,"token":"","categories":[{"cid":11642,"id":"required","value":true},{"cid":11643,"id":"analytics","value":true},{"cid":11644,"id":"marketing","value":true}]}; mp_c8264d72f1bf9ccbd46506980180516d_mixpanel=%7B%22distinct_id%22%3A%20%2216dac235dd6171-0e26b8b4563782-67e1b3f-384000-16dac235dd73e3%22%2C%22%24device_id%22%3A%20%2216dac235dd6171-0e26b8b4563782-67e1b3f-384000-16dac235dd73e3%22%2C%22%24initial_referrer%22%3A%20%22http%3A%2F%2Flocalhost%3A3000%2Fcompany-profiles%2F99%22%2C%22%24initial_referring_domain%22%3A%20%22localhost%3A3000%22%7D; __hstc=181257784.0d1bc18646dd07bc15a833acf29374c9.1558429155146.1580137745527.1581509728026.275
Host: localhost:24201
Referer: http://localhost:24201/swagger/index.html
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.129 Safari/537.36
Origin: http://localhost:24201
Content-Length: 18
Sec-Fetch-Site: same-origin
Sec-Fetch-Mode: cors
Sec-Fetch-Dest: empty

Expected behavior No errors and 200 OK response.

Rollbar Client - Rollbar.NET Hosting Environment (please complete the following information):

Additional context Second critical error in two days after adding Rollbar :( First in Azure functions, now in ASP.NET Core. Does make us a bit nervous with the .NET compatibility, although we probably are just very unlucky... We will try to look into the error from an ASP.NET Core 3 point of view from our end. Perhaps some settings can be changed to avoid this issue, although we would hope for the changes not to be permanent modifications to our setup to avoid too many band-aids in the backend that needs maintenance during updates. We will share, if we learn something here.... Probably will not happen before tomorrow, as its night here in EU (just finished debugging of this... Was pretty hard to find the reason for the error due to an initial obscure stack trace not pointing us in the right direction... That was due to our bad exception middleware though, so lesson learned there the hard way!).

opolo commented 4 years ago

Found a temporary solution that does come with caveats though (see comments if anyone decides to use it): https://github.com/dotnet/aspnetcore/issues/7644

This blog post linked to the above issue, so credit where credit is due: https://khalidabuhakmeh.com/dotnet-core-3-dot-0-allowsynchronousio-workaround

Hope it can help someone else for now, if they face the issue :)

akornich commented 4 years ago

@opolo , thanks for reporting the issue and the workaround. From the test cases and the trace stacks, it looks like ASP.NET Core had some changes in its internal HTTP request body reading API implementation. We do have a rewind of the request body stream implemented as part of a workaround to keep APS.NET Core happy when it further processes the same request body. I suspect we might have to adjust the implementation of it based on the new ASP.NET Core 3.0 behavior. Also, I noticed you already use the Serilog logging framework within your application (and its middleware). In this case, I would recommend you try using our plug-in component for Serilog (basically implementing Rollbar Sink for Serilog) instead of the Rollbar middleware. The component distributed via Nuget as Rollbar.PlugIns.Serilog package. This way you get one less middleware in your HTTP request processing pipeline but will be able to capture every Serilog logging event as a Rollbar payload.

opolo commented 3 years ago

Hi!

I have to follow up on this: Any news on this, a short year after?

I'm to setup error tracking in one of my new client's backend APIs and want to suggest Rollbar - I am not keen on adding "hacks with caveats" in their BE though, as I am not that familiar with all their logic and thus the impact of this. Some enlightment on whether this still have to be added with .NET Core 3.1 would help in the decision.

Thanks! :)

akornich commented 3 years ago

Hi @opolo, I assumed the allow-sync-io-workaround resolved the problem for you. Before I start looking into it, may I reiterate your use case? You are planning to use RollbarMiddleware with the Asp.Net Core 3.1. Correct? Any plans on using Rollbar.NET with any other logging framework like Serilog?

One more question regarding the original stack trace you posted here to start this issue report: did you get an application crash with that exception/stack OR that is part of an exception reported by Rollbar.NET to your project dashboard on rollbar.com? Here is the way I would interpret the call stack: you use both Serilog's middleware and Rollbar middleware components. The Serilog middleware is an inner middleware as compare to the Rollbar middleware, hence, the Rollbar middleware would capture any unhandled exception (within its inner middleware chain) that reaches it. So, it (RollbarMiddleware) does seem to serve its purpose by capturing the exceptions triggered within the calls starting from the following call:

at Serilog.AspNetCore.RequestLoggingMiddleware.Invoke(HttpContext httpContext)

Does it seem correct from your perspective?

akornich commented 3 years ago

@opolo, please, try our v5.0.4-beta release of the SDK and see if that works better for you. It is a new major release, so some changes to the client code are expected (mainly around manually built configuration objects and explicit initialization of Rollbar infrastructure). v5 specific documentation is available here.

opolo commented 3 years ago

Hi Akornich! Thanks for letting me know! I will give it a spin in one of our services and see what happens :D NB. On vacation atm, so might take a couple of weeks. Aka. don't let me hold your new release captured till then by waiting for a response from me :)

akornich commented 3 years ago

@opolo , thanks for the update! Yes, the new release is code-complete at this point, we are clearing all the build warnings while waiting for feedback from the beta users (in case we need to make any changes to the SDK public APIs based on the feedback).

brianr commented 3 years ago

Optimistically moving this to closed. @opolo let us know if this should be reopened; thanks!