Restarting deluged via systemd causes errornous torrents

[krichter]

I'm managing deluged with the following systemd unit:

[Unit]
Description=Deluge Bittorrent daemon
Requires=network.target

[Service]
Type=simple
#forking
User=debian-deluged
Group=debian-deluged
LimitNOFILE=500000
ExecStart=/usr/bin/deluged --do-not-daemonize --config /var/lib/deluge/deluged/ --logfile /var/log/deluged/deluged.log

[Install]
WantedBy=multi-user.target

When I restart deluged with sudo systemctl stop deluged.service a random number of torrents is marked errornous and has to be force-rechecked.

#3028 is about corruption happening when the torrents are moved which is not the case in this issue - assuming that there's no move happening during restart.

experienced with 2.0.0.dev7019+fefe742+201705201502~ubuntu17.04.1 on Ubuntu 17.04

[Cas]

Did you see the stop timer on the wiki page:

​http://dev.deluge-torrent.org/wiki/UserGuide/Service/systemd#DelugeDaemondelugedService

Also you have not provided any logs so no idea what is occurring on stop.

[krichter]

Did you see the stop timer on the wiki page:

​​http://dev.deluge-torrent.org/wiki/UserGuide/Service/systemd#DelugeDaemondelugedService

I added it now (I always forget that deluge doesn't maintain the systemd unit in its package), but that doesn't change the issue.

Also you have not provided any logs so no idea what is occurring on stop.

Right, the log reveals

15:09:54.830 [ERROR   ][deluge.core.torrentmanager    :1158] on_alert_fastresume_rejected: manjaro-xfce-17.0.1-stable-i686.iso fast resume rejected. stat(/var/lib/deluge/complete/manjaro-xfce-17.0.1-stable-i686.iso): mismatching file timestamp
15:09:58.231 [ERROR   ][deluge.core.torrentmanager    :1158] on_alert_fastresume_rejected: manjaro-gnome-17.0.1-stable-i686.iso fast resume rejected. stat(/var/lib/deluge/complete/manjaro-gnome-17.0.1-stable-i686.iso): mismatching file timestamp

which I naively assume is the reason for failure. The file with mismatching timestamp correspond to the errornous files I see in deluge-gtk. I'm using different ZFS datasets for the incomplete/download and complete directory (0.6.5.9-5ubuntu4 on Ubuntu 17.04).

[Cas]

Need the log when shutting down...

[krichter]

Need the log when shutting down...

Until #3045 is fixed, I'll provide it at ​https://richtercloud.de:451/index.php/s/n5Un0j7xVcjxiTo (might not be available at all time because my WiFi? "router" has trouble with port forwarding).

[krzaku]

Same issue, same log line:

[ERROR   ] 02:00:53 torrentmanager:1147 on_alert_fastresume_rejected: Star.Trek.The.Next.Generation.S01-07.COMPLETE.1080p.BluRay.x264-MULTiGRP fast resume rejected: mismatching file timestamp

I'm on Unraid, deluge is running in a docker, and this happens when I stop that docker. This only happens for torrents that aren't fully downloaded yet. I'd provide a log but it contains a lot of private data that I wouldn't want posted online.

I noticed that when the error occurs, in logs there is no information about specific torrents saving resume data:

[DEBUG   ] 11:10:43 torrentmanager:1117 on_alert_save_resume_data
[DEBUG   ] 11:10:43 torrentmanager:769 Opening torrents fastresume file for load.
[INFO    ] 11:10:43 torrentmanager:780 Successfully loaded fastresume file: /config/state/torrents.fastresume
[DEBUG   ] 11:10:43 torrentmanager:821 Creating backup of fastresume at: /config/state/torrents.fastresume.bak
[INFO    ] 11:10:43 torrentmanager:826 Saving the fastresume at: /config/state/torrents.fastresume
[DEBUG   ] 11:10:43 alertmanager:124 portmap_log_alert: NAT-PMP: ==> port map [ mapping: 2 action: add proto: udp local: 58946 external: 58946 ttl: 3600 ]
[DEBUG   ] 11:10:44 alertmanager:124 portmap_log_alert: UPnP: broadcasting search for rootdevice
[DEBUG   ] 11:10:44 alertmanager:124 portmap_log_alert: UPnP: HTTP method m-search from 192.168.1.10:52336
[DEBUG   ] 11:10:44 alertmanager:124 portmap_log_alert: UPnP: HTTP method m-search from 192.168.1.10:1900
[DEBUG   ] 11:10:44 alertmanager:124 portmap_log_alert: UPnP: HTTP method m-search from 192.168.1.10:1900
[INFO    ] 11:10:45 daemon:196 Waiting for components to shutdown..
[DEBUG   ] 11:10:45 core:163 Core stopping...
[DEBUG   ] 11:10:45 torrentmanager:732 Creating backup of state at: /config/state/torrents.state.bak
[INFO    ] 11:10:45 torrentmanager:737 Saving the state at: /config/state/torrents.state

Notice how after on_alert_save_resume_data there are no torrents, while I usually have a line like that for every running torrent:

[DEBUG   ] 11:04:35 alertmanager:124 save_resume_data_alert: nnn resume data generated
[DEBUG   ] 11:04:35 torrentmanager:1117 on_alert_save_resume_data

[Cas]

With timestamp error I suspect that something (perhaps libtorrent) is touching the torrents after resume is written. I think that checking for timestamp has been removed from latest versions of libtorrent.

I shall look into catching and ignoring it.

[Cas]

So there is an option in the lt_config plugins ignore_resume_timestamps that you can enable if the data is not being modified, just the file timestamps.

What I might do is skip sending these particular torrents to Error state in the next release. This wouldn't stop them needing rechecking (if ignore_resume_timestamps setting is false) as it's part of libtorrent code.

[krzaku]

That fixed it for me, the torrents no longer end up needing a recheck. Although ltConfig might not always be there, so I think it'd be a good idea to add this option to Deluge itself.

[Cas]

Yeah I am likely to enable that setting permanently.

Disabled checking in develop: [85a1e478f]

[Cas]

Now also disabled in 1.3-stable: [5f0694deb]

[Cas]

Ticket retargeted after milestone deleted