Apm-agent-dotnet: Possible Bug: Cannot access a disposed object named 'FileBufferingReadStream'

[rcanpahali]

Describe the bug
Application throws "Cannot access a disposed object. Object name: 'FileBufferingReadStream'." exception at unpredictable times.

To Reproduce
Steps to reproduce the behavior: It occurs randomly.

Debug logs

Exception:

{
  "StackTraceString": "   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.ThrowIfDisposed()\r\n   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.set_Position(Int64 value)\r\n   at Elastic.Apm.AspNetCore.Extensions.HttpRequestExtensions.ExtractRequestBodyAsync(HttpRequest request, IApmLogger logger)",
  "Message": "Cannot access a disposed object.\r\nObject name: 'FileBufferingReadStream'.",
  "HResult": -2146232798,
  "RemoteStackTraceString": null,
  "ClassName": "System.ObjectDisposedException",
  "RemoteStackIndex": 0,
  "Depth": 0,
  "Source": "Microsoft.AspNetCore.WebUtilities",
  "HelpURL": null
}

Exception Source:

 at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.ThrowIfDisposed()
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.set_Position(Int64 value)
   at Elastic.Apm.AspNetCore.Extensions.HttpRequestExtensions.ExtractRequestBodyAsync(HttpRequest request, IApmLogger logger)

Expanded Result:

{
  "_index": "log-westcore-2019.12.23",
  "_type": "logevent",
  "_id": "43_7e85261f-623c-4051-9d25-3db60bbe1cd2",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2019-12-23T11:13:52.2979696+02:00",
    "level": "Error",
    "message": "{\"ApmMiddleware\"} Error reading request body",
    "fields": {
      "RequestPath": "/api/###/###/###/###",
      "ParentId": "",
      "ExceptionDetail": {
        "Type": "System.ObjectDisposedException",
        "Message": "Cannot access a disposed object.\r\nObject name: 'FileBufferingReadStream'.",
        "HResult": -2146232798,
        "Source": "Microsoft.AspNetCore.WebUtilities",
        "ObjectName": "FileBufferingReadStream"
      },
      "UserName": "\"westapi\"",
      "ApplicationName": "WestCore.Api",
      "Scope": "ApmMiddleware",
      "RequestId": "80000536-0003-f000-b63f-84710c7967bb",
      "MachineName": "\"####\"",
      "TraceId": "a756254b-428e056b2a0942f8",
      "Environment": "Production",
      "SourceContext": "Elastic.Apm",
      "SpanId": "|a756254b-428e056b2a0942f8."
    },
    "messageTemplate": "{{{Scope}}} Error reading request body",
    "exceptions": [
      {
        "StackTraceString": "   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.ThrowIfDisposed()\r\n   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.set_Position(Int64 value)\r\n   at Elastic.Apm.AspNetCore.Extensions.HttpRequestExtensions.ExtractRequestBodyAsync(HttpRequest request, IApmLogger logger)",
        "Message": "Cannot access a disposed object.\r\nObject name: 'FileBufferingReadStream'.",
        "HResult": -2146232798,
        "RemoteStackTraceString": null,
        "ClassName": "System.ObjectDisposedException",
        "RemoteStackIndex": 0,
        "Depth": 0,
        "Source": "Microsoft.AspNetCore.WebUtilities",
        "HelpURL": null
      }
    ]
  },
  "fields": {
    "@timestamp": [
      "2019-12-23T09:13:52.297Z"
    ]
  },
  "highlight": {
    "fields.RequestId": [
      "@kibana-highlighted-field@80000536@/kibana-highlighted-field@-@kibana-highlighted-field@0003@/kibana-highlighted-field@-@kibana-highlighted-field@f000@/kibana-highlighted-field@-@kibana-highlighted-field@b63f@/kibana-highlighted-field@-@kibana-highlighted-field@84710c7967bb@/kibana-highlighted-field@"
    ],
    "level": [
      "@kibana-highlighted-field@Error@/kibana-highlighted-field@"
    ]
  },
  "sort": [
    1577092432297
  ]
}

[gregkalapos]

Oh, it looks like our body capturing causes this.

Are you on the latest (1.1.2) version @rcanpahali?

One quick (and not optimal) fix would be to turn off request body capturing.

I'll take a deeper look later - sorry about the trouble.

[simonare]

I am writing on behalf of @rcanpahali

we are using v1.2.0

• Elastic.Apm.AspNetCore v1.2.0
• Elastic.Apm.EntityFrameworkCore v1.2.0

I appreciate for your interest. I will take a look at the possibility of truning off request body capturing option.

Regards

[russcam]

The way that request bodies are captured has changed from 1.2.0 to the latest version, 1.10.0. I don't recall this same issue coming up in newer versions so I recommend upgrading to a newer version of the agent. I'm going to close this, but if the problem persists with 1.10.0, please feel free to reopen.