Apm-agent-dotnet: APM agent logs basic authentication user/password

[fredeil]

We had some transient network errors happen which caused the APM agent to log some errors. We have the error logging connected to our central logging system.

We discovered that the error logs included fields like ApmServerUrl, Url and EventsIntakeAbsoluteUrl which all included our Basic HTTP Authorization username and password in the URL. The errors were logged mainly from CentralConfigFetcher and PayloadSenderV2.

These should probably be removed or obfuscated before being logged

[gregkalapos]

@fredeil could you tell me which logs these are (of course without the username/pw)? I found 2 of those that could have this issue:

From PayloadSenderV2:

Failed sending events. Following events were not transferred successfully to the server ({ApmServerUrl}):\n{SerializedItems}

From CentralConfigFetcher:
```
Exception was thrown while fetching configuration from APM Server and parsing it. ...
````

Anything missing here? Any additional log where you have this problem?

We sanitize the url for the incoming HTTP request and we specifically hide the username/pw in case of basic HTTP authentication on those urls - My idea is that we'll just put the serverurl through the same logic.

[fredeil]

Seems like it's only those two. Found two unique messageTemplates in the logs (and they correspond to those you posted @gregkalapos ).

CentralConfigFetcher:

{{{Scope}}} Exception was thrown while fetching configuration from APM Server and parsing it. ETag: `{ETag}'. URL: `{Url}'. Apm Server base URL: `{ApmServerUrl}'. WaitInterval: {WaitInterval}. dbgIterationsCount: {dbgIterationsCount}.\n+-> Request:{HttpRequest}\n+-> Response:{HttpResponse}\n+-> Response body [length: {HttpResponseBodyLength}]:{HttpResponseBody}

Here, both {Url} and {ApmServerUrl} contains the username and password.

{
  "_index": "removed",
  "_type": "_doc",
  "_id": "-C2ZDXUBkB0mQNlz7CgG",
  "_version": 1,
  "_score": null,
  "_source": {
    "exception": {
      "Message": "Resource temporarily unavailable",
      "RemoteStackTraceString": null,
      "Depth": 0,
      "HelpURL": null,
      "ClassName": "System.Net.Http.HttpRequestException",
      "StackTraceString": "   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)\n   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)\n   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)\n   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)\n   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)\n   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\n   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)\n   at Elastic.Apm.BackendComm.CentralConfigFetcher.FetchConfigHttpResponseImplAsync(HttpRequestMessage httpRequest)\n   at Elastic.Apm.Helpers.AgentTimerExtensions.TryAwaitOrTimeout(IAgentTimer agentTimer, Task taskToAwait, AgentTimeInstant until, CancellationToken cancellationToken)\n   at Elastic.Apm.Helpers.AgentTimerExtensions.TryAwaitOrTimeout[TResult](IAgentTimer agentTimer, Task`1 taskToAwait, AgentTimeInstant until, CancellationToken cancellationToken)\n   at Elastic.Apm.Helpers.AgentTimerExtensions.AwaitOrTimeout[TResult](IAgentTimer agentTimer, Task`1 taskToAwait, AgentTimeInstant until, CancellationToken cancellationToken)\n   at Elastic.Apm.BackendComm.CentralConfigFetcher.FetchConfigHttpResponseAsync(HttpRequestMessage httpRequest)\n   at Elastic.Apm.BackendComm.CentralConfigFetcher.WorkLoopIteration()",
      "RemoteStackIndex": 0,
      "HResult": -2147467259,
      "Source": "System.Net.Http",
      "innerException": {
        "Message": "Resource temporarily unavailable",
        "RemoteStackTraceString": null,
        "Depth": 1,
        "HelpURL": null,
        "ClassName": "System.Net.Sockets.SocketException",
        "StackTraceString": "   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)",
        "RemoteStackIndex": 0,
        "HResult": -2147467259,
        "Source": "System.Private.CoreLib"
      }
    },
    "fields": {
      "Scope": "CentralConfigFetcher",
      "SourceContext": "Elastic.Apm",
      "ExceptionDetail": {
        "HResult": -2147467259,
        "Message": "Resource temporarily unavailable",
        "Source": "System.Net.Http",
        "InnerException": {
          "Message": "Resource temporarily unavailable",
          "ErrorCode": 11,
          "Type": "System.Net.Sockets.SocketException",
          "HResult": -2147467259,
          "Source": "System.Private.CoreLib",
          "NativeErrorCode": 11,
          "SocketErrorCode": "TryAgain"
        },
        "Type": "System.Net.Http.HttpRequestException"
      },
      "HttpResponseBody": " N/A",
      "ETag": "<null>",
      "dbgIterationsCount": 1,
      "HttpResponse": " N/A",
      "HttpResponseBodyLength": "N/A",
      "Url": "http://dp_apm_writer:*******@******:8200/config/v1/agents?service.name=cs-public-api&service.environment=ConnectionSuite",
      "HttpRequest": "\n    Method: GET, RequestUri: 'http://dp_apm_writer:*******@******:8200/config/v1/agents?service.name=cs-public-api&service.environment=ConnectionSuite', Version: 1.1, Content: <null>, Headers:\n    {\n      User-Agent: elasticapm-dotnet/1.4.0\n      User-Agent: System.Net.Http/4.700.20.41903\n      User-Agent: .NET_Core/3.1.8\n    }",
      "WaitInterval": "5m",
      "Index": "removed",
      "ApmServerUrl": "http://dp_apm_writer:*******@******:8200/"
    },
    "message": "{\"CentralConfigFetcher\"} Exception was thrown while fetching configuration from APM Server and parsing it. ETag: `\"<null>\"'. URL: `http://dp_apm_writer:*******@******:8200/config/v1/agents?service.name=cs-public-api&service.environment=ConnectionSuite'. Apm Server base URL: `http://dp_apm_writer:*******@******:8200/'. WaitInterval: \"5m\". dbgIterationsCount: 1.\n+-> Request:\"\n    Method: GET, RequestUri: 'http://dp_apm_writer:*******@******:8200/config/v1/agents?service.name=cs-public-api&service.environment=ConnectionSuite', Version: 1.1, Content: <null>, Headers:\n    {\n      User-Agent: elasticapm-dotnet/1.4.0\n      User-Agent: System.Net.Http/4.700.20.41903\n      User-Agent: .NET_Core/3.1.8\n    }\"\n+-> Response:\" N/A\"\n+-> Response body [length: \"N/A\"]:\" N/A\"",
    "@version": "1",
    "messageTemplate": "{{{Scope}}} Exception was thrown while fetching configuration from APM Server and parsing it. ETag: `{ETag}'. URL: `{Url}'. Apm Server base URL: `{ApmServerUrl}'. WaitInterval: {WaitInterval}. dbgIterationsCount: {dbgIterationsCount}.\n+-> Request:{HttpRequest}\n+-> Response:{HttpResponse}\n+-> Response body [length: {HttpResponseBodyLength}]:{HttpResponseBody}",
    "level": "Error",
    "@timestamp": "2020-10-09T13:43:10.887Z"
  },
  "fields": {
    "@timestamp": [
      "2020-10-09T13:43:10.887Z"
    ]
  },
  "sort": [
    1602250990887
  ]
}

PayloadSenderV2:

{{{Scope}}} Failed sending event. Events intake API absolute URL: {EventsIntakeAbsoluteUrl}. APM Server response: status code: {ApmServerResponseStatusCode}, content: \n{ApmServerResponseContent}

{EventsIntakeAbsoluteUrl} includes the username and password.

{
  "_index": "removed",
  "_type": "_doc",
  "_id": "5QHLE3UBvw1cb_3gNE32",
  "_version": 1,
  "_score": null,
  "_source": {
    "fields": {
      "EventsIntakeAbsoluteUrl": "http://dp_apm_writer:*****@******:8200/intake/v2/events",
      "Scope": "PayloadSenderV2",
      "SourceContext": "Elastic.Apm",
      "Application": "removed",
      "ApmServerResponseContent": "{\"accepted\":0,\"errors\":[{\"message\":\"queue is full\"}]}\n",
      "ApmServerResponseStatusCode": "ServiceUnavailable",
      "Index": "removed",
      "ThreadId": 10
    },
    "message": "{\"PayloadSenderV2\"} Failed sending event. Events intake API absolute URL: http://dp_apm_writer:*****@******:8200/intake/v2/events. APM Server response: status code: ServiceUnavailable, content: \n\"{\\\"accepted\\\":0,\\\"errors\\\":[{\\\"message\\\":\\\"queue is full\\\"}]}\n\"",
    "@version": "1",
    "messageTemplate": "{{{Scope}}} Failed sending event. Events intake API absolute URL: {EventsIntakeAbsoluteUrl}. APM Server response: status code: {ApmServerResponseStatusCode}, content: \n{ApmServerResponseContent}",
    "level": "Error",
    "@timestamp": "2020-10-10T18:34:44.854Z"
  },
  "fields": {
    "@timestamp": [
      "2020-10-10T18:34:44.854Z"
    ]
  },
  "sort": [
    1602354884854
  ]
}

[gregkalapos]

Perfect, thanks @fredeil .