Issue with datadog source and decoding.codec = "json"

[fredericpellin]

Hello,

I've an issue with datadog source, json decoding codec and apache log which raised an error about json parsing.

My vector.toml config to reproduce :

[sources.dlogs]
type = "datadog_agent"
address = "0.0.0.0:8089"
decoding.codec = "json"

[sources.stdin]
type = "stdin"
decoding.codec = "json"

[sinks.stdout]
type = "console"
inputs =  ["dlogs","stdin"]
target = "stdout"
encoding.codec = "json"

datadog.yml

logs_enabled: true

apache.d/conf.yaml

init_config:
instances:
  - apache_status_url: http://localhost:8090/server-status?auto
logs:
  - type: file
    path: /var/log/apache2/other_vhosts_access.log
    source: apache
    service: apache
    sourcecategory: http_web_access

output when decoding.codec = "json" is commented

# vector -c vector.toml
2023-01-06T05:31:59.208801Z  INFO vector::app: Internal log rate limit configured. internal_log_rate_secs=10
2023-01-06T05:31:59.208880Z  INFO vector::app: Log level is enabled. level="vector=info,codec=info,vrl=info,file_source=info,tower_limit=trace,rdkafka=info,buffers=info,lapin=info,kube=info"
2023-01-06T05:31:59.208933Z  INFO vector::app: Loading configs. paths=["vector.toml"]
2023-01-06T05:31:59.210314Z  INFO vector::sources::datadog_agent: Building HTTP server. address=0.0.0.0:8089
2023-01-06T05:31:59.210614Z  INFO vector::topology::running: Running healthchecks.
2023-01-06T05:31:59.210837Z  INFO vector: Vector has started. debug="false" version="0.26.0" arch="x86_64" revision="c6b5bc2 2022-12-05"
2023-01-06T05:31:59.210936Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.
2023-01-06T05:31:59.211012Z  INFO vector::sources::file_descriptors: Capturing stdin.
2023-01-06T05:31:59.211208Z  INFO vector::topology::builder: Healthcheck: Passed.
{"ddsource":"apache","ddtags":"filename:other_vhosts_access.log,sourcecategory:http_web_access","hostname":"debian","message":"127.0.0.1 - - [06/Jan/2023:06:33:30 +0100] \"GET /server-status?auto HTTP/1.1\" 200 719 \"-\" \"Datadog Agent/7.41.1\"","service":"apache","source_type":"datadog_agent","status":"info","timestamp":"2023-01-06T05:33:31.074Z"}
{"ddsource":"apache","ddtags":"filename:other_vhosts_access.log,sourcecategory:http_web_access","hostname":"debian","message":"127.0.0.1 - - [06/Jan/2023:06:33:43 +0100] \"GET / HTTP/1.1\" 200 11012 \"-\" \"Wget/1.21\"","service":"apache","source_type":"datadog_agent","status":"info","timestamp":"2023-01-06T05:33:44.083Z"}
{"ddsource":"apache","ddtags":"filename:other_vhosts_access.log,sourcecategory:http_web_access","hostname":"debian","message":"127.0.0.1 - - [06/Jan/2023:06:33:45 +0100] \"GET /server-status?auto HTTP/1.1\" 200 722 \"-\" \"Datadog Agent/7.41.1\"","service":"apache","source_type":"datadog_agent","status":"info","timestamp":"2023-01-06T05:33:45.084Z"}

output when dedocing.codec = "json" is activated

vector -c vector.toml
2023-01-06T05:34:21.520749Z  INFO vector::app: Internal log rate limit configured. internal_log_rate_secs=10
2023-01-06T05:34:21.520821Z  INFO vector::app: Log level is enabled. level="vector=info,codec=info,vrl=info,file_source=info,tower_limit=trace,rdkafka=info,buffers=info,lapin=info,kube=info"
2023-01-06T05:34:21.520876Z  INFO vector::app: Loading configs. paths=["vector.toml"]
2023-01-06T05:34:21.522283Z  INFO vector::sources::datadog_agent: Building HTTP server. address=0.0.0.0:8089
2023-01-06T05:34:21.522539Z  INFO vector::topology::running: Running healthchecks.
2023-01-06T05:34:21.522660Z  INFO vector: Vector has started. debug="false" version="0.26.0" arch="x86_64" revision="c6b5bc2 2022-12-05"
2023-01-06T05:34:21.522675Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.
2023-01-06T05:34:21.522960Z  INFO vector::sources::file_descriptors: Capturing stdin.
2023-01-06T05:34:21.523187Z  INFO vector::topology::builder: Healthcheck: Passed.
2023-01-06T05:34:23.682172Z ERROR source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::internal_events::codecs: Failed deserializing frame. error=Error parsing JSON: Error("trailing characters", line: 1, column: 6) error_type="parser_failed" stage="processing" internal_log_rate_limit=true
2023-01-06T05:34:29.075815Z ERROR source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::internal_events::codecs: Internal log [Failed deserializing frame.] is being rate limited.
2023-01-06T05:34:34.071983Z ERROR source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::internal_events::codecs: Internal log [Failed deserializing frame.] has been rate limited 1 times.
2023-01-06T05:34:34.072029Z ERROR source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::internal_events::codecs: Failed deserializing frame. error=Error parsing JSON: Error("trailing characters", line: 1, column: 6) error_type="parser_failed" stage="processing" internal_log_rate_limit=true

If I put log level to trace, no more information is printed

vector -c vector.toml -vv
2023-01-06T05:35:22.742659Z  INFO vector::app: Internal log rate limit configured. internal_log_rate_secs=10
2023-01-06T05:35:22.742752Z  INFO vector::app: Log level is enabled. level="vector=trace,codec=trace,vrl=trace,file_source=trace,tower_limit=trace,rdkafka=trace,buffers=trace,lapin=trace,kube=trace"
2023-01-06T05:35:22.742810Z  INFO vector::app: Loading configs. paths=["vector.toml"]
2023-01-06T05:35:22.743333Z DEBUG vector::config::loading: No secret placeholder found, skipping secret resolution.
2023-01-06T05:35:22.743954Z DEBUG vector::topology::builder: Building new source. component=dlogs
2023-01-06T05:35:22.744279Z  INFO vector::sources::datadog_agent: Building HTTP server. address=0.0.0.0:8089
2023-01-06T05:35:22.744304Z DEBUG vector::topology::builder: Building new source. component=stdin
2023-01-06T05:35:22.744491Z DEBUG vector::topology::builder: Building new sink. component=stdout
2023-01-06T05:35:22.744570Z  INFO vector::topology::running: Running healthchecks.
2023-01-06T05:35:22.744579Z DEBUG vector::topology::running: Connecting changed/added component(s).
2023-01-06T05:35:22.744588Z DEBUG vector::topology::running: Configuring outputs for source. component=dlogs
2023-01-06T05:35:22.744885Z DEBUG vector::topology::running: Configuring output for component. component=dlogs output_id=None
2023-01-06T05:35:22.744902Z DEBUG vector::topology::running: Configuring outputs for source. component=stdin
2023-01-06T05:35:22.744911Z DEBUG vector::topology::running: Configuring output for component. component=stdin output_id=None
2023-01-06T05:35:22.744921Z DEBUG vector::topology::running: Connecting inputs for sink. component=stdout
2023-01-06T05:35:22.744931Z DEBUG vector::topology::running: Adding component input to fanout. component=stdout fanout_id=dlogs
2023-01-06T05:35:22.744973Z  INFO vector::topology::builder: Healthcheck: Passed.
2023-01-06T05:35:22.745035Z DEBUG vector::topology::running: Adding component input to fanout. component=stdout fanout_id=stdin
2023-01-06T05:35:22.745062Z DEBUG vector::topology::running: Spawning new source. key=dlogs
2023-01-06T05:35:22.745085Z DEBUG vector::topology::running: Spawning new source. key=stdin
2023-01-06T05:35:22.745101Z TRACE vector::topology::running: Spawning new sink. key=stdout
2023-01-06T05:35:22.745116Z DEBUG source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::topology::builder: Source pump supervisor starting.
2023-01-06T05:35:22.745136Z DEBUG source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::topology::builder: Source pump starting.
2023-01-06T05:35:22.745139Z DEBUG source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::topology::builder: Source starting.
2023-01-06T05:35:22.745154Z DEBUG source{component_kind="source" component_id=stdin component_type=stdin component_name=stdin}: vector::topology::builder: Source pump supervisor starting.
2023-01-06T05:35:22.745177Z DEBUG source{component_kind="source" component_id=stdin component_type=stdin component_name=stdin}: vector::topology::builder: Source pump starting.
2023-01-06T05:35:22.745184Z DEBUG source{component_kind="source" component_id=stdin component_type=stdin component_name=stdin}: vector::topology::builder: Source starting.
2023-01-06T05:35:22.745206Z DEBUG sink{component_kind="sink" component_id=stdout component_type=console component_name=stdout}: vector::topology::builder: Sink starting.
2023-01-06T05:35:22.745362Z  INFO vector::sources::file_descriptors: Capturing stdin.
2023-01-06T05:35:22.745519Z  INFO vector: Vector has started. debug="false" version="0.26.0" arch="x86_64" revision="c6b5bc2 2022-12-05"
2023-01-06T05:35:22.745539Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.
2023-01-06T05:35:22.746429Z DEBUG sink{component_kind="sink" component_id=stdout component_type=console component_name=stdout}: vector::utilization: utilization=0.01327304755343417
2023-01-06T05:35:53.747075Z TRACE vector: Beep.
2023-01-06T05:35:54.746660Z TRACE vector: Beep.
2023-01-06T05:35:55.746409Z TRACE vector: Beep.
2023-01-06T05:35:55.904753Z TRACE source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::internal_events::http: Bytes received. byte_size=592 http_path=/api/v2/logs protocol=http
2023-01-06T05:35:55.904900Z ERROR source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::internal_events::codecs: Internal log [Failed deserializing frame.] has been rate limited 4 times.
2023-01-06T05:35:55.904923Z ERROR source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::internal_events::codecs: Failed deserializing frame. error=Error parsing JSON: Error("trailing characters", line: 1, column: 6) error_type="parser_failed" stage="processing" internal_log_rate_limit=true
2023-01-06T05:35:55.904970Z ERROR source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector::internal_events::codecs: Internal log [Failed deserializing frame.] is being rate limited.
2023-01-06T05:35:55.904993Z TRACE source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector_common::internal_event::events_received: Events received. count=0 byte_size=2
2023-01-06T05:35:55.905033Z TRACE source{component_kind="source" component_id=dlogs component_type=datadog_agent component_name=dlogs}: vector_common::internal_event::events_sent: Events sent. count=0 byte_size=0 output=_default
2023-01-06T05:35:56.746581Z TRACE vector: Beep.
2023-01-06T05:35:57.747185Z TRACE vector: Beep.
2023-01-06T05:35:57.747257Z DEBUG sink{component_kind="sink" component_id=stdout component_type=console component_name=stdout}: vector::utilization: utilization=0.00000004693665614420876
2023-01-06T05:35:58.746515Z TRACE vector: Beep.

Any idea ?

[tobz]

@fredericpellin Hey there!

You've discovered a somewhat-poorly documented configuration of the source, but this is working as intended. The Datadog Agent sends its requests using a fixed codec (JSON and/or Protocol Buffers) but what decoding.codec controls is how log messages, specifically, are further decoded.

By default, decoding.codec will be bytes, which means we treat the log message as-is and just pass the unmodified bytes through Vector. When you set it to decoding.codec, the source will now attempt to decode each log message as JSON. As your log messages are Apache logs, this is going to fail to parse as JSON, hence the error.

So, overall, you should only change decoding.codec if you're trying to natively decode the log messages i.e. the log lines are JSON and you want to parse them as JSON in the source directly. We'll investigate if we can better document this to explain where and when the chosen codec is applied.

[fredericpellin]

After opening code, I see how it works.
I'm going to use directly datadog mapping to replace vector instance.
Thanks .