vector sends thousands of log lines when it cannot read the logs from docker containers

[pgassmann]

Vector Version

vector 0.13.0 (v0.13.0 x86_64-unknown-linux-gnu 2021-04-21)

Docker version:
Docker version 20.10.5, build 55c4c88

Vector Configuration File

# Read logs from Docker API and Send to loki sink

[sources.docker-local]
  type = "docker_logs"
  docker_host = "/var/run/docker.sock"
  exclude_containers = []

  # Identify zero-width space as first line of a multiline block.
  multiline.condition_pattern = '^\x{200B}' # required
  multiline.mode = "halt_before" # required
  multiline.start_pattern = '^\x{200B}' # required
  multiline.timeout_ms = 1000 # required, milliseconds

[sinks.loki]
  # General
  type = "loki" # required
  inputs = ["docker-local"] # required
  endpoint = "https://logs.example.com:443" # required


  # Auth
  auth.strategy = "basic" # required
  auth.user = "" # required
  auth.password = "" # required

  # Encoding
  encoding.codec = "json" # required

  # Healthcheck
  healthcheck.enabled = true # optional, default


  # Labels
  labels.forwarder = 'vector'
  labels.host = '{{ host }}'
  labels.container_name = '{{ container_name }}'
  labels.compose_service = '{{ label.com\.docker\.compose\.service }}'
  labels.compose_project = '{{ label.com\.docker\.compose\.project }}'
  labels.source = '{{ stream }}'
  labels.category = 'dockerlogs'

Debug Output

Expected Behavior

• When vector cannot read docker logs, it should send minimal error message.
• the error messages/ retries should be rate limited.
• vector should log the problem on its own log

Actual Behavior

• Vector sends more than 7000 lines of error message per minute per container, including all container metadata
• Vector uses a lot of cpu resources in that case for processing/pushing all those messages

Example Data

Example message (without the metadata that is also sent):

�Error grabbing logs: error getting log reader: LogDriver.ReadLogs: logger does not exist for 888216b36e1adf224aea65ef1e6ffdcb67cf4697cf81b3f8bee402accc6cb32d

Full example message (json):

{
  "container_created_at": "2021-02-01T19:33:25.594887482Z",
  "container_id": "b15818d4115f46bde077f6f7c1e868c52616c4b552a1fe02bd812fe5bb752627",
  "container_name": "webproxy_nginx-web",
  "host": "dev2",
  "image": "nginx:alpine",
  "label.com.docker.compose.config-hash": "9f8bf9324321705d7a74f7ac9201b605ec741019540455cf295a16cea54c2cad",
  "label.com.docker.compose.container-number": "1",
  "label.com.docker.compose.oneoff": "False",
  "label.com.docker.compose.project": "webproxy",
  "label.com.docker.compose.project.config_files": "/container/webproxy/docker-compose.yml",
  "label.com.docker.compose.project.working_dir": "/container/webproxy",
  "label.com.docker.compose.service": "nginx-web",
  "label.com.docker.compose.version": "1.28.2",
  "label.com.github.jrcs.letsencrypt_nginx_proxy_companion.nginx_proxy": "true",
  "label.maintainer": "NGINX Docker Maintainers <[email protected]>",
  "message": "\u0003\u0000\u0000\u0000\u0000\u0000\u0000�Error grabbing logs: error getting log reader: LogDriver.ReadLogs: logger does not exist for b15818d4115f46bde077f6f7c1e868c52616c4b552a1fe02bd812fe5bb752627\n",
  "source_type": "docker",
  "stream": "console"
}

Full message as screenshot from grafana explore view of loki

Additional Context

The log driver in use was the loki docker log driver which sometimes got stuck. that's why we want to replace it with vector ;-)

But the problem could also be happening with other cases where vector cannot read logs.

References

[pgassmann]

This does not only happen with "broken" drivers, this also happens with build containers. During docker-compose build, vector writes thousands of lines to syslog and to the configured sink.

@jszwedko can you prioritize this and assign it to a milestone again?

[jszwedko]

@pgassmann to confirm, you are using the loki log driver in both cases? I do see a related issue grafana/loki#1368 . It's unclear to me if this is an issue with vector or the log driver just yet.

[pgassmann]

@jszwedko no, I don't use the loki driver anymore. There are other cases where vector cannot read the logs. With docker-compose build, containers are launched (in the background) where you cannot attach to the logs. also on the command line if you run docker logs <container> you get driver does not support reading. not dependent on docker-compose. with docker build it's the same.

root@webserver-test1 ~ # docker logs pedantic_kapitsa
Error response from daemon: configured logging driver does not support reading

In such cases vector tries hundreds times a second to connect to the logs and sends above mentioned error messages.

Example to reproduce:

Dockerfile :

FROM php:7-fpm

ADD https://github.com/mlocati/docker-php-extension-installer/releases/latest/download/install-php-extensions /usr/local/bin/

RUN set -ex && \
    \
    apt-get update && \
    apt-get install -y --no-install-recommends \
        git \
    && \
    chmod +x /usr/local/bin/install-php-extensions && sync && \
    install-php-extensions \
        gd \
        intl \
        imagick \
        opcache \
        zip \
        mcrypt \
        pdo_mysql \
        mysqli \
        xdebug \
        soap \
        apcu \
        && \
    rm -rf /var/lib/apt/lists/*

# Use the default production configuration
RUN mv "$PHP_INI_DIR/php.ini-production" "$PHP_INI_DIR/php.ini"

COPY php-override.ini /usr/local/etc/php/conf.d/override.ini

run docker build . and then in a separate terminal check docker ps and then docker logs random_name

[jszwedko]

Aha, gotcha, thanks for confirming @pgassmann

I can verify that if the log driver does not support reading, Vector does output continuous log messages.

Reproduce:

data_dir = "/var/lib/vector/"

[sources.source0]
auto_partial_merge = true
host_key = "host"
partial_event_marker_field = "_partial"
retry_backoff_secs = 2
type = "docker_logs"

[sinks.sink0]
inputs = ["source0"]
target = "stdout"
type = "console"

[sinks.sink0.encoding]
codec = "json"

[sinks.sink0.healthcheck]
enabled = true

[sinks.sink0.buffer]
type = "memory"
max_events = 500
when_full = "block"

I ran:

docker run --log-driver none --rm mingrammer/flog -l -d 100m

To generate unreadable logs.

I saw:

Jul 06 11:18:40.131  INFO vector::internal_events::docker_logs: Started watching for container logs. container_id=6b1fded2d4b935cb8928befdaa4881a55e7170e5c96a73b7132c08677c13b375
Jul 06 11:18:52.718  INFO vector::internal_events::docker_logs: Started watching for container logs. container_id=681297a85d06685498d814049631b585762b5071753c7731f69fa40a7acb9a77
Jul 06 11:18:52.721 ERROR vector::internal_events::docker_logs: Docker engine is not using either the `jsonfile` or `journald`
                logging driver. Please enable one of these logging drivers
                to get logs from the Docker daemon. error=DockerResponseServerError { status_code: 501, message: "{\"message\":\"configured logging driver does not support reading\"}\n" } container_id="68
1297a85d06685498d814049631b585762b5071753c7731f69fa40a7acb9a77" internal_log_rate_secs=10
Jul 06 11:18:52.721  INFO vector::internal_events::docker_logs: Stopped watching for container logs. container_id=681297a85d06685498d814049631b585762b5071753c7731f69fa40a7acb9a77
Jul 06 11:18:52.721  INFO vector::internal_events::docker_logs: Started watching for container logs. container_id=681297a85d06685498d814049631b585762b5071753c7731f69fa40a7acb9a77
Jul 06 11:18:52.726 ERROR vector::internal_events::docker_logs: Internal log [Docker engine is not using either the `jsonfile` or `journald`
                logging driver. Please enable one of these logging drivers
                to get logs from the Docker daemon.] is being rate limited.

Followed by a continuous stream of:

Jul 06 11:18:52.753  INFO vector::internal_events::docker_logs: Stopped watching for container logs. container_id=681297a85d06685498d814049631b585762b5071753c7731f69fa40a7acb9a77
Jul 06 11:18:52.753  INFO vector::internal_events::docker_logs: Started watching for container logs. container_id=681297a85d06685498d814049631b585762b5071753c7731f69fa40a7acb9a77

[ktff]

retry_backoff_secs option wasn't working properly hence the large amount of logs.

While regarding:

{
  "container_created_at": "2021-02-01T19:33:25.594887482Z",
  "container_id": "b15818d4115f46bde077f6f7c1e868c52616c4b552a1fe02bd812fe5bb752627",
  "container_name": "webproxy_nginx-web",
  "host": "dev2",
  "image": "nginx:alpine",
  "label.com.docker.compose.config-hash": "9f8bf9324321705d7a74f7ac9201b605ec741019540455cf295a16cea54c2cad",
  "label.com.docker.compose.container-number": "1",
  "label.com.docker.compose.oneoff": "False",
  "label.com.docker.compose.project": "webproxy",
  "label.com.docker.compose.project.config_files": "/container/webproxy/docker-compose.yml",
  "label.com.docker.compose.project.working_dir": "/container/webproxy",
  "label.com.docker.compose.service": "nginx-web",
  "label.com.docker.compose.version": "1.28.2",
  "label.com.github.jrcs.letsencrypt_nginx_proxy_companion.nginx_proxy": "true",
  "label.maintainer": "NGINX Docker Maintainers <[email protected]>",
  "message": "\u0003\u0000\u0000\u0000\u0000\u0000\u0000�Error grabbing logs: error getting log reader: LogDriver.ReadLogs: logger does not exist for b15818d4115f46bde077f6f7c1e868c52616c4b552a1fe02bd812fe5bb752627\n",
  "source_type": "docker",
  "stream": "console"
}

Those aren't logs from Vector, but a proper error message from Docker/log driver so that's working as intended, and depends on the log driver or Docker version. Although, the amount of events is too large, but that will also be solved with the linked PR.