Promtail Docker SD: sending all logs once again after stopping the target Docker container

[itsx]

Hello,

I have deployed promtail with new Docker service discovery feature (2.5.0). Logs from my target Docker containers are being shipped to Loki correctly. But when I stop the target container, all logs from the stopped container are send to Loki once again. After stopping the container I see all log lines from this container in Grafana twice.

Steps to reproduce the behavior:

1. Install promtail 2.5.0:

    sudo curl -O -L "https://github.com/grafana/loki/releases/download/v2.5.0/promtail-linux-arm64.zip"
    sudo unzip ./promtail-linux-arm64.zip
    sudo chmod a+x ./promtail-linux-arm64
    sudo vim config.yaml
    sudo mkdir /opt/promtail/
    sudo chmod 755 /opt/promtail

2. Start promtail binary: sudo ./promtail-linux-arm64 -config.file=./config.yaml

3. Start target Docker container: sudo docker run --name redis redis

4. Stop target Docker container: sudo docker stop redis

5. Check container logs in Grafana

I expect container log lines are send to Loki only once.

Environment:

• Infrastructure: ARM64 EC2 (t4g.micro), Ubuntu 20.04 LTS
• Loki: Grafana Cloud
• Grafana: Grafana Cloud

Promtail config:

server:
  http_listen_port: 3101
  grpc_listen_port: 0
  log_level: "debug"


clients:
  - url: https://****:***@logs-prod-us-central1.grafana.net/loki/api/v1/push
    batchsize: 104857600 # 10 MB

positions:
  filename: /opt/promtail/positions.yaml

scrape_configs:
  - job_name: docker
    docker_sd_configs:
      - host: unix:///var/run/docker.sock
        refresh_interval: 5s
    relabel_configs:
      - source_labels: ['__meta_docker_container_name']
        regex: '/(.*)'
        target_label: 'container'

Promtail log:

ssm-user@ip-10-0-99-157:/var/snap/amazon-ssm-agent/5780$ sudo ./promtail-linux-arm64 -config.file=./config.yaml
level=debug ts=2022-04-26T09:02:40.908244166Z caller=manager.go:265 component=docker_discovery msg="Starting provider" provider=docker/0 subs=map[docker/unix:///var/run/docker.sock:80:{}]
level=info ts=2022-04-26T09:02:40.911890337Z caller=server.go:260 http=[::]:3101 grpc=[::]:33659 msg="server listening on addresses"
level=info ts=2022-04-26T09:02:40.912105983Z caller=main.go:119 msg="Starting Promtail" version="(version=2.5.0, branch=HEAD, revision=2d9d0ee23)"
level=debug ts=2022-04-26T09:03:15.90923491Z caller=target.go:203 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="starting process loop" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=error ts=2022-04-26T09:03:15.909562457Z caller=target_group.go:95 msg="added Docker target" containerID=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:20.909054642Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:20.909108533Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:25.908882047Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:25.908951126Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:30.908508981Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:30.908579536Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:35.909177497Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:35.909234366Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:40.908421356Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:40.908513327Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:45.908960103Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:45.909032177Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:50.908941443Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:50.909161257Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:55.90935332Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:03:55.909463753Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:00.908330889Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:00.908587183Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:05.908870175Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:05.908926077Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:10.908565025Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:10.908619458Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:15.909036894Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:15.909292171Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:20.908585177Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:20.908907054Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:25.908861801Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:25.908921674Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:30.908981618Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:30.909036075Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:35.908792381Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:35.90887453Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:40.908938229Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:40.909036444Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:45.908886522Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:45.908946772Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:50.908938952Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:50.909041934Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:55.908542571Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:04:55.908596527Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:00.908752971Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:00.908848626Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:05.908792328Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:05.908848812Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:10.909038562Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:10.909092756Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:15.908399928Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:15.908456724Z caller=target.go:208 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="attempted to start process loop but it's already running" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=info ts=2022-04-26T09:05:16.861756534Z caller=target.go:122 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="finished transferring logs" written=1604 container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:16.861840086Z caller=target.go:134 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="done processing Docker logs" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:16.861870084Z caller=target.go:215 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="stopped Docker target" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:20.908763436Z caller=target_group.go:76 msg="container target already exists" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:20.908995813Z caller=target.go:203 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="starting process loop" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=info ts=2022-04-26T09:05:20.910227036Z caller=target.go:122 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="finished transferring logs" written=1604 container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:20.910380282Z caller=target.go:134 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="done processing Docker logs" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194
level=debug ts=2022-04-26T09:05:20.9104074Z caller=target.go:215 target=docker/a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194 msg="stopped Docker target" container=a24a9fe4c6e0528a9aad720f9e9354a4690da2b49b61e93d9fea56d594a71194

Docker container logs:

ssm-user@ip-10-0-99-157:/var/snap/amazon-ssm-agent/5780$ sudo docker --version
Docker version 20.10.14, build a224086
ssm-user@ip-10-0-99-157:/var/snap/amazon-ssm-agent/5780$ sudo docker run --name redis redis
1:C 26 Apr 2022 09:03:10.314 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1:C 26 Apr 2022 09:03:10.314 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=1, just started
1:C 26 Apr 2022 09:03:10.314 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
1:M 26 Apr 2022 09:03:10.314 * monotonic clock: POSIX clock_gettime
1:M 26 Apr 2022 09:03:10.315 * Running mode=standalone, port=6379.
1:M 26 Apr 2022 09:03:10.315 # Server initialized
1:M 26 Apr 2022 09:03:10.315 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
1:M 26 Apr 2022 09:03:10.316 * Ready to accept connections
1:signal-handler (1650963916) Received SIGTERM scheduling shutdown...
1:M 26 Apr 2022 09:05:16.824 # User requested shutdown...
1:M 26 Apr 2022 09:05:16.824 * Saving the final RDB snapshot before exiting.
1:M 26 Apr 2022 09:05:16.827 * DB saved on disk
1:M 26 Apr 2022 09:05:16.827 # Redis is now ready to exit, bye bye...

[jeschkies]

Thanks for posting this. Would you have the position file or the Promtail instance?

[abhidcoder]

are you sure about this command

sudo ./promtail-linux-arm64 -config.file=./config.yaml

didn't work in my case

[cstyan]

@itsx are you still seeing this issue?

[jpascal]

I have this issue too now. Tested on 2.9.2, 2.9.3, 2.9.4 versions

[cstyan]

I believe this would be resolved by the same fix as https://github.com/grafana/loki/issues/7103 (which was https://github.com/grafana/loki/pull/11563), though I don't think that's gone out in any public releases yet. You could try the current weekly release (which we're running ourselves atm) which would be k190.

[rnmsslido]

@cstyan is there an ETA to have this fix present in a public release?

[cstyan]

We have no set public release schedule for major, minor, or patch releases. However, the Loki 3.0 release went out this week and the promtail build for the same tag should contain the relevant fixes.