Timeout and multiple bugs when using new notification url #1485

kirbylink · 2022-11-29T07:58:34Z

Describe the bug

As discussed in #1374 i create a new issue for my problem.
I switched to the new notification url and among other things i get a time out when watchtower tries to send a notification after updating container.
When setting WATCHTOWER_NO_STARTUP_MESSAGE=false i will be notified, so the notification url seems to be correct.

Additional i found three more bugs:

When starting Watchtower with notify-upgrade and legacy setup for smtp and gotify, the url for gotify may not have been converted correctly:
According to documentation the url should be like
gotify://gotify.example.com:443/AzyoeNS.D4iJLVa/?title=Great+News&priority=1 but in my case Watchtower created an url like:
gotify://gotify.example.com:443/AzyoeNS.D4iJLVa?title=Great+News&priority=1 (without / after the token)
If needed, i can restore the old setup and post the complete anonymized created url.
Secondly i set WATCHTOWER_NOTIFICATION_DELAY=300 but watchtower tries to send immediately after updating the container.
Third the error message seems to fetch the wrong service for logging purpose (because the startup notification were handled correctly). For email the log says service=gotify and for gotify the log says service=smtp

Steps to reproduce

Create docker-compose file like:

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=false
      - 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}"

Create .env file like:

WATCHTOWER_NOTIFICATION_URL=smtp://<mail_address>:<password>@<host>:<port>/?auth=Plain&fromaddress=<from_address>&fromname=Watchtower&subject=&toaddresses=<to_address> gotify://<gotify_host>:<port>/<token>/?priority=5
WATCHTOWER_NOTIFICATIONS_HOSTNAME=<hostname>

start container with docker-compose up -d
Notification will be send after startup
Wait until watchtower starts at midnight and new container are available for updates.
Notification will not be send

Expected behavior

Delayed send of notification at least at midnight
Maybe also a delayed send at startup? Well it depends if delayed notification should also be done on startup. For this, i have no preferences or expectation

Screenshots

No response

Environment

Platform: Debian Bullseye (Linux 5.10.17-v8+)
Architecture: aarch64 (Raspberry Pi)
Docker version: Docker version 20.10.21, build baeda1f

Your logs

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

Additional context

No response

The text was updated successfully, but these errors were encountered:

piksel · 2022-11-29T15:17:19Z

The environment variable needs to be WATCHTOWER_NOTIFICATIONS_DELAY (plural). This is really inconsistent in watchtower but not easily fixable without #1253.

As for the notification error logs, they are identified in the order in which they are sent. But since they are each sending asynchronously, the errors will be in the order that they fail. The only real fix is to remove the service and index fields from the log until a a proper fix can be done in shoutrrr.

kirbylink · 2022-11-29T21:45:43Z

Okay, i copied the variable WATCHTOWER_NOTIFICATION_DELAY from https://containrrr.dev/watchtower/notifications/. I will change it and see what happens next :)

kirbylink · 2022-11-30T05:11:19Z

Okay, short update:
I changed the variable and this night i got a notification. But it was not after 5 minutes (delay = 300)

time="2022-11-29T22:41:28+01:00" level=info msg="Watchtower 1.5.1" notify=no
time="2022-11-29T22:41:28+01:00" level=info msg="Using notifications: smtp, gotify" notify=no
time="2022-11-29T22:41:28+01:00" level=info msg="Checking all containers (except explicitly disabled with label)" notify=no
time="2022-11-29T22:41:28+01:00" level=info msg="Scheduling first run: 2022-11-30 00:00:00 +0100 CET" notify=no
time="2022-11-29T22:41:28+01:00" level=info msg="Note that the first check will be performed in 1 hour, 18 minutes, 31 seconds" notify=no
time="2022-11-30T00:00:15+01:00" level=info msg="Found new phoenix.ipv64.de/kirbylink/apache-archiva:latest image (6bbd5e7f66e4)"
time="2022-11-30T00:01:45+01:00" level=info msg="Found new nextcloud:production-fpm-alpine image (c79d5390e28c)"
time="2022-11-30T00:01:48+01:00" level=info msg="Found new nextcloud:production-fpm-alpine image (c79d5390e28c)"
time="2022-11-30T00:01:55+01:00" level=info msg="Stopping /nextcloud_cron (db2faabfc385) with SIGTERM"
time="2022-11-30T00:02:08+01:00" level=info msg="Stopping /apache-archiva (c56568d83a29) with SIGTERM"
time="2022-11-30T00:02:19+01:00" level=info msg="Creating /apache-archiva"
time="2022-11-30T00:02:20+01:00" level=info msg="Creating /nextcloud_cron"
time="2022-11-30T00:02:22+01:00" level=info msg="Session done" Failed=0 Scanned=47 Updated=3 notify=no

If logs with debug are needed, i can try to force an update again.

piksel · 2022-11-30T09:35:17Z

When was the notification received? I don't think there will be any log entries even in debug when there are no problems sending...

kirbylink · 2022-11-30T18:08:56Z

The notification were received

for email at Wed, 30 Nov 2022 00:02:24 +0100 (header of mail)
for Gotify at 2022/11/30 - 00:02:22 (log of Gotify)

piksel · 2022-11-30T19:43:12Z

Yeah, it seems like the delay is broken. Haven't found the source of the problem, but I can at least reproduce it.

simskij · 2023-04-29T11:42:11Z

Okay, i copied the variable WATCHTOWER_NOTIFICATION_DELAY from https://containrrr.dev/watchtower/notifications/. I will change it and see what happens next :)

Are you still using it in singular form? If so, add the missing S. 👍🏼

kirbylink · 2023-05-05T04:50:16Z

Okay, i copied the variable WATCHTOWER_NOTIFICATION_DELAY from https://containrrr.dev/watchtower/notifications/. I will change it and see what happens next :)

Are you still using it in singular form? If so, add the missing S. 👍🏼

See the comments below this comment. I already changed the variable.
Additionally i added a PR to change the variable in the notifications.md

kirbylink · 2023-08-12T12:17:54Z

Will #1726 resolve the notification bug?

See comment from #1485 (comment)

piksel · 2023-08-12T12:22:08Z

@kirbylink, I think so. Not sure how I missed it when debugging it, though. Perhaps it was just me doing it without gopls/ide and not catching that the delay was not used.

kirbylink · 2023-10-12T23:44:00Z

@piksel could it be that this problem is fixed in the new versions?
It seems that the notification arrived at least after 5 minutes (WATCHTOWER_NOTIFICATIONS_DELAY is set to 300)
If so, we could close this issue

piksel · 2023-10-13T06:15:18Z

Yeah! Thanks

kirbylink added Priority: Medium Status: Available Type: Bug Unintended behavior labels Nov 29, 2022

kirbylink mentioned this issue Nov 29, 2022

docs: fix env variable name notification(s)-delay #1486

Merged

piksel mentioned this issue Aug 12, 2023

fix(notifications): correctly set the delay from options #1726

Merged

piksel added Status: Testing Needed A fix has been applied, but real-world testing is needed to confirm and removed Status: Available labels Aug 12, 2023

piksel closed this as completed Oct 13, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timeout and multiple bugs when using new notification url #1485

Timeout and multiple bugs when using new notification url #1485

kirbylink commented Nov 29, 2022 •

edited

Loading

piksel commented Nov 29, 2022

kirbylink commented Nov 29, 2022

kirbylink commented Nov 30, 2022

piksel commented Nov 30, 2022

kirbylink commented Nov 30, 2022 •

edited

Loading

piksel commented Nov 30, 2022

simskij commented Apr 29, 2023

kirbylink commented May 5, 2023

kirbylink commented Aug 12, 2023 •

edited

Loading

piksel commented Aug 12, 2023

kirbylink commented Oct 12, 2023

piksel commented Oct 13, 2023

Timeout and multiple bugs when using new notification url #1485

Timeout and multiple bugs when using new notification url #1485

Comments

kirbylink commented Nov 29, 2022 • edited Loading

Describe the bug

Steps to reproduce

Expected behavior

Screenshots

Environment

Your logs

Additional context

piksel commented Nov 29, 2022

kirbylink commented Nov 29, 2022

kirbylink commented Nov 30, 2022

piksel commented Nov 30, 2022

kirbylink commented Nov 30, 2022 • edited Loading

piksel commented Nov 30, 2022

simskij commented Apr 29, 2023

kirbylink commented May 5, 2023

kirbylink commented Aug 12, 2023 • edited Loading

piksel commented Aug 12, 2023

kirbylink commented Oct 12, 2023

piksel commented Oct 13, 2023

kirbylink commented Nov 29, 2022 •

edited

Loading

kirbylink commented Nov 30, 2022 •

edited

Loading

kirbylink commented Aug 12, 2023 •

edited

Loading