search

elastic / apm-agent-dotnet

https://www.elastic.co/guide/en/apm/agent/dotnet/current/index.html
Apache License 2.0
585 stars 208 forks source link

[BUG] Headers: invalid input for HTTPHeader #2478

Open Vaahik opened 2 weeks ago

Vaahik commented 2 weeks ago

APM Agent version

The version of the Elastic.Apm nuget package used 1.0.30 linux profiler

Environment

Operating system and version: Centos 9

.NET Framework/Core name and version (e.g. .NET 4.6.2, NET Core 3.1.100) : Net Core 8.0.8

Application Target Framework(s) (e.g. net462, netcoreapp3.1):

Describe the bug

APM 8.15.3

[2024-11-06 19:53:38.768 +04:00][4][Error] - {PayloadSenderV2} Failed sending event. Events intake API absolute URL: http://localhost:8200/intake/v2/events. APM Server response: status code: BadRequest, reasons: decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.HTTPVersion: Headers: invalid input for HTTPHeader:

To Reproduce

Steps to reproduce the behavior:

  1. Use this config '...'
  2. Then call '....'
  3. Then do '....'
  4. See error

Expected behavior

A clear and concise description of what you expected to happen.

Actual behavior

Sing303 commented 2 weeks ago

I confirm, I had the same problem {"PayloadSenderV2"} Failed sending event. Events intake API absolute URL: http://localhost:8200/intake/v2/events. APM Server response: status code: BadRequest, reasons: "decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.HTTPVersion: Headers: invalid input for HTTPHeader: <nil>"

Sing303 commented 2 weeks ago

The problem was in the header, which has a value of NULL. So far I have fixed it like this

        Agent.AddFilter((ITransaction transaction) =>
        {
            if (transaction.Context?.Request?.Headers != null)
            {
                var headersWithNullValues = transaction.Context.Request.Headers
                    .Where(header => header.Value == null)
                    .ToList();
                foreach (var header in headersWithNullValues)
                {
                    transaction.Context.Request.Headers[header.Key] = "[REDACTED_NULL]";
                }
            }
            return transaction;
        });

Example of a problem query in APM from tracing

{
    "context": {
        "request": {
            "body": "[REDACTED]",
            "headers": {
                "Authorization": "[REDACTED]",
                "Cookie": null, <---- The problem was here
                "elastic-apm-traceparent": "...",
                "Host": "...",
                "traceparent": "..."
            },
            "http_version": "1.1",
            "method": "GET",
            "socket": {
                "remote_address": "..."
            },
            "url": {
                "full": "...",
                "hostname": "...",
                "pathname": "...",
                "protocol": "HTTP",
                "raw": "...",
                "search": ""
            }
        },
        "response": {
            "finished": true,
            "headers": {
                "api-file-version": "1.0.0.0",
                "api-supported-versions": "1.0",
                "api-version": "1.0",
                "Content-Type": "application/json; charset=utf-8",
                "Date": "Thu, 07 Nov 2024 16:54:11 GMT",
                "Server": "Kestrel",
                "Set-Cookie": "[REDACTED]",
                "Transfer-Encoding": "chunked"
            },
            "status_code": 200
        },
        "user": {
            "email": "...",
            "id": "...",
            "username": "..."
        }
    },
    "duration": 14.034,
    "id": "...",
    "name": "GET ...",
    "outcome": "success",
    "parent_id": "...",
    "result": "HTTP 2xx",
    "sampled": true,
    "span_count": {
        "dropped": 0,
        "started": 1
    },
    "timestamp": ...,
    "trace_id": "...",
    "type": "request"
}
stevejgordon commented 2 weeks ago

@Sing303 Thanks for providing the additional context. I'd like to understand how null headers are entering your system. ASP.NET Core defines the headers (from which we populate those on the transaction) as IDictionary<string, StringValues> and StringValues itself should not contain null strings.

Sing303 commented 2 weeks ago

@Sing303 Thanks for providing the additional context. I'd like to understand how null headers are entering your system. ASP.NET Core defines the headers (from which we populate those on the transaction) as IDictionary<string, StringValues> and StringValues itself should not contain null strings.

We have not yet figured out where the null values come from, so we decided on this filter so that there would be no errors

stevejgordon commented 2 weeks ago

Okay, thanks for the response. At this point, I'm hesitant to make changes to handle nulls when, as far as I can see, they should not occur. We can review this issue if a minimal repro scenario is found. @Vaahik, do you have any further details on your scenario?

Vaahik commented 2 weeks ago

{ "log.level": "error", "@timestamp": "2024-11-11T18:18:34.104Z", "message": "data validation error", "component": { "binary": "apm-server", "dataset": "elastic_agent.apm_server", "id": "apm-default", "type": "apm" }, "log": { "source": "apm-default" }, "source.address": "127.0.0.1", "event.duration": 895072, "service.name": "apm-server", "url.original": "/intake/v2/events", "user_agent.original": "apm-agent-dotnet/1.30.0+0539257e257b237f003a7e2413c2261408571bae-p (SSS 1.0.0+f32c3122bc7f3710fd2e4ad3a125f27704612870) System.Net.Http/8.0.824.36612 .NET_8/8.0.8", "http.request.id": "739353f3-2d1a-4bda-820f-f1ecc428da66", "http.request.body.bytes": 19010, "http.response.status_code": 400, "log.logger": "request", "log.origin": { "file.line": 59, "file.name": "middleware/log_middleware.go", "function": "github.com/elastic/apm-server/internal/beater/api.apmMiddleware.LogMiddleware.func1.1" }, "http.request.method": "POST", "error.message": "decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.HTTPVersion: Headers: invalid input for HTTPHeader: ", "ecs.version": "1.6.0", "ecs.version": "1.6.0" }

stevejgordon commented 1 week ago

@Vaahik, I'm trying to understand how you end up with null values for headers in the first place.

stevejgordon commented 5 days ago

@Vaahik Do you have any further information to help take this issue forward?

Vaahik commented 3 days ago

I don`t have any diag info. Only log :(

Sing303 commented 3 days ago

I don`t have any diag info. Only log :(

Can you set the APM logging level to Trace? Through setting environment variables. I got my log from these Trace logs

Env variable - ELASTIC_APM_LOG_LEVEL Env variable value - TRACE Info: https://www.elastic.co/guide/en/apm/agent/dotnet/current/config-supportability.html

Vaahik commented 3 days ago

I change log level to trace, but "outgoing json" do not present in the log.

log: [2024-11-22 15:59:43.277 +04:00][8][Trace] - {Transaction} Starting Span{Id: 4f588ddf1365c0a5, TransactionId: c5e3c9f1663799ea, ParentId: c5e3c9f1663799ea, TraceId: 6174d1d433a50a8910f0e1d3490d009a, Name: SET, Type: db, Outcome: Unknown, IsSampled: True, Duration: null} [2024-11-22 15:59:43.277 +04:00][56][Trace] - {Span.194683ead32fec2c} New Span instance created: Span{Id: 194683ead32fec2c, TransactionId: bfe5bcee8a0ca3c3, ParentId: bfe5bcee8a0ca3c3, TraceId: 6944789cca1d3cff3f8fa32017bc2697, Name: SET, Type: db, Outcome: Unknown, IsSampled: True, Duration: null}. Start time: 2024-11-22 11:59:43.2771390 UTC (as timestamp: 1732276783277139). Parent span: (null) [2024-11-22 15:59:43.278 +04:00][56][Trace] - {Transaction} Starting Span{Id: 194683ead32fec2c, TransactionId: bfe5bcee8a0ca3c3, ParentId: bfe5bcee8a0ca3c3, TraceId: 6944789cca1d3cff3f8fa32017bc2697, Name: SET, Type: db, Outcome: Unknown, IsSampled: True, Duration: null} [2024-11-22 15:59:43.278 +04:00][60][Trace] - {Span.3d3fa1b28535ca60} New Span instance created: Span{Id: 3d3fa1b28535ca60, TransactionId: 0d94bcf6b596cdf5, ParentId: 0d94bcf6b596cdf5, TraceId: 71bddeeaf0be9aa6fc670833d1e38906, Name: SELECT FROM UserDevices, Type: db, Outcome: Unknown, IsSampled: True, Duration: null}. Start time: 2024-11-22 11:59:43.2780890 UTC (as timestamp: 1732276783278089). Parent span: (null) [2024-11-22 15:59:43.278 +04:00][28][Trace] - {Span.e4e45f8fe15165e2} New Span instance created: Span{Id: e4e45f8fe15165e2, TransactionId: 7bec9b4e26360406, ParentId: 7bec9b4e26360406, TraceId: c20135a01f6521a05ca3550421b9e22d, Name: SET, Type: db, Outcome: Unknown, IsSampled: True, Duration: null}. Start time: 2024-11-22 11:59:43.2781180 UTC (as timestamp: 1732276783278118). Parent span: (null) [2024-11-22 15:59:43.278 +04:00][61][Trace] - {Span.1ae64c242522a046} New Span instance created: Span{Id: 1ae64c242522a046, TransactionId: c08b82c166328142, ParentId: c08b82c166328142, TraceId: 987dd6de3bc5297dd584c1c99e82defa, Name: SET, Type: db, Outcome: Unknown, IsSampled: True, Duration: null}. Start time: 2024-11-22 11:59:43.2773860 UTC (as timestamp: 1732276783277386). Parent span: (null) [2024-11-22 15:59:43.279 +04:00][60][Trace] - {Transaction} Starting Span{Id: 3d3fa1b28535ca60, TransactionId: 0d94bcf6b596cdf5, ParentId: 0d94bcf6b596cdf5, TraceId: 71bddeeaf0be9aa6fc670833d1e38906, Name: SELECT FROM UserDevices, Type: db, Outcome: Unknown, IsSampled: True, Duration: null} [2024-11-22 15:59:43.279 +04:00][28][Trace] - {Transaction} Starting Span{Id: e4e45f8fe15165e2, TransactionId: 7bec9b4e26360406, ParentId: 7bec9b4e26360406, TraceId: c20135a01f6521a05ca3550421b9e22d, Name: SET, Type: db, Outcome: Unknown, IsSampled: True, Duration: null} [2024-11-22 15:59:43.279 +04:00][61][Trace] - {Transaction} Starting Span{Id: 1ae64c242522a046, TransactionId: c08b82c166328142, ParentId: c08b82c166328142, TraceId: 987dd6de3bc5297dd584c1c99e82defa, Name: SET, Type: db, Outcome: Unknown, IsSampled: True, Duration: null} [2024-11-22 15:59:43.278 +04:00][4][Error] - {PayloadSenderV2} Failed sending event. Events intake API absolute URL: http://localhost:8200/intake/v2/events. APM Server response: status code: BadRequest, reasons: decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.HTTPVersion: Headers: invalid input for HTTPHeader: [2024-11-22 15:59:43.279 +04:00][4][Trace] - {PayloadSenderV2} Waiting for data to send... FlushInterval: 10s [2024-11-22 15:59:43.279 +04:00][4][Trace] - {PayloadSenderV2} There is data to be sent. Batch size: 10. newEventQueueCount: 172. First event: Span{Id: eb4c7d2f07111487, TransactionId: 0d0d3825a4b35673, ParentId: 0d0d3825a4b35673, TraceId: 3550e95e160586af0b9f0174462bdd25, Name: SELECT FROM Users, Type: db, Outcome: Success, IsSampled: True, Duration: 42.518}.

Vaahik commented 3 days ago

[2024-11-22 15:59:43.754 +04:00][57][Trace] - {HttpDiagnosticListenerCoreImpl} Request URL (http://localhost:8200/intake/v2/events) is filtered out - exiting [2024-11-22 15:59:43.754 +04:00][57][Trace] - {HttpDiagnosticListenerCoreImpl} Called with key: System.Net.Http.Response' [2024-11-22 15:59:43.754 +04:00][57][Trace] - {HttpDiagnosticListenerCoreImpl} Event's Request property is null - exiting [2024-11-22 15:59:43.754 +04:00][67][Trace] - {AspNetCoreDiagnosticListener} Called with key:Microsoft.AspNetCore.Hosting.EndRequest' [2024-11-22 15:59:43.754 +04:00][4][Error] - {PayloadSenderV2} Failed sending event. Events intake API absolute URL: http://localhost:8200/intake/v2/events. APM Server response: status code: BadRequest, reasons: decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.HTTPVersion: Headers: invalid input for HTTPHeader: [2024-11-22 15:59:43.754 +04:00][4][Trace] - {PayloadSenderV2} Waiting for data to send... FlushInterval: 10s