APM Bug causes null pointer for web requests in .NET 4.6.1

If you are asking about a problem you are experiencing, please use the following template, as it will help us help you. If you have a different problem, please delete all of this text :slight_smile:

Kibana version:7.3.0

Elasticsearch version:7.3.0

APM Server version:7.3.0

APM Agent language and version:C# V 1.0 of agent

Browser version: NA

Original install method (e.g. download page, yum, deb, from source, etc.) and version:Nuget

Fresh install or upgraded from other version?
fresh

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
Get a null pointer on web requests that fail due to access denied. This then causse the web error to come back differently and application falls in a heap. If you disable the out going http request monitoring our code gets the access denied error then resends with auth token.

Image of line that causes the null pointer and the state and type of objects is is trying to use reflection to get a non existent value from a non existent property called "Exception". You can see "Exception" is not a property on this object. Also AMP Agent logs at bottom of post.

Steps to reproduce:

  1. build a dotnet 4.6.1 console app
  2. Add line Agent.Subscribe(new HttpDiagnosticsSubscriber());
  3. make a http calls that results in an access denied
    NOTE: steps above should give a similar or same out come but have not tested.

Errors in browser console (if relevant):

Provide logs and/or server output (if relevant):
LOGS

[2019-08-20 11:56:43][Trace] - {HttpDiagnosticListenerImplBase} Processing start event... Request URL: https://xxxx/api/georef/v1/regions/details?orqId=Cs_6a91a9c4-e40c-4457-89f2-06570b3f9805
[2019-08-20 11:56:43][Trace] - {CurrentExecutionSegmentsContainer.transaction} Getting value... Thread: 1. Current value: (null).
[2019-08-20 11:56:43][Debug] - {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
[2019-08-20 11:56:43][Trace] - {HttpDiagnosticListenerImplBase} Called with key: `
System.Net.Http.Desktop.HttpRequestOut.Ex.Stop', value: `{ Request = System.Net.HttpWebRequest, StatusCode = Unauthorized, Headers = Connection: keep-alive
Content-Length: 0
Date: Tue, 20 Aug 2019 11:56:43 GMT
Set-Cookie: ss-id=nm4f50cAVOHEGK8Dgnk3; path=/; samesite=lax; httponly,ss-pid=q2HnaRvpr9pcHR4ca1YQ; expires=Sat, 20 Aug 2039 11:56:43 GMT; path=/; samesite=lax; httponly
Server: Kestrel
Vary: Accept
WWW-Authenticate: jwt realm="/auth/jwt"
Access-Control-Allow-Credentials: true
Access-Control-Allow-Headers: Content-Type,Access-Control-Allow-Headers,Authorization,Accept
Access-Control-Allow-Methods: GET, POST, PUT, DELETE, PATCH, OPTIONS
X-Powered-By: ServiceStack/5.10 NETStandard/.NET

 }
[2019-08-20 11:56:43][Trace] - {HttpDiagnosticListenerImplBase} Processing exception event... Request URL: https://xxxx/api/georef/v1/regions/details?orqId=Cs_6a91a9c4-e40c-4457-89f2-06570b3f9805
Application startup exception: System.Net.WebException: The request was aborted: The request was canceled. ---> System.NullReferenceException: Object reference not set to an instance of an object.
   at Elastic.Apm.DiagnosticListeners.HttpDiagnosticListenerImplBase`2.ProcessExceptionEvent(Object eventValue, Uri requestUrl)
   at Elastic.Apm.DiagnosticListeners.HttpDiagnosticListenerImplBase`2.OnNext(KeyValuePair`2 kv)
   at System.Diagnostics.DiagnosticListener.Write(String name, Object value)
   at System.Diagnostics.HttpHandlerDiagnosticListener.RaiseResponseEvent(HttpWebRequest request, HttpStatusCode statusCode, WebHeaderCollection headers)
   at System.Diagnostics.HttpHandlerDiagnosticListener.HttpWebRequestArrayList.RemoveAt(Int32 index)
   at System.Net.Connection.ReadStartNextRequest(WebRequest currentRequest, ConnectionReturnResult& returnResult)
   at System.Net.ConnectStream.CallDone(ConnectionReturnResult returnResult)
   at System.Net.HttpWebResponse..ctor(Uri responseUri, KnownHttpVerb verb, CoreResponseData coreData, String mediaType, Boolean usesProxySemantics, DecompressionMethods decompressionMethod, Boolean isWebSocketResponse, String connectionGroupName)
   at System.Net.HttpWebRequest.SetResponse(CoreResponseData coreResponseData)
   --- End of inner exception stack trace ---
   at System.Net.HttpWebRequest.GetResponse()
   at ServiceStack.ServiceClientBase.Send[TResponse](String httpMethod, String relativeOrAbsoluteUrl, Object request)

`

Hi @Chris_Gilligan ,

thanks for reporting this!

Yes, it seems to be something that we did not expect - I opened a bug on GitHub: https://github.com/elastic/apm-agent-dotnet/issues/443

After the first look at it, I'd say this is something we'll need to fix in the agent, as you hinted probably by making sure that the Exception property is there.

Do you have maybe a repro of this?

Thanks!

Sorry i don't have one i can share. I don't think it will make a difference but just in case we are using the (ServiceStack) client that wraps standard dotnet http client etc. If i get a chance i will build a test app but i don't think i will for a few days at least as i am behind at work due tot he other monitoring solution not working for us which lead me to find elastic APM.

If there is a beta package published i am happy to test it but for what i need right now i was just going to turn that feature off as it was just a nice to have for what i currently need.

ok this is really strange now. This happens in our internal app on startup every time so i tried to quickly copy similar logic into a console app that uses https://httpstat.us/403 and the same issue is not happening. Even pointing to the same internal endpoint it does not happen so it must be something to do with ServiceStack Client vs raw HttpClient.

Even using ServiceStack client i have not been able to duplicate this outside our main application to find the settings that trigger this. A standard request to 401 endpoint seems fine. It must have to do with some setting or something on the HTTP client that configures things differently or something to make the provided object to the tracing different than expected.

Thanks for all the info @Chris_Gilligan,

I managed to reproduce it, so I’m able to debug through this.

Maybe a couple of ideas, why your tests did not reproduce the problem:

  • The tracing for HttpClient is different on Full Framework and on .NET Core. In the logs I see that when the problem happens your application runs on Full Framework. It’s because the key is System.Net.Http.Desktop.HttpRequestOut.Ex.Stop - that’s what Full Framework emits. So, this problem only seem to happen on Full Framework, .NET Core has a different implementation.

  • In case there is no active transaction the HttpClient tracing part won’t do any work, and it returns before we get to this problem. So in a simple console app you have to start a transaction manually - otherwise the code cusing the trouble won't run.

I’m just speculating, but maybe one of these 2 explains why you were not able to reproduce it in different environments.

Anyways, I already work on this, hopefully we’ll be able to push a fix soon.

@GregKalapos thanks

A short update on it - a fix just got published, the package version is 1.0.1. More details here - the packages are also uploaded to NuGet.org.

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.