4

I am trying to make a periodic backup (OnCalendar=daily) to my dropbox via rclone. Since this runs on a laptop, I use Persistent=true. If I wake up the laptop, it takes a few seconds until the network is up. It is therefore expected, that the first attempt after wake up fails. However, I do not understand why I get the Start request repeated too quickly error.

systemctl cat --user rclone-copy-dropbox.timer

[Install]
WantedBy=timers.target

[Timer]
OnCalendar=daily
Persistent=true
RandomizedDelaySec=10m

[Unit]
Description=rclone copy to dropbox

systemctl cat --user rclone-copy-dropbox.service

[Service]
ExecStart=rclone copy dropbox: /home/me/dropbox --bwlimit 10M:20M --config=/home/me/rclone.conf
Restart=on-failure
RestartSec=10m
Type=oneshot

[Unit]
After=graphical-session-pre.target
Description=rclone copy dropbox
OnFailure=notify-email@%n.service
StartLimitBurst=5
StartLimitIntervalSec=12h
Wants=graphical-session.target
X-RestartIfChanged=false

journalctl --user -u rclone-copy-dropbox.service

Jan 08 11:52:14 yoga systemd[8306]: Starting rclone copy dropbox...
Jan 08 11:52:16 yoga systemd[8306]: Finished rclone copy dropbox.
Jan 09 07:15:44 yoga systemd[8306]: Starting rclone copy dropbox...
Jan 09 07:15:44 yoga rclone[2215956]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 09 07:15:44 yoga rclone[2215956]: ERROR : Attempt 1/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 09 07:15:44 yoga rclone[2215956]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 09 07:15:44 yoga rclone[2215956]: ERROR : Attempt 2/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 09 07:15:44 yoga rclone[2215956]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 09 07:15:44 yoga rclone[2215956]: ERROR : Attempt 3/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 09 07:15:44 yoga rclone[2215956]: Failed to copy: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 09 07:15:44 yoga systemd[8306]: rclone-copy-dropbox.service: Main process exited, code=exited, status=1/FAILURE
Jan 09 07:15:44 yoga systemd[8306]: rclone-copy-dropbox.service: Failed with result 'exit-code'.
Jan 09 07:15:44 yoga systemd[8306]: Failed to start rclone copy dropbox.
Jan 09 07:25:44 yoga systemd[8306]: rclone-copy-dropbox.service: Scheduled restart job, restart counter is at 1.
Jan 09 07:25:44 yoga systemd[8306]: Stopped rclone copy dropbox.
Jan 09 07:25:44 yoga systemd[8306]: rclone-copy-dropbox.service: Start request repeated too quickly.
Jan 09 07:25:44 yoga systemd[8306]: rclone-copy-dropbox.service: Failed with result 'exit-code'.
Jan 09 07:25:44 yoga systemd[8306]: Failed to start rclone copy dropbox.
Jan 09 07:25:44 yoga systemd[8306]: rclone-copy-dropbox.service: Triggering OnFailure= dependencies.
lines 1853-1892/1892 (END)

According to the config, there should be up to 5 attempts within a 12-hour period, before a failure is triggered. What is wrong with my reasoning?

Edit: The version is systemd 252 (252.1)

Running the service directly works as expected.

systemctl reset-failed --user rclone-copy-dropbox.service
systemctl start --user rclone-copy-dropbox.service

Jan 16 14:26:53 yoga systemd[7257]: Starting rclone copy dropbox...
Jan 16 14:26:54 yoga rclone[1412126]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:26:54 yoga rclone[1412126]: ERROR : Attempt 1/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:26:54 yoga rclone[1412126]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:26:54 yoga rclone[1412126]: ERROR : Attempt 2/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:26:54 yoga rclone[1412126]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:26:54 yoga rclone[1412126]: ERROR : Attempt 3/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:26:54 yoga rclone[1412126]: Failed to copy: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:26:54 yoga systemd[7257]: rclone-copy-dropbox.service: Main process exited, code=exited, status=1/FAILURE
Jan 16 14:26:54 yoga systemd[7257]: rclone-copy-dropbox.service: Failed with result 'exit-code'.
Jan 16 14:26:54 yoga systemd[7257]: Failed to start rclone copy dropbox.
Jan 16 14:36:54 yoga systemd[7257]: rclone-copy-dropbox.service: Scheduled restart job, restart counter is at 1.
Jan 16 14:36:54 yoga systemd[7257]: Stopped rclone copy dropbox.
Jan 16 14:36:54 yoga systemd[7257]: Starting rclone copy dropbox...
Jan 16 14:36:54 yoga rclone[1420729]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:36:54 yoga rclone[1420729]: ERROR : Attempt 1/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:36:54 yoga rclone[1420729]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:36:54 yoga rclone[1420729]: ERROR : Attempt 2/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:36:54 yoga rclone[1420729]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:36:54 yoga rclone[1420729]: ERROR : Attempt 3/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:36:54 yoga rclone[1420729]: Failed to copy: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:36:54 yoga systemd[7257]: rclone-copy-dropbox.service: Main process exited, code=exited, status=1/FAILURE
Jan 16 14:36:54 yoga systemd[7257]: rclone-copy-dropbox.service: Failed with result 'exit-code'.
Jan 16 14:36:54 yoga systemd[7257]: Failed to start rclone copy dropbox.
Jan 16 14:46:54 yoga systemd[7257]: rclone-copy-dropbox.service: Scheduled restart job, restart counter is at 2.
Jan 16 14:46:54 yoga systemd[7257]: Stopped rclone copy dropbox.
Jan 16 14:46:54 yoga systemd[7257]: Starting rclone copy dropbox...
Jan 16 14:46:54 yoga rclone[1427795]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:46:54 yoga rclone[1427795]: ERROR : Attempt 1/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:46:54 yoga rclone[1427795]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:46:54 yoga rclone[1427795]: ERROR : Attempt 2/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:46:54 yoga rclone[1427795]: ERROR : Dropbox root '': error reading source root directory: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:46:54 yoga rclone[1427795]: ERROR : Attempt 3/3 failed with 1 errors and: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:46:54 yoga rclone[1427795]: Failed to copy: Post "https://api.dropboxapi.com/2/files/list_folder": dial tcp: lookup api.dropboxapi.com: no such host
Jan 16 14:46:54 yoga systemd[7257]: rclone-copy-dropbox.service: Main process exited, code=exited, status=1/FAILURE
Jan 16 14:46:54 yoga systemd[7257]: rclone-copy-dropbox.service: Failed with result 'exit-code'.
Jan 16 14:46:54 yoga systemd[7257]: Failed to start rclone copy dropbox.
...
Manuel Schmidt
  • 175
  • 8
  • What systemd version do you have? – Edgar Magallon Jan 16 '23 at 03:20
  • @EdgarMagallon systemd 252 (252.1) – Manuel Schmidt Jan 16 '23 at 06:03
  • And what happens if you run the service directly, without using the systemd timer? Is this repeated 5 times? – Edgar Magallon Jan 16 '23 at 09:30
  • You may need `RemainAfterExit=yes` in the service section. I think it would deactivate after running the command otherwise. Also, have you considered waiting for network: `After=systemd-networkd-wait-online.service` (depends if available and properly configured) – rudib Jan 16 '23 at 11:57
  • @EdgarMagallon Running the service directly repeats 5 times until failure is triggered (see edit). – Manuel Schmidt Jan 16 '23 at 13:49
  • @rulib Could you please elaborate? I think `RemainAfterExit=yes` is wrong for a backup script which does not change any state. – Manuel Schmidt Jan 16 '23 at 13:55
  • my bad - and it's working if you start it manually. Are you sure that it didn't just hit the quota then? (of 5 restarts in 12h?). You can check with `systemctl show --user rclone-copy-dropbox.service -p NRestarts`. If you try manually, the limit will be ignored. – rudib Jan 16 '23 at 14:56
  • @rudib The first log shows, that the unit run successfully at Jan 08 11:52:16. The next start at Jan 09 07:15:44 fails after only one retry. The limit is not ignored when started manually. I had to reset the counter. – Manuel Schmidt Jan 16 '23 at 15:08
  • Are you able to reproduce the problem with an MCVE (`ExecStart=/bin/false`)? It looks like `Restart=5m` is not being respected. I normally use `1min` but `1m` seems to work ok on my machine too, – Stewart Jan 16 '23 at 15:32
  • Is the service enabled? In that case it may be started not just by the timer. Have you tried starting the timer and seeing what happens then? – rudib Jan 16 '23 at 15:38
  • @Stewart It is `RestartSec=10m` which seems to be respected. I will reproduce with a minimal example. For now, I suspect the problem to be `Persistent=true`. – Manuel Schmidt Jan 16 '23 at 17:11
  • @ManuelSchmidt I was unable to reproduce this behavior. Maybe this is a bug? In my case the systemd version is: `252.4` and the service is restarted either it's run directly or by the timer. Maybe if you upgrade systemd (or try in another machine) will work. – Edgar Magallon Jan 16 '23 at 21:37
  • I also tested on Ubuntu server with systemd version `249.11` and works too (both tests I assigned a short time). I don't think this resolves the issue but might be necessary to add these directives: `TimeoutStopSec=infinity` and `RemainAfterExit=no` in `[Service]` section – Edgar Magallon Jan 16 '23 at 21:59

1 Answers1

0

Why not have the service only run after the network is up and online?

After=network-online.target
Wants=network-online.target

Then after the laptop wakes up and the network is up, then the service runs.

TechLoom
  • 11
  • 2
  • This is a very unreliable workaround. See e.g. https://unix.stackexchange.com/questions/209832/debian-systemd-network-online-target-not-working Moreover, I would like to know the root cause of my issue. – Manuel Schmidt Jan 16 '23 at 15:42
  • 1
    I would look at the timer you made, right now you are just looking at the system log for service only. Look at both of them in the log. In your timer, you have RandomizedDelaySec set to 10mins from what I understand this will select between 0 and 10mins to run the service. Most likely it's the timer firing off the service. – TechLoom Jan 16 '23 at 18:55