search

containrrr / watchtower

A process for automating Docker container base image updates.
https://containrrr.dev/watchtower/
Apache License 2.0
19.81k stars 873 forks source link

Watchtower logs "Failed to send shoutrrr notification" when not configured for shoutrrr #1374

Open kjnicoletti opened 2 years ago

kjnicoletti commented 2 years ago

When configured WATCHTOWER_NOTIFICATIONS="email", the logs show an error "Failed to send shoutrrr notification".

docker logs watchtower
  time="2022-09-04T15:04:06-05:00" level=info msg="Watchtower 1.4.0"
  time="2022-09-04T15:04:06-05:00" level=info msg="Using notifications: smtp"
  time="2022-09-04T15:04:06-05:00" level=info msg="Only checking containers using enable label"
  time="2022-09-04T15:04:06-05:00" level=info msg="Scheduling first run: 2022-09-05 05:00:00 -0500 CDT"
  time="2022-09-04T15:04:06-05:00" level=info msg="Note that the first check will be performed in 13 hours, 55 minutes, 53 seconds"
  time="2022-09-04T15:04:18-05:00" level=error msg=**"Failed to send shoutrrr notification"** error="failed to send using smtp: timed out" index=0 notify=no service=smtp

Email does work, shortly after starting the container, I receive this email:

from Watchtower <***@gmail.com>
to me

Watchtower 1.4.0
Using notifications: smtp
Only checking containers using enable label
Scheduling first run: 2022-09-05 05:00:00 -0500 CDT
Note that the first check will be performed in 13 hours, 55 minutes, 53 seconds

The environmental variable WATCHTOWER_NOTIFICATIONS has an option for shoutrrr, but the container was not started with this option, so why is Watchtower trying to send a shoutrrr notification?

To Reproduce

start the container: 

docker run \
  --detach \
  --name watchtower \
  --restart unless-stopped \
  --env TZ="America/Chicago" \
  --env WATCHTOWER_NOTIFICATIONS="email" \
  --env WATCHTOWER_NOTIFICATION_EMAIL_FROM=***@gmail.com \
  --env WATCHTOWER_NOTIFICATION_EMAIL_TO=***@gmail.com \
  --env WATCHTOWER_NOTIFICATION_EMAIL_SERVER=smtp.gmail.com \
  --env WATCHTOWER_NOTIFICATION_EMAIL_SERVER_PORT=587 \
  --env WATCHTOWER_NOTIFICATION_EMAIL_SERVER_USER=***@gmail.com \
  --env WATCHTOWER_NOTIFICATION_EMAIL_SERVER_PASSWORD=*** \
  --env WATCHTOWER_NOTIFICATION_EMAIL_DELAY=2 \
  --env WATCHTOWER_NOTIFICATIONS_HOSTNAME=*** \
  --env WATCHTOWER_SCHEDULE="0 0 5 * * *" \
  --env WATCHTOWER_LABEL_ENABLE=true \
  --env WATCHTOWER_CLEANUP=true \
  --volume /var/run/docker.sock:/var/run/docker.sock \
  --label com.centurylinklabs.watchtower.enable=true \
  containrrr/watchtower

wait a minute, then pull the logs: docker logs watchtower

Expected behavior

When not configured for shoutrrr notifications, the container should not log an error that shoutrrr notification failed.

Platform Ubuntu 22.04.1 LTS Architecture x86_64

docker version
Client: Docker Engine - Community
 Version:           20.10.17
 API version:       1.41
 Go version:        go1.17.11
 Git commit:        100c701
 Built:             Mon Jun  6 23:02:46 2022
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.17
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.17.11
  Git commit:       a89b842
  Built:            Mon Jun  6 23:00:51 2022
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.8
  GitCommit:        9cd3357b7fd7218e4aec3eae239db1f68a5a6ec6
 runc:
  Version:          1.1.4
  GitCommit:        v1.1.4-0-g5fd4c4d
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Watchtower debug logs:

docker logs watchtower
time="2022-09-04T16:18:13-05:00" level=debug
time="2022-09-04T16:18:13-05:00" level=debug msg="Sleeping for a second to ensure the docker api client has been properly initialized."
time="2022-09-04T16:18:14-05:00" level=debug msg="Making sure everything is sane before starting"
time="2022-09-04T16:18:14-05:00" level=debug msg="Retrieving running containers"
time="2022-09-04T16:18:15-05:00" level=debug msg="There are no additional watchtower containers"
time="2022-09-04T16:18:15-05:00" level=debug msg="Watchtower HTTP API skipped."
time="2022-09-04T16:18:15-05:00" level=info msg="Watchtower 1.4.0"
time="2022-09-04T16:18:15-05:00" level=info msg="Using notifications: smtp"
time="2022-09-04T16:18:15-05:00" level=info msg="Only checking containers using enable label"
time="2022-09-04T16:18:15-05:00" level=info msg="Scheduling first run: 2022-09-05 05:00:00 -0500 CDT"
time="2022-09-04T16:18:15-05:00" level=info msg="Note that the first check will be performed in 12 hours, 41 minutes, 44 seconds"
time="2022-09-04T16:18:27-05:00" level=error msg="Failed to send shoutrrr notification" error="failed to send using smtp: timed out" index=0 notify=no service=smtp
github-actions[bot] commented 2 years ago

Hi there! 👋🏼 As you're new to this repo, we'd like to suggest that you read our code of conduct as well as our contribution guidelines. Thanks a bunch for opening your first issue! 🙏

piksel commented 2 years ago

shoutrrr is the notification library that watchtower uses. the email notifications map to shoutrrrs smtp service. the time out could be due to a number of things, but for some reason it takes longer than 10 seconds to send the e-mail, which is why the error is logged.

kirbylink commented 2 years ago

I am not sure, if my problem is the same because i switched to the new notification url, but i also get a time out. When setting WATCHTOWER_NO_STARTUP_MESSAGE=false i also get notified, so the notification url seems to be working. But in my case i see two more bugs:

docker-compose.yml:

version: "3"
services:
  watchtower:
    container_name: watchtower
    restart: unless-stopped
    image: containrrr/watchtower
    network_mode: bridge
    environment:
      - WATCHTOWER_MONITOR_ONLY=false
      - WATCHTOWER_SCHEDULE=@midnight
      - WATCHTOWER_NO_STARTUP_MESSAGE=true
      - WATCHTOWER_NOTIFICATION_URL=${WATCHTOWER_NOTIFICATION_URL}
      - WATCHTOWER_NOTIFICATIONS_HOSTNAME=${WATCHTOWER_NOTIFICATIONS_HOSTNAME}
      - WATCHTOWER_NOTIFICATION_DELAY=300
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
      - /etc/localtime:/etc/localtime:ro
    labels:
      - "io.portainer.accesscontrol.users=${PORTAINER_USER}"

Watchtower logs (unfortunately without debug)

time="2022-11-27T12:50:06+01:00" level=info msg="Watchtower 1.5.1" notify=no
time="2022-11-27T12:50:06+01:00" level=info msg="Using notifications: smtp, gotify" notify=no
time="2022-11-27T12:50:06+01:00" level=info msg="Checking all containers (except explicitly disabled with label)" notify=no
time="2022-11-27T12:50:06+01:00" level=info msg="Scheduling first run: 2022-11-28 00:00:00 +0100 CET" notify=no
time="2022-11-27T12:50:06+01:00" level=info msg="Note that the first check will be performed in 11 hours, 9 minutes, 53 seconds" notify=no
time="2022-11-28T00:00:20+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/openvpn:latest image (8327dc2e3bf0)"
time="2022-11-28T00:00:20+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/openvpn:latest image (8327dc2e3bf0)"
time="2022-11-28T00:00:21+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/openvpn:latest image (8327dc2e3bf0)"
time="2022-11-28T00:00:21+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/openvpn:latest image (8327dc2e3bf0)"
time="2022-11-28T00:00:27+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/sftp:latest image (f55d431e8ae1)"
time="2022-11-28T00:00:31+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/unbound-cron:latest image (8f2d415458c1)"
time="2022-11-28T00:00:33+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/unbound:latest image (c8059cc6d012)"
time="2022-11-28T00:00:50+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/cups:latest image (d94ab7fc81a4)"
time="2022-11-28T00:01:02+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/apache-archiva:latest image (3e6b70a66c23)"
time="2022-11-28T00:01:11+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/apt-cacher-ng:latest image (ac1fa07872a8)"
time="2022-11-28T00:01:55+01:00" level=info msg="Found new pihole/pihole:latest image (b4977f2fe155)"
time="2022-11-28T00:02:05+01:00" level=info msg="Stopping /pihole (fd1f1b795da2) with SIGTERM"
time="2022-11-28T00:02:13+01:00" level=info msg="Stopping /apt-cacher-ng (ffcdfd869a5f) with SIGTERM"
time="2022-11-28T00:02:24+01:00" level=info msg="Stopping /apache-archiva (78e9e6a36749) with SIGTERM"
time="2022-11-28T00:02:35+01:00" level=info msg="Stopping /cups (da1480340c61) with SIGTERM"
time="2022-11-28T00:02:45+01:00" level=info msg="Stopping /pihole-unbound (9974159d15df) with SIGTERM"
time="2022-11-28T00:02:46+01:00" level=info msg="Stopping /pihole-unbound-cron (cd2b38a946cc) with SIGTERM"
time="2022-11-28T00:02:57+01:00" level=info msg="Stopping /kodi_sftp (80c0b62174b7) with SIGTERM"
time="2022-11-28T00:02:58+01:00" level=info msg="Stopping /openvpn-full-https (b778e738846c) with SIGTERM"
time="2022-11-28T00:02:59+01:00" level=info msg="Stopping /openvpn-lan (db7d4fc411a0) with SIGTERM"
time="2022-11-28T00:03:01+01:00" level=info msg="Stopping /openvpn-full-ovpn (1163bc50d8bb) with SIGTERM"
time="2022-11-28T00:03:02+01:00" level=info msg="Stopping /openvpn-vpn-only (826f19a86545) with SIGTERM"
time="2022-11-28T00:03:03+01:00" level=info msg="Creating /openvpn-vpn-only"
time="2022-11-28T00:03:04+01:00" level=info msg="Creating /openvpn-full-ovpn"
time="2022-11-28T00:03:05+01:00" level=info msg="Creating /openvpn-lan"
time="2022-11-28T00:03:05+01:00" level=info msg="Creating /openvpn-full-https"
time="2022-11-28T00:03:06+01:00" level=info msg="Creating /kodi_sftp"
time="2022-11-28T00:03:08+01:00" level=info msg="Creating /pihole-unbound-cron"
time="2022-11-28T00:03:09+01:00" level=info msg="Creating /pihole-unbound"
time="2022-11-28T00:03:11+01:00" level=info msg="Creating /cups"
time="2022-11-28T00:03:12+01:00" level=info msg="Creating /apache-archiva"
time="2022-11-28T00:03:14+01:00" level=info msg="Creating /apt-cacher-ng"
time="2022-11-28T00:03:16+01:00" level=info msg="Creating /pihole"
time="2022-11-28T00:03:17+01:00" level=info msg="Session done" Failed=0 Scanned=47 Updated=11 notify=no
time="2022-11-28T00:03:27+01:00" level=error msg="Failed to send shoutrrr notification" error="failed to send using gotify: timed out" index=0 notify=no service=smtp
time="2022-11-28T00:03:27+01:00" level=error msg="Failed to send shoutrrr notification" error="failed to send using smtp: timed out" index=1 notify=no service=gotify

Should i open a new issue and post my findings there?

piksel commented 2 years ago

Hm, yeah, it looks like the timeout (10s) is not being adjusted for the delayed sending. The error comes 10s after the session is done, but obviously it would never complete before the deadline if it's set to wait 300s before sending.

Also, the error messages picking up the wrong service is likely due to go randomizing map iteration, a constant source of bugs unfortunately.

The original issue doesn't have a delay, and is more about shoutrrr being used to send email. Perhaps a new issue is better. It should be fairly easy fixes...

magisk317 commented 7 months ago

I seem to have encountered this problem, but the strange thing is that it was fine for the first two days and suddenly became bad. I am not sure what I did, but the configuration file should be the same as before. The specific situation is as follows:

log：

time="2024-04-29T23:57:01+08:00" level=warning msg="Using an HTTP url for Gotify is insecure"
time="2024-04-29T23:57:01+08:00" level=debug msg="Sleeping for a second to ensure the docker api client has been properly initialized."
time="2024-04-29T23:57:02+08:00" level=debug msg="Making sure everything is sane before starting"
time="2024-04-29T23:57:02+08:00" level=debug msg="Retrieving running containers"
time="2024-04-29T23:57:02+08:00" level=debug msg="There are no additional watchtower containers"
time="2024-04-29T23:57:02+08:00" level=debug msg="Watchtower HTTP API skipped."
time="2024-04-29T23:57:02+08:00" level=info msg="Watchtower 1.7.1"
time="2024-04-29T23:57:02+08:00" level=info msg="Using notifications: gotify"
time="2024-04-29T23:57:02+08:00" level=info msg="Checking all containers (except explicitly disabled with label)"
time="2024-04-29T23:57:02+08:00" level=info msg="Scheduling first run: 2024-04-30 05:57:02 +0800 CST"
time="2024-04-29T23:57:02+08:00" level=info msg="Note that the first check will be performed in 5 hours, 59 minutes, 59 seconds"
time="2024-04-29T23:57:12+08:00" level=error msg="Failed to send shoutrrr notification" error="failed to send using gotify: timed out" index=0 notify=no service=gotify

docker compose：

services:
  watchtower:
    image: containrrr/watchtower
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
    environment:
      WATCHTOWER_CLEANUP: "true"
      TZ: "Asia/Shanghai"
      WATCHTOWER_POLL_INTERVAL: "21600"
      WATCHTOWER_NOTIFICATIONS: "gotify"
      WATCHTOWER_NOTIFICATION_GOTIFY_URL: "http://10.0.0.11:99/"
      WATCHTOWER_NOTIFICATION_GOTIFY_TOKEN: "***************"
      WATCHTOWER_NOTIFICATION_REPORT: "true"
      WATCHTOWER_DEBUG: "1"
      WATCHTOWER_NOTIFICATION_TEMPLATE: |
       ......

Use this token to make a separate request through curl, and the result is OK： image You can also see the previous record in the screenshot. This notification was once OK.

MyWay commented 4 months ago

I am not sure, if my problem is the same because i switched to the new notification url, but i also get a time out. When setting WATCHTOWER_NO_STARTUP_MESSAGE=false i also get notified, so the notification url seems to be working. But in my case i see two more bugs:

  • First i set WATCHTOWER_NOTIFICATION_DELAY=300 but watchtower tries to send immediately after finishing it's work. I thought, this could be the problem. Gotify and Mail are also docker container, but as you can see in the logs, both are not updated and so still running
  • Secondly the error message seems to fetch the wrong service for logging purpose (because the startup messages were handled correctly). I use email and gotify and for email the log says service=gotify and for gotify the log says service=smtp

docker-compose.yml:

version: "3"
services:
  watchtower:
    container_name: watchtower
    restart: unless-stopped
    image: containrrr/watchtower
    network_mode: bridge
    environment:
      - WATCHTOWER_MONITOR_ONLY=false
      - WATCHTOWER_SCHEDULE=@midnight
      - WATCHTOWER_NO_STARTUP_MESSAGE=true
      - WATCHTOWER_NOTIFICATION_URL=${WATCHTOWER_NOTIFICATION_URL}
      - WATCHTOWER_NOTIFICATIONS_HOSTNAME=${WATCHTOWER_NOTIFICATIONS_HOSTNAME}
      - WATCHTOWER_NOTIFICATION_DELAY=300
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
      - /etc/localtime:/etc/localtime:ro
    labels:
      - "io.portainer.accesscontrol.users=${PORTAINER_USER}"

Watchtower logs (unfortunately without debug)

time="2022-11-27T12:50:06+01:00" level=info msg="Watchtower 1.5.1" notify=no
time="2022-11-27T12:50:06+01:00" level=info msg="Using notifications: smtp, gotify" notify=no
time="2022-11-27T12:50:06+01:00" level=info msg="Checking all containers (except explicitly disabled with label)" notify=no
time="2022-11-27T12:50:06+01:00" level=info msg="Scheduling first run: 2022-11-28 00:00:00 +0100 CET" notify=no
time="2022-11-27T12:50:06+01:00" level=info msg="Note that the first check will be performed in 11 hours, 9 minutes, 53 seconds" notify=no
time="2022-11-28T00:00:20+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/openvpn:latest image (8327dc2e3bf0)"
time="2022-11-28T00:00:20+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/openvpn:latest image (8327dc2e3bf0)"
time="2022-11-28T00:00:21+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/openvpn:latest image (8327dc2e3bf0)"
time="2022-11-28T00:00:21+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/openvpn:latest image (8327dc2e3bf0)"
time="2022-11-28T00:00:27+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/sftp:latest image (f55d431e8ae1)"
time="2022-11-28T00:00:31+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/unbound-cron:latest image (8f2d415458c1)"
time="2022-11-28T00:00:33+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/unbound:latest image (c8059cc6d012)"
time="2022-11-28T00:00:50+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/cups:latest image (d94ab7fc81a4)"
time="2022-11-28T00:01:02+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/apache-archiva:latest image (3e6b70a66c23)"
time="2022-11-28T00:01:11+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/apt-cacher-ng:latest image (ac1fa07872a8)"
time="2022-11-28T00:01:55+01:00" level=info msg="Found new pihole/pihole:latest image (b4977f2fe155)"
time="2022-11-28T00:02:05+01:00" level=info msg="Stopping /pihole (fd1f1b795da2) with SIGTERM"
time="2022-11-28T00:02:13+01:00" level=info msg="Stopping /apt-cacher-ng (ffcdfd869a5f) with SIGTERM"
time="2022-11-28T00:02:24+01:00" level=info msg="Stopping /apache-archiva (78e9e6a36749) with SIGTERM"
time="2022-11-28T00:02:35+01:00" level=info msg="Stopping /cups (da1480340c61) with SIGTERM"
time="2022-11-28T00:02:45+01:00" level=info msg="Stopping /pihole-unbound (9974159d15df) with SIGTERM"
time="2022-11-28T00:02:46+01:00" level=info msg="Stopping /pihole-unbound-cron (cd2b38a946cc) with SIGTERM"
time="2022-11-28T00:02:57+01:00" level=info msg="Stopping /kodi_sftp (80c0b62174b7) with SIGTERM"
time="2022-11-28T00:02:58+01:00" level=info msg="Stopping /openvpn-full-https (b778e738846c) with SIGTERM"
time="2022-11-28T00:02:59+01:00" level=info msg="Stopping /openvpn-lan (db7d4fc411a0) with SIGTERM"
time="2022-11-28T00:03:01+01:00" level=info msg="Stopping /openvpn-full-ovpn (1163bc50d8bb) with SIGTERM"
time="2022-11-28T00:03:02+01:00" level=info msg="Stopping /openvpn-vpn-only (826f19a86545) with SIGTERM"
time="2022-11-28T00:03:03+01:00" level=info msg="Creating /openvpn-vpn-only"
time="2022-11-28T00:03:04+01:00" level=info msg="Creating /openvpn-full-ovpn"
time="2022-11-28T00:03:05+01:00" level=info msg="Creating /openvpn-lan"
time="2022-11-28T00:03:05+01:00" level=info msg="Creating /openvpn-full-https"
time="2022-11-28T00:03:06+01:00" level=info msg="Creating /kodi_sftp"
time="2022-11-28T00:03:08+01:00" level=info msg="Creating /pihole-unbound-cron"
time="2022-11-28T00:03:09+01:00" level=info msg="Creating /pihole-unbound"
time="2022-11-28T00:03:11+01:00" level=info msg="Creating /cups"
time="2022-11-28T00:03:12+01:00" level=info msg="Creating /apache-archiva"
time="2022-11-28T00:03:14+01:00" level=info msg="Creating /apt-cacher-ng"
time="2022-11-28T00:03:16+01:00" level=info msg="Creating /pihole"
time="2022-11-28T00:03:17+01:00" level=info msg="Session done" Failed=0 Scanned=47 Updated=11 notify=no
time="2022-11-28T00:03:27+01:00" level=error msg="Failed to send shoutrrr notification" error="failed to send using gotify: timed out" index=0 notify=no service=smtp
time="2022-11-28T00:03:27+01:00" level=error msg="Failed to send shoutrrr notification" error="failed to send using smtp: timed out" index=1 notify=no service=gotify

Should i open a new issue and post my findings there?

Note that the environment variable is WATCHTOWER_NOTIFICATIONS_DELAY with a S at the end.