[Deluge] #3044: Restarting deluged via systemd causes errornous torrents

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: needs verified
Component: Unknown | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------

​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).

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:2>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: needs verified
Component: Unknown | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------

Comment (by Cas):

Need the log when shutting down...

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:3>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: needs verified
Component: Unknown | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------

Post by Deluge
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).

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:4>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: needs verified
Component: Unknown | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------

Comment (by 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`.

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:1>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: needs verified
Component: Unknown | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------

Comment (by 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
}}}

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
}}}

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:5>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: needs verified
Component: Unknown | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------

Comment (by 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.

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:6>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: 1.3.16
Component: Core | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------
Changes (by Cas):

* component: Unknown => Core
* milestone: needs verified => 1.3.16


Comment:

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.

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:7>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: 1.3.16
Component: Core | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------

Comment (by 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.

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:8>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: new
Priority: minor | Milestone: 1.3.16
Component: Core | Version: other (please specify)
Resolution: | Keywords:
-----------------------+------------------------------------

Comment (by Cas):

Yeah I am likely to enable that setting permanently.

Disabled checking in develop: [85a1e478f]

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:9>
Deluge <http://deluge-torrent.org/>
Deluge Project

[Deluge]

#3044: Restarting deluged via systemd causes errornous torrents
-----------------------+------------------------------------
Reporter: krichter | Owner:
Type: bug | Status: closed
Priority: minor | Milestone: 1.3.16
Component: Core | Version: other (please specify)
Resolution: Fixed | Keywords:
-----------------------+------------------------------------
Changes (by Cas):

* status: new => closed
* resolution: => Fixed


Comment:

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

--
Ticket URL: <http://dev.deluge-torrent.org/ticket/3044#comment:10>
Deluge <http://deluge-torrent.org/>
Deluge Project