[BUG] Headers: invalid input for HTTPHeader

[Vaahik]

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]

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]

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]

@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]

@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]

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]

{
"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]

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

[stevejgordon]

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

[Vaahik]

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

[Sing303]

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]

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]

[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

[stevejgordon]

@Vaahik Unfortunately, these don't help explain the root issue of how your app ends up with a null value in the header we receive. Is this a regular ASP.NET Core app? What do your csproj and program.cs files look like? Can you boil it down to a minimal reproduction we can use to investigate?

@Sing303 Are you also on Centos?