apm-agent-python icon indicating copy to clipboard operation
apm-agent-python copied to clipboard

Flask 400 decode error with HTTPHeader <nil> value

Open onesolpark opened this issue 1 year ago • 3 comments

Describe the bug: Flask transaction data are not gathered due to 400 decode error with HTTPHeader value Dependency and metric data are gathered and shown on dashboard but transaction data are rejected.

Additional data just in case if it matters

  • Flask debug is turned on but ELASTIC_APM_DEBUG is also set to True to enable sending data.

**Environment

  • OS: Ubuntu Linux (Container to be exact)
  • Python version: 3.10
  • Framework and version [e.g. Django 2.1]: flask-3.0.2
  • APM Server version: 8.15
  • Agent version: 6.23.0

Additional context

Add any other context about the problem here.

  • Agent config options

    Click to expand
    using default configs except for ELASTIC_APM_DEBUG 
    
  • requirements.txt:

    Click to expand
    Flask
    SQLAlchemy 
    PyMySQL
    Flask-Babel
    pydantic
    elastic-apm
    

Python Agent Logs

2024-10-04 01:50:43.785 7 DEBUG elasticapm.metrics [-] Collecting metrics base_metrics.py:97 collect 
2024-10-04 01:50:44.176 7 DEBUG elasticapm.transport [-] flushing due to time since last flush 10.549s > max_flush_time 10.549s base.py:165 _process_queue
2024-10-04 01:50:44.183 7 DEBUG elasticapm.transport.http [-] Sent request, url=http://[apm-server-address]:8200/intake/v2/events size=25.74kb status=400 http.py:97 send 
2024-10-04 01:50:44.184 7 ERROR elasticapm.transport [-] Failed to submit message: 'HTTP 400: {"accepted":32,"errors":[{"message":"decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.URL: v2.contextRequestURL.Headers: invalid input for HTTPHeader: \\\\u003cnil\\\\u003e","document":"{\\\\"transaction\\\\": {\\\\"id\\\\": \\\\"956ba79c937359c5\\\\", \\\\"trace_id\\\\": \\\\"8930f92212c7229641b769754c1f13c5\\\\", \\\\"name\\\\": \\\\"GET [REDACTED]\\\\", \\\\"type\\\\": \\\\"request\\\\", \\\\"duration\\\\": 244.316, \\\\"result\\\\": \\\\"HTTP 2xx\\\\", \\\\"timestamp\\\\": 1728006633627826, \\\\"outcome\\\\": \\\\"success\\\\", \\\\"sampled\\\\": true, \\\\"span_count\\\\": {\\\\"started\\\\": 3, \\\\"dropped\\\\": 0}, \\\\"sample_rate\\\\": 1.0, \\\\"context\\\\": {\\\\"request\\\\": {\\\\"env\\\\": {\\\\"REMOTE_ADDR\\\\": \\\\"[REDACTED]\\\\", \\\\"

APM Server Logs

{"log.level":"error","@timestamp":"2024-10-04T01:51:25.015Z","log.logger":"request","log.origin":{"function":"github.com/elastic/apm-server/internal/beater/api.apmMiddleware.LogMiddleware.func1.1","file.name":"middleware/log_middleware.go","file.line":59},"message":"data validation error","service.name":"apm-server","url.original":"/intake/v2/events","http.request.method":"POST","user_agent.original":"apm-agent-python/6.23.0 (APP_NAME)","source.address":"[REDACTED]","http.request.id":"89ce0a55-95f1-4dd1-8b75-417a3bc5c990","event.duration":3209908,"http.request.body.bytes":20497,"http.response.status_code":400,"error.message":"decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.URL: v2.contextRequestURL.Headers: invalid input for HTTPHeader: <nil>, decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.URL: v2.contextRequestURL.Headers: invalid input for HTTPHeader: <nil>, decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.URL: v2.contextRequestURL.Headers: invalid input for HTTPHeader: <nil>, decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.URL: v2.contextRequestURL.Headers: invalid input for HTTPHeader: <nil>, decode error: data read error: v2.transactionRoot.Transaction: v2.transaction.Context: v2.context.Request: v2.contextRequest.URL: v2.contextRequestURL.Headers: invalid input for HTTPHeader: <nil>","ecs.version":"1.6.0"}

Seems like agent is sending HTTPHeader as and apm server errors out when trying to decode the request. I've redacted sensitive data tell me if you need more information.

onesolpark avatar Oct 04 '24 03:10 onesolpark

Turning off header capture removed the 400 error. https://www.elastic.co/guide/en/apm/agent/python/current/configuration.html#config-capture-headers

I think agent/server should be able to deal with null, nil headers.

onesolpark avatar Oct 07 '24 02:10 onesolpark

Thanks for reporting, do this reproduce with a minimal application or are you doing something specific with headers?

xrmx avatar Oct 07 '24 07:10 xrmx

I know its strange that there are nil headers but I don't think we are doing anything specific with headers. (let me double check this)

Let me see if I can reproduce with a minimal application.

onesolpark avatar Oct 08 '24 04:10 onesolpark