desktop-linux icon indicating copy to clipboard operation
desktop-linux copied to clipboard

com.docker.backend posts a lot of messages to the syslog

Open alexgmin opened this issue 3 years ago • 9 comments

  • [x] I have tried with the latest version of Docker Desktop
  • [x] I have tried disabling enabled experimental features
  • [x] I have uploaded Diagnostics
  • Diagnostics ID: 8adbdc9e-543b-47a5-af6b-2e915cb94bb3/20221208095714

Expected behavior

Docker desktop doesn't spam with system logs with useless messages every time it makes an API call

Actual behavior

Docker Desktop logs stuff constantly. In one hour of running it, with some restarts, I have 12588 messages in the syslog from com.docker.backend

Information

  • Linux distro: Ubuntu
  • Distro version: 22.10
  • Docker Desktop Version: 4.15.0

Example logs: Dec 8 10:53:39 XXX com.docker.backend[185584]: [2022-12-08T09:53:39.848931691Z][com.docker.backend][I] (62bc03d1) 46c5db2e-BackendAPI S<-C Go-http-client/1.1 GET /forwards/list Dec 8 10:53:39 XXX com.docker.backend[185584]: [2022-12-08T09:53:39.849349802Z][com.docker.backend][I] (62bc03d1) 46c5db2e-BackendAPI S->C Go-http-client/1.1 GET /forwards/list (431.394µs): [] Dec 8 10:53:44 XXX com.docker.backend[185584]: [2022-12-08T09:53:44.900423176Z][com.docker.backend][I] (2ff80ede) 46c5db2e-BackendAPI S<-C Go-http-client/1.1 GET /forwards/list Dec 8 10:53:44 XXX com.docker.backend[185584]: [2022-12-08T09:53:44.901005188Z][com.docker.backend][I] (2ff80ede) 46c5db2e-BackendAPI S->C Go-http-client/1.1 GET /forwards/list (591.347µs): [] Dec 8 10:53:49 XXX com.docker.backend[185584]: [2022-12-08T09:53:49.952327518Z][com.docker.backend][I] (7782cca2) 46c5db2e-BackendAPI S<-C Go-http-client/1.1 GET /forwards/list Dec 8 10:53:49 XXX com.docker.backend[185584]: [2022-12-08T09:53:49.952768812Z][com.docker.backend][I] (7782cca2) 46c5db2e-BackendAPI S->C Go-http-client/1.1 GET /forwards/list (454.637µs): [] Dec 8 10:53:55 XXX com.docker.backend[185584]: [2022-12-08T09:53:54.999984712Z][com.docker.backend][I] (17db6ecb) 46c5db2e-BackendAPI S<-C Go-http-client/1.1 GET /forwards/list Dec 8 10:53:55 XXX com.docker.backend[185584]: [2022-12-08T09:53:55.000484688Z][com.docker.backend][I] (17db6ecb) 46c5db2e-BackendAPI S->C Go-http-client/1.1 GET /forwards/list (512.187µs): [] Dec 8 10:54:00 XXX com.docker.backend[185584]: [2022-12-08T09:54:00.053312531Z][com.docker.backend][I] (8fdcc5fa) 46c5db2e-BackendAPI S<-C Go-http-client/1.1 GET /forwards/list Dec 8 10:54:00 XXX com.docker.backend[185584]: [2022-12-08T09:54:00.054091338Z][com.docker.backend][I] (8fdcc5fa) 46c5db2e-BackendAPI S->C Go-http-client/1.1 GET /forwards/list (787.362µs): []

Steps to reproduce the behavior

  1. Install Docker desktop and run it. In my case I have a few compose projects, but the logging spam happens without them running

alexgmin avatar Dec 08 '22 10:12 alexgmin

There hasn't been any activity on this issue for a long time. If the problem is still relevant, mark the issue as fresh with a /remove-lifecycle stale comment. If not, this issue will be closed in 30 days.

Prevent issues from auto-closing with a /lifecycle frozen comment.

/lifecycle stale

docker-robott avatar Mar 08 '23 01:03 docker-robott

/remove-lifecycle stale

alexgmin avatar Mar 14 '23 14:03 alexgmin

/lifecycle frozen

thaJeztah avatar Apr 05 '23 07:04 thaJeztah

I upgraded to Ubuntu 23.04, which may be related, and I noticed that now it's even worse, I have 400k lines of this in 24 hours 2023-04-24T12:10:06.010906+02:00 PC com.docker.backend[25790]: [2023-04-24T10:10:06.010611098Z][com.docker.backend][I] (a359d3f6) 5f3d644f-BackendAPI S<-C Go-http-client/1.1 GET /forwards/list 2023-04-24T12:10:06.011084+02:00 PC com.docker.backend[25790]: [2023-04-24T10:10:06.010853311Z][com.docker.backend][I] (a359d3f6) 5f3d644f-BackendAPI S->C Go-http-client/1.1 GET /forwards/list (254.296µs): []

alexgmin avatar Apr 24 '23 10:04 alexgmin

Same here, on Ubuntu 22.04 (kernel 6.2.0), syslog gets flooded with docker.backend messages from the sort:

Oct 24 15:42:30 InfinityBook com.docker.backend[40489]: [2023-10-24T12:42:30.931416154Z][com.docker.backend.ipc][I] (057c7a81) 390f7270-idle C->S lifecycle GET /vm/disk-usage Oct 24 15:42:30 InfinityBook com.docker.backend[40489]: [2023-10-24T12:42:30.931485014Z][com.docker.backend.ipc][I] (20be60a5) 390f7270-idle C->S lifecycle GET /vm/ram-cpu-usage Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [#011common/cmd/com.docker.backend/supervisor/tasks/supervisor.go:74 +0xae Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [common/cmd/com.docker.backend/supervisor/tasks.Supervise.func2() Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [#011common/cmd/com.docker.backend/supervisor/tasks/supervisor.go:47 +0xc9 Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [common/cmd/com.docker.backend/supervisor/tasks.Supervise Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [#011common/cmd/com.docker.backend/supervisor/tasks/supervisor.go:46 +0x232 Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [2023-10-24T12:48:02.305493385Z][com.docker.backend.tasks][I] shutting down 1 tasks Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [2023-10-24T12:48:02.305512017Z][com.docker.backend.tasks][I] shutdown group 0/0: [docker] Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [2023-10-24T12:48:02.305530226Z][com.docker.backend.tasks][I] all 1 tasks shutdown Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: Services.startCLIMetrics: supervising tasks: task failed: shutdown with exit code<INT>: docker Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [2023-10-24T12:48:02.305819584Z][com.docker.backend.bugsnag][I] notifying bugsnag: Services.startCLIMetrics: supervising tasks: task failed: shutdown with exit code 125: docker Oct 24 15:48:02 InfinityBook com.docker.backend[40489]: [2023-10-24T12:48:02.596132305Z][com.docker.backend.services][I] CLI metrics failed: supervising tasks: task failed: shutdown with exit code 125: docker

stann1 avatar Oct 24 '23 12:10 stann1

Is there any solution to this issue?

sroziewski avatar Feb 07 '24 13:02 sroziewski

If you are running systemd, here is my workaround.

To prevent the log files from growing indefinitely, you have several options:

  1. set up a crontab job with a secondary user service docker-desktop-log.service to logrotate and restart the secondary service periodically. That's what I describe and set up below.
  2. Manually nuke the log files as you go along or automatically when you login.
  3. Redirect all the output to /dev/null in the systemctl --user edit docker-desktop.service instead of to a log file.

Option 3: Redirect to /dev/null

This is the simplest option. Execute:

systemctl --user edit docker-desktop.service

In your editor immediately below the line:

### Anything between here and the comment below will become the contents of the drop-in file

Paste the following:

[Service]
StandardError=null

That's a very blunt instrument, because now there are no logs for anything from docker-desktop.service. So below, I set out an alternative, implementing option 1.

Option 1: crontab

You will need a working cron system on your machine for this to work.

This option will redirect the logs from the syslog/journal to a dedicated log file, and to prevent that from filling your system, I implement a log rotation that compresses older logs and deletes old logs. I implement a secondary service to do this, because otherwise we would need to temporarily stop the docker-desktop.service every time we want to rotate the log files, stopping all of your containers in the process.

Edit docker-desktop.service (indirectly)

mkdir -p /home/$USER/.docker/logs/
systemctl --user edit docker-desktop.service

In your editor immediately below the line:

### Anything between here and the comment below will become the contents of the drop-in file

Paste the following:

[Unit]
Wants=docker-desktop-log.service
After=docker-desktop-log.service

[Service]
StandardError=file:/home/%u/.docker/logs/log.fifo

Secondary service

Create a secondary service that can be started and stopped without stopping the primary service. Execute:

mkdir -p /home/$USER/.docker/scripts

Create /home/$USER/.docker/scripts/docker-desktop-log.sh and paste the following into it:

#!/bin/bash

log_dir=/home/$USER/.docker/logs
log_fifo=${log_dir}/log.fifo
log_file=${log_dir}/docker-desktop.log
pid_file=${log_dir}/log.pid


if ! [ -d ${log_dir} ]; then
    mkdir -p ${log_dir}
fi

if ! [ -p ${log_fifo} ]; then
    /usr/bin/mkfifo ${log_fifo}
fi

nohup cat ${log_fifo} >> ${log_file} &
echo $! > ${pid_file}

Create /home/$USER/.docker/scripts/start-log.sh and paste the following into it:

#!/bin/bash
if systemctl --user is-active --quiet docker-desktop.service; then
   /usr/bin/systemctl --user start docker-desktop-log.service > /dev/null 2>/dev/null || true
fi

Make the scripts executable. Execute:

chmod a+x /home/$USER/.docker/scripts/{docker-desktop-log,start-log}.sh

Create a service file

create /home/$USER/.config/systemd/user/docker-desktop-log.service and paste the following into it:

[Unit]
Description=Stores log files for docker-desktop Service
PartOf=docker-desktop.service

[Service]
Type=simple
ExecStart=/home/%u/.docker/scripts/docker-desktop-log.sh
RemainAfterExit=yes
ExecStop=/bin/bash -c 'kill $(cat /home/%u/.docker/logs/log.pid) ; rm -f /home/%u/.docker/logs/log.pid'

There's no need to enable, start or stop it manually, as this will be done automatically when the docker-desktop.service is started/stopped, and by logrotate.

Restart the services. Execute:

systemctl --user daemon-reload
systemctl --user restart docker-desktop.service

logrotate

Make sure you have the logrotate program installed using your system's package manager.

Create a configuration file for it at $HOME/.config/logrotate.conf. Paste in the following:

/home/__USER__/.docker/logs/docker-desktop.log {
    daily
    rotate 7
    compress
    delaycompress
    missingok
    notifempty
    create 640 __USER__ __USER__
    prerotate
        /usr/bin/systemctl --user stop docker-desktop-log.service
    endscript
    postrotate
        /home/__USER__/.docker/scripts/start-log.sh
    endscript
}

Populate the file with the correct user name:

$ sed -i 's/__USER__/'$USER'/g' $HOME/.config/logrotate.conf

Set up logrotate to run daily

Execute:

$ crontab -e

Add the following line:

@daily /usr/bin/logrotate -s $HOME/.config/logrotate.status $HOME/.config/logrotate.conf

Conclusion

I'd like to say QED, but it wasn't all that simple TBH. It does work to prevent the journal from filling up with rubbish info logs from docker-desktop, but it shouldn't need to be so complicated! It's very frustrating that there are no options for controlling the log-level for com.docker.backend. This workaround really isn't a final solution, and this longstanding issue still needs to be fixed.

moriartynz avatar Feb 20 '24 15:02 moriartynz

Option 3: Redirect to /dev/null

This is the simplest option. Execute:

systemctl --user edit docker-desktop.service

In your editor immediately below the line:

Anything between here and the comment below will become the contents of the drop-in file

Paste the following:

StandardError=null

That's a very blunt instrument, because now there are no logs for anything from docker-desktop.service. So below, I set out an alternative, implementing option 1.

Based on my tests it you have to paste this

[Service]
StandardError=null

Otherwise you get this error /home/username/.config/systemd/user/docker-desktop.service.d/override.conf:1: Assignment outside of section. Ignoring.

However your comment actually solved the spamming, thanks a lot.

alexgmin avatar Feb 21 '24 08:02 alexgmin

Yes, sorry, missed a step ☺. I've updated my answer above.

Based on my tests it you have to paste this

[Service]
StandardError=null

Otherwise you get this error /home/username/.config/systemd/user/docker-desktop.service.d/override.conf:1: Assignment outside of section. Ignoring.

However your comment actually solved the spamming, thanks a lot.

I'm pleased it worked for you!

moriartynz avatar Feb 21 '24 11:02 moriartynz