Vector: Datadog Logs - sending data problem after switch to HTTP sink

Created on 26 Oct 2020 · 14Comments · Source: timberio/vector

Vector Version

vector 0.11.0 (g221a1f7 x86_64-unknown-linux-gnu 2020-10-26)

Vector Configuration File

[sinks.datadog_logs_nginx]
  # General
  type = "datadog_logs" # required
  inputs = ["nginx-access","nginx-error"] # required
  api_key = "${DATADOG_API_KEY}" # required
  endpoint = "https://http-intake.logs.datadoghq.com:443" # optional, default
  region = "us"
  healthcheck = true # optional, default

  # Buffer
  buffer.type = "memory" # memory/disk optional, default
  buffer.max_events = 500 # optional, default, events, relevant when type = "memory"
  buffer.when_full = "block" # optional, default

  # Encoding
  encoding.codec = "json" # required
  encoding.except_fields = [] # optional, no default
  encoding.timestamp_format = "rfc3339" # optional, default

  tls.enabled = true
  tls.verify_certificate = true # optional, default
  tls.verify_hostname = true # optional, default

Debug Output

Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.236 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Polling batch linger.
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: message repeated 2 times: [ Oct 26 10:13:05.236 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Polling batch linger.]
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.237 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Polling batch linger.
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: message repeated 3 times: [ Oct 26 10:13:05.237 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Polling batch linger.]
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.238 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Polling batch linger.
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: message repeated 2 times: [ Oct 26 10:13:05.238 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Polling batch linger.]
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.239 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Polling batch linger.
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: message repeated 2 times: [ Oct 26 10:13:05.239 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Polling batch linger.]
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.239 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Batch full.
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.239 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Batch full.
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.286 ERROR sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}:request{request_id=1726}: vector::sinks::util::retries: Not retriable; dropping the request. reason=response status: 400 Bad Request
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.286 ERROR sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}:request{request_id=1726}: vector::sinks::util::sink: Response wasn't successful. response=Response { status: 400, version: HTTP/1.1, headers: {"date": "Mon, 26 Oct 2020 10:13:05 GMT", "content-type": "text/html", "content-length": "90", "connection": "keep-alive", "cache-control": "no-cache"}, body: b"<html><body><h1>400 Bad request</h1>\nYour browser sent an invalid request.\n</body></html>\n" }
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.286 TRACE sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}: vector::sinks::util::sink: Batch full.
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.286 ERROR sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}:request{request_id=1727}: vector::sinks::util::retries: Not retriable; dropping the request. reason=response status: 400 Bad Request
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.286 ERROR sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}:request{request_id=1727}: vector::sinks::util::sink: Response wasn't successful. response=Response { status: 400, version: HTTP/1.1, headers: {"date": "Mon, 26 Oct 2020 10:13:05 GMT", "content-type": "text/html", "content-length": "90", "connection": "keep-alive", "cache-control": "no-cache"}, body: b"<html><body><h1>400 Bad request</h1>\nYour browser sent an invalid request.\n</body></html>\n" }
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.296 ERROR sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}:request{request_id=1728}: vector::sinks::util::retries: Not retriable; dropping the request. reason=response status: 400 Bad Request
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.296 ERROR sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}:request{request_id=1728}: vector::sinks::util::sink: Response wasn't successful. response=Response { status: 400, version: HTTP/1.1, headers: {"date": "Mon, 26 Oct 2020 10:13:05 GMT", "content-type": "text/html", "content-length": "90", "connection": "keep-alive", "cache-control": "no-cache"}, body: b"<html><body><h1>400 Bad request</h1>\nYour browser sent an invalid request.\n</body></html>\n" }
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.354 ERROR sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}:request{request_id=1729}: vector::sinks::util::retries: Not retriable; dropping the request. reason=response status: 400 Bad Request
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.354 ERROR sink{component_kind="sink" component_name=datadog_logs_nginx component_type=datadog_logs}:request{request_id=1729}: vector::sinks::util::sink: Response wasn't successful. response=Response { status: 400, version: HTTP/1.1, headers: {"date": "Mon, 26 Oct 2020 10:13:05 GMT", "content-type": "text/html", "content-length": "90", "connection": "keep-alive", "cache-control": "no-cache"}, body: b"<html><body><h1>400 Bad request</h1>\nYour browser sent an invalid request.\n</body></html>\n" }
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.848 TRACE sink{component_kind="sink" component_name=datadog_logs_haproxy component_type=datadog_logs}: vector::sinks::util::sink: Service ready; Sending batch.
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.848 TRACE sink{component_kind="sink" component_name=datadog_logs_haproxy component_type=datadog_logs}: vector::sinks::util::sink: submitting service request. in_flight_requests=1
Oct 26 10:13:05 ip-10-105-195-46 vector[14237]: Oct 26 10:13:05.848 TRACE sink{component_kind="sink" component_name=datadog_logs_haproxy component_type=datadog_logs}: vector::sinks::util::sink: No batches; driving service to completion.

bug

Source

szibis

All 14 comments

@szibis I'm struggling to reproduce this.

Is your account definitely with the US region and not EU? You should get a 403 response rather than a 400 if this was the case, but it's worth checking. It isn't necessary to include both the endpoint and region settings. endpoint takes priority, but it should be ok to just delete this unless you are testing locally.

Would you be able to share the config for the "nginx-access" and "nginx-error" sources. Maybe there is something there?

FungusHumungus on 26 Oct 2020

Yes, the region is the US.

The configuration works on TCP sink on 0.10.0 without issues with all the nginx pipelines.

Is this endpoint form is valid ?? endpoint = "https://http-intake.logs.datadoghq.com:443"

szibis on 26 Oct 2020

Yeah, that endpoint looks correct. I'm testing against the eu endpoint -

endpoint = "https://http-intake.logs.datadoghq.eu:443"

I am sending 1000 nginx messages through without a problem. I am sending the raw nginx messages though. Hence, I am wondering if perhaps your "nginx-access" source is doing some additional processing to the messages that I am missing which is causing the datadog endpoint to see them as invalid.

FungusHumungus on 26 Oct 2020

I found only that -https://github.com/DataDog/datadog-agent/issues/3158

szibis on 26 Oct 2020

An invalid API key should be picked up by the healthcheck.

Are you getting the API key from https://app.datadoghq.com/account/settings#api?

FungusHumungus on 26 Oct 2020

The same is used in TCP logs. Checking all things.

szibis on 26 Oct 2020

Yes same is used by Telegraf and dd-agent on this box. Double-check that.

szibis on 26 Oct 2020

Oct 26 13:24:58 ip-10-105-195-46 vector[19804]: Oct 26 13:24:58.149 ERROR vector::topology::builder: Healthcheck: Failed Reason: Server returned unexpected error status: 400 Bad Request body: <html><body><h1>400 Bad request</h1>

szibis on 26 Oct 2020

Hi @szibis Can you share the rest of the config so we can confirm the events are valid? Thanks!

jamtur01 on 26 Oct 2020

I have fixed all coming from https://github.com/timberio/vector/issues/4742 but still, this exists for logs. Will provide config soon.

szibis on 26 Oct 2020

Ok. I think this one also is connected with my env variables. Sorry for this issues alert.

Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.183 DEBUG http: vector::http: Response. status=200 version=HTTP/1.1
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.259 DEBUG http: vector::http: Response. status=200 version=HTTP/1.1
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.266 DEBUG http: vector::http: Sending request. uri=https://http-intake.logs.datadoghq.com:443/v1/input method=POST
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.274 DEBUG http: vector::http: Sending request. uri=https://http-intake.logs.datadoghq.com:443/v1/input method=POST
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.278 DEBUG http: vector::http: Sending request. uri=https://http-intake.logs.datadoghq.com:443/v1/input method=POST
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.283 DEBUG http: vector::http: Sending request. uri=https://http-intake.logs.datadoghq.com:443/v1/input method=POST
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.350 DEBUG http: vector::http: Response. status=200 version=HTTP/1.1
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.367 DEBUG http: vector::http: Response. status=200 version=HTTP/1.1
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.373 DEBUG http: vector::http: Response. status=200 version=HTTP/1.1
Oct 26 13:46:05 ip-10-105-195-46 vector[14019]: Oct 26 13:46:05.412 DEBUG http: vector::http: Response. status=200 version=HTTP/1.1

Because we are loading all env variables from unit definition and default package just wiping this when updating manually.

This is our Unit file:

[Unit]
Description=Vector
Documentation=https://vector.dev
After=network-online.target
Requires=network-online.target

[Service]
User=vector
Group=vector
ExecStart=/usr/bin/vector -v
ExecReload=/bin/kill -HUP $MAINPID
Restart=no
AmbientCapabilities=CAP_NET_BIND_SERVICE
EnvironmentFile=/etc/default/vector

[Install]
WantedBy=multi-user.target

I forgot about this when updating the package for testing on this box.

As remediation is this possible to add some EnvironmentFile=/etc/default/vector or any other option to easily provide env variables file via default package ??

szibis on 26 Oct 2020

👍1

@szibis See #4748

jamtur01 on 26 Oct 2020

❤1

@szibis

I agree that supporting an EnvironmentFile in the shipped systemd config would be helpful. For now, you can use systemctl edit vector to edit an override file to add additional directives that will be merged with the unit file shipped with the package (this file will not be overwritten).