Deluge
2013-03-07 15:03:01 UTC
#2291: Stop seed at ratio not respected with GUI closed
----------------------+-----------------------------------------------------
Reporter: michkrol | Owner:
Type: bug | Status: new
Priority: major | Milestone: Future
Component: other | Version: git master
Keywords: |
----------------------+-----------------------------------------------------
I'm using Windows 7 (x64), deluge from git/master (commit
2a3eb7b70cb5a71c741ffe105b51ee17cec11589), python 2.7 (32bit) and
libtorrent 0.16.8.0. After updating deluge, quite a while since last
update (January), I've encountered a problem: my "stop seed at ratio"
settings stopped working in some cases - the torrent would not stop when
hitting the ratio, but instead continue seeding indefinitely. It has
worked correctly before.
With little investigation, it turns out running deluged alone (without
GUI) is required for this error to occur.
If you let the daemon run for a while, then start the GUI, you can see the
torrents still running (with ratio long since reached), then they get
paused after a second or two. It's like the GUI refresh makes the daemon
realise the torrents should get paused because of the ratio, probably by
triggering some checks by querying for the ratio values (to display them).
Running the GUI (focused or even minimised) makes the "stop seed at ratio"
work correctly.
"Closing" the GUI to tray icon doesn't prevent the error from occurring.
I've managed to reproduce the behaviour with clean install/config.
----
Below are partial debug logs - only the parts that I think are relevant. I
can paste/attach full logs if necessary, but they're LONG and spammed with
messages totally irrelevant to this bug.
The torrent finishes downloading:
{{{
13:57:10.932 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_finished_alert: test_file.zip torrent finished downloading
13:57:10.932 [DEBUG ][deluge.core.alertmanager :81 ]
state_changed_alert: test_file.zip: state changed to: finished
13:57:10.932 [DEBUG ][deluge.core.alertmanager :81 ]
state_changed_alert: test_file.zip: state changed to: seeding
13:57:10.932 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_announce_alert: test_file.zip (udp://tracker.openbittorrent.com)
sending announce (completed)
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_finished
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
6cd42a2c22d12033a00ae0d562c2d2cbeed5902f is finished..
13:57:10.932 [DEBUG ][deluge.core.rpcserver :81 ] intevents: {}
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_state_changed
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_state_changed
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_announce
13:57:10.979 [DEBUG ][deluge.core.alertmanager :81 ]
storage_moved_alert: test_file.zip moved storage to:
R:\DelugeTest\Completed
13:57:10.979 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.zip resume data generated
13:57:10.979 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_storage_moved
13:57:10.979 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
13:57:10.979 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
}}}
Then there are only "tracker announce" and "fast_resume/torrent_state file
saved" messages, omitted for readability.
I run/connect with GUI, to check the torrents. The torrent gets paused as
it should (the ratio being reached long ago). Then I close the GUI and
shutdown the daemon:
{{{
14:02:24.975 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
torrent state file.
14:05:04.923 [INFO ][deluge.core.rpcserver :85 ] Deluge Client
connection made from: 127.0.0.1:23013
14:05:05.032 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
daemon.login
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
daemon.set_event_interest
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_known_accounts
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_auth_levels_mappings
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_state
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_config_values
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_config_values
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_config_values
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_enabled_plugins
14:05:05.126 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:05.126 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:05.126 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:05.126 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:05.173 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:05.173 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:07.056 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:07.134 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:07.181 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:07.181 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:08.072 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:08.072 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:08.072 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:09.049 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:09.052 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:09.122 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:09.169 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:09.169 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:10.032 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_announce_alert: test_file.zip
(udp://fr33domtracker.h33t.com:3310/announce) sending announce (stopped)
14:05:10.032 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_paused_alert: test_file.zip paused
14:05:10.032 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_announce
14:05:10.032 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_paused
14:05:10.032 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
14:05:10.032 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
14:05:10.032 [DEBUG ][deluge.core.rpcserver :81 ] intevents:
{1: [u'NewVersionAvailableEvent', u'PluginEnabledEvent',
u'TorrentResumedEvent', u'TorrentAddedEvent', u'TorrentRemovedEvent',
u'PluginDisabledEvent', u'SessionResumedEvent',
u'TorrentQueueChangedEvent', u'TorrentFileRenamedEvent',
u'TorrentFolderRenamedEvent', u'TorrentStateChangedEvent',
u'TorrentFinishedEvent', u'ConfigValueChangedEvent',
u'SessionPausedEvent']}
14:05:10.032 [DEBUG ][deluge.core.rpcserver :81 ] Emit Event:
TorrentStateChangedEvent ['6cd42a2c22d12033a00ae0d562c2d2cbeed5902f',
'Paused']
14:05:10.079 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.zip resume data generated
14:05:10.079 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
14:05:10.079 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
14:05:11.054 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:11.069 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:11.069 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:11.069 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:11.130 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:11.177 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:11.177 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:11.559 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
14:05:12.933 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
14:05:13.058 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:13.058 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:13.136 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:13.183 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:13.183 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:14.074 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:14.074 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:14.074 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:14.904 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
daemon.shutdown
14:05:14.904 [INFO ][deluge.core.daemon :85 ] Waiting for
components to shutdown..
14:05:14.904 [DEBUG ][deluge.core.core :81 ] Core
stopping...
14:05:14.919 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
torrent state file.
14:05:14.935 [INFO ][deluge.core.rpcserver :85 ] Deluge client
disconnected: Connection to the other side was lost in a non-clean
fashion: Connection lost.
14:05:14.935 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_paused_alert: test_file.zip paused
14:05:14.935 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.zip resume data generated
14:05:14.935 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_paused
14:05:14.935 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
14:05:14.935 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: True
14:05:14.935 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
14:05:14.935 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
14:05:14.951 [INFO ][twisted :532 ] (TLS Port
58846 Closed)
14:05:14.951 [INFO ][twisted :532 ] Stopping
factory <twisted.internet.protocol.Factory instance at 0x0375BE68>
14:05:14.951 [INFO ][twisted :532 ] Main loop
terminated.
14:05:14.951 [INFO ][deluge.core.daemon :85 ] Waiting for
components to shutdown..
}}}
----
Now, here's what happens when I leave the GUI running, so the "stop seed
at ratio" works. Log starts a dozen of seconds before the ratio is
reached, the torrent is being seeded:
{{{
13:40:49.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:51.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:51.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:40:53.815 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:55.813 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:55.813 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:40:57.815 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:59.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:59.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:01.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:03.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:03.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:05.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:07.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:07.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:09.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:11.813 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:11.813 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:13.815 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:15.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:15.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:16.680 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
13:41:16.680 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:16.680 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
13:41:16.680 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
13:41:16.690 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
13:41:16.710 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
13:41:16.710 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
13:41:17.825 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:18.268 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_announce_alert: test_file.rar (udp://tracker.ccc.de:80/announce)
sending announce (stopped)
13:41:18.268 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_announce_alert: test_file.rar
(udp://tracker.publicbt.com:80/announce) sending announce (stopped)
13:41:18.268 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_paused_alert: test_file.rar paused
13:41:18.268 [DEBUG ][deluge.core.alertmanager :81 ]
udp_error_alert: UDP error: Can't connect, remote host actively rejects
connection from: 0.0.0.0
13:41:18.268 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_announce
13:41:18.268 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_announce
13:41:18.268 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_paused
13:41:18.268 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:41:18.268 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
13:41:18.268 [DEBUG ][deluge.core.rpcserver :81 ] intevents:
{0: [u'NewVersionAvailableEvent', u'PluginEnabledEvent',
u'TorrentResumedEvent', u'TorrentAddedEvent', u'TorrentRemovedEvent',
u'PluginDisabledEvent', u'SessionResumedEvent',
u'TorrentQueueChangedEvent', u'TorrentFileRenamedEvent',
u'TorrentFolderRenamedEvent', u'TorrentStateChangedEvent',
u'TorrentFinishedEvent', u'ConfigValueChangedEvent',
u'SessionPausedEvent']}
13:41:18.268 [DEBUG ][deluge.core.rpcserver :81 ] Emit Event:
TorrentStateChangedEvent ['d45718d2c29e971ddb3099b27f8429fdba2d26c0',
'Paused']
13:41:18.318 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.rar resume data generated
13:41:18.318 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_reply_alert: test_file.rar
(udp://tracker.publicbt.com:80/announce) received peers: 0
13:41:18.318 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
13:41:18.318 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
13:41:18.318 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_reply: test_file.rar
(udp://tracker.publicbt.com:80/announce) received peers: 0
13:41:18.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
13:41:18.678 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
13:41:18.718 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
13:41:18.718 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
13:41:19.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
13:41:19.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:19.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
13:41:19.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:19.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:20.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
13:41:20.678 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
13:41:20.718 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
13:41:20.718 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
13:41:21.063 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
daemon.shutdown
13:41:21.063 [INFO ][deluge.core.daemon :85 ] Waiting for
components to shutdown..
13:41:21.063 [DEBUG ][deluge.core.core :81 ] Core
stopping...
13:41:21.073 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
torrent state file.
13:41:21.083 [INFO ][deluge.core.rpcserver :85 ] Deluge client
disconnected: Connection to the other side was lost in a non-clean
fashion: Connection lost.
13:41:21.113 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_paused_alert: test_file.rar paused
13:41:21.113 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.rar resume data generated
13:41:21.113 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_paused
13:41:21.113 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:41:21.113 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: True
13:41:21.113 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
13:41:21.113 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
13:41:21.113 [INFO ][twisted :532 ] (TLS Port
58846 Closed)
13:41:21.113 [INFO ][twisted :532 ] Stopping
factory <twisted.internet.protocol.Factory instance at 0x036BBE68>
13:41:21.113 [INFO ][twisted :532 ] Main loop
terminated.
13:41:21.113 [INFO ][deluge.core.daemon :85 ] Waiting for
components to shutdown..
}}}
As expected while running the GUI the log doesn't "stay silent", since the
GUI keeps getting updated stats every second or two.
Hope my logs and explanations are at least remotely useful.
Please tell me if/what additional info would be useful.
Thanks in advance for your time.
----------------------+-----------------------------------------------------
Reporter: michkrol | Owner:
Type: bug | Status: new
Priority: major | Milestone: Future
Component: other | Version: git master
Keywords: |
----------------------+-----------------------------------------------------
I'm using Windows 7 (x64), deluge from git/master (commit
2a3eb7b70cb5a71c741ffe105b51ee17cec11589), python 2.7 (32bit) and
libtorrent 0.16.8.0. After updating deluge, quite a while since last
update (January), I've encountered a problem: my "stop seed at ratio"
settings stopped working in some cases - the torrent would not stop when
hitting the ratio, but instead continue seeding indefinitely. It has
worked correctly before.
With little investigation, it turns out running deluged alone (without
GUI) is required for this error to occur.
If you let the daemon run for a while, then start the GUI, you can see the
torrents still running (with ratio long since reached), then they get
paused after a second or two. It's like the GUI refresh makes the daemon
realise the torrents should get paused because of the ratio, probably by
triggering some checks by querying for the ratio values (to display them).
Running the GUI (focused or even minimised) makes the "stop seed at ratio"
work correctly.
"Closing" the GUI to tray icon doesn't prevent the error from occurring.
I've managed to reproduce the behaviour with clean install/config.
----
Below are partial debug logs - only the parts that I think are relevant. I
can paste/attach full logs if necessary, but they're LONG and spammed with
messages totally irrelevant to this bug.
The torrent finishes downloading:
{{{
13:57:10.932 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_finished_alert: test_file.zip torrent finished downloading
13:57:10.932 [DEBUG ][deluge.core.alertmanager :81 ]
state_changed_alert: test_file.zip: state changed to: finished
13:57:10.932 [DEBUG ][deluge.core.alertmanager :81 ]
state_changed_alert: test_file.zip: state changed to: seeding
13:57:10.932 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_announce_alert: test_file.zip (udp://tracker.openbittorrent.com)
sending announce (completed)
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_finished
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
6cd42a2c22d12033a00ae0d562c2d2cbeed5902f is finished..
13:57:10.932 [DEBUG ][deluge.core.rpcserver :81 ] intevents: {}
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_state_changed
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_state_changed
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:57:10.932 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
13:57:10.932 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_announce
13:57:10.979 [DEBUG ][deluge.core.alertmanager :81 ]
storage_moved_alert: test_file.zip moved storage to:
R:\DelugeTest\Completed
13:57:10.979 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.zip resume data generated
13:57:10.979 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_storage_moved
13:57:10.979 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
13:57:10.979 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
}}}
Then there are only "tracker announce" and "fast_resume/torrent_state file
saved" messages, omitted for readability.
I run/connect with GUI, to check the torrents. The torrent gets paused as
it should (the ratio being reached long ago). Then I close the GUI and
shutdown the daemon:
{{{
14:02:24.975 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
torrent state file.
14:05:04.923 [INFO ][deluge.core.rpcserver :85 ] Deluge Client
connection made from: 127.0.0.1:23013
14:05:05.032 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
daemon.login
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
daemon.set_event_interest
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:05.079 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_known_accounts
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_auth_levels_mappings
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_state
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_config_values
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_config_values
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_config_values
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:05.095 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_enabled_plugins
14:05:05.126 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:05.126 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:05.126 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:05.126 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:05.173 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:05.173 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:07.056 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:07.134 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:07.181 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:07.181 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:08.072 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:08.072 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:08.072 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:09.049 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:09.052 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:09.122 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:09.169 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:09.169 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:10.032 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_announce_alert: test_file.zip
(udp://fr33domtracker.h33t.com:3310/announce) sending announce (stopped)
14:05:10.032 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_paused_alert: test_file.zip paused
14:05:10.032 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_announce
14:05:10.032 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_paused
14:05:10.032 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
14:05:10.032 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
14:05:10.032 [DEBUG ][deluge.core.rpcserver :81 ] intevents:
{1: [u'NewVersionAvailableEvent', u'PluginEnabledEvent',
u'TorrentResumedEvent', u'TorrentAddedEvent', u'TorrentRemovedEvent',
u'PluginDisabledEvent', u'SessionResumedEvent',
u'TorrentQueueChangedEvent', u'TorrentFileRenamedEvent',
u'TorrentFolderRenamedEvent', u'TorrentStateChangedEvent',
u'TorrentFinishedEvent', u'ConfigValueChangedEvent',
u'SessionPausedEvent']}
14:05:10.032 [DEBUG ][deluge.core.rpcserver :81 ] Emit Event:
TorrentStateChangedEvent ['6cd42a2c22d12033a00ae0d562c2d2cbeed5902f',
'Paused']
14:05:10.079 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.zip resume data generated
14:05:10.079 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
14:05:10.079 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
14:05:11.054 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:11.069 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:11.069 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:11.069 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:11.130 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:11.177 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:11.177 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:11.559 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
14:05:12.933 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
14:05:13.058 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:13.058 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
14:05:13.136 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
14:05:13.183 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
14:05:13.183 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
14:05:14.074 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
14:05:14.074 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
14:05:14.074 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
14:05:14.904 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
daemon.shutdown
14:05:14.904 [INFO ][deluge.core.daemon :85 ] Waiting for
components to shutdown..
14:05:14.904 [DEBUG ][deluge.core.core :81 ] Core
stopping...
14:05:14.919 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
torrent state file.
14:05:14.935 [INFO ][deluge.core.rpcserver :85 ] Deluge client
disconnected: Connection to the other side was lost in a non-clean
fashion: Connection lost.
14:05:14.935 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_paused_alert: test_file.zip paused
14:05:14.935 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.zip resume data generated
14:05:14.935 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_paused
14:05:14.935 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
14:05:14.935 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: True
14:05:14.935 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
14:05:14.935 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
14:05:14.951 [INFO ][twisted :532 ] (TLS Port
58846 Closed)
14:05:14.951 [INFO ][twisted :532 ] Stopping
factory <twisted.internet.protocol.Factory instance at 0x0375BE68>
14:05:14.951 [INFO ][twisted :532 ] Main loop
terminated.
14:05:14.951 [INFO ][deluge.core.daemon :85 ] Waiting for
components to shutdown..
}}}
----
Now, here's what happens when I leave the GUI running, so the "stop seed
at ratio" works. Log starts a dozen of seconds before the ratio is
reached, the torrent is being seeded:
{{{
13:40:49.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:51.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:51.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:40:53.815 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:55.813 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:55.813 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:40:57.815 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:59.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:40:59.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:01.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:03.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:03.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:05.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:07.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:07.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:09.810 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:11.813 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:11.813 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:13.815 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:15.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:15.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:16.680 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
13:41:16.680 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:16.680 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
13:41:16.680 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
13:41:16.690 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
13:41:16.710 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
13:41:16.710 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
13:41:17.825 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:18.268 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_announce_alert: test_file.rar (udp://tracker.ccc.de:80/announce)
sending announce (stopped)
13:41:18.268 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_announce_alert: test_file.rar
(udp://tracker.publicbt.com:80/announce) sending announce (stopped)
13:41:18.268 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_paused_alert: test_file.rar paused
13:41:18.268 [DEBUG ][deluge.core.alertmanager :81 ]
udp_error_alert: UDP error: Can't connect, remote host actively rejects
connection from: 0.0.0.0
13:41:18.268 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_announce
13:41:18.268 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_announce
13:41:18.268 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_paused
13:41:18.268 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:41:18.268 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: False
13:41:18.268 [DEBUG ][deluge.core.rpcserver :81 ] intevents:
{0: [u'NewVersionAvailableEvent', u'PluginEnabledEvent',
u'TorrentResumedEvent', u'TorrentAddedEvent', u'TorrentRemovedEvent',
u'PluginDisabledEvent', u'SessionResumedEvent',
u'TorrentQueueChangedEvent', u'TorrentFileRenamedEvent',
u'TorrentFolderRenamedEvent', u'TorrentStateChangedEvent',
u'TorrentFinishedEvent', u'ConfigValueChangedEvent',
u'SessionPausedEvent']}
13:41:18.268 [DEBUG ][deluge.core.rpcserver :81 ] Emit Event:
TorrentStateChangedEvent ['d45718d2c29e971ddb3099b27f8429fdba2d26c0',
'Paused']
13:41:18.318 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.rar resume data generated
13:41:18.318 [DEBUG ][deluge.core.alertmanager :81 ]
tracker_reply_alert: test_file.rar
(udp://tracker.publicbt.com:80/announce) received peers: 0
13:41:18.318 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
13:41:18.318 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
13:41:18.318 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_tracker_reply: test_file.rar
(udp://tracker.publicbt.com:80/announce) received peers: 0
13:41:18.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
13:41:18.678 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
13:41:18.718 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
13:41:18.718 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
13:41:19.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_num_connections
13:41:19.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:19.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_free_space
13:41:19.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_session_status
13:41:19.808 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_filter_tree
13:41:20.668 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrent_status
13:41:20.678 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
core.get_torrents_status
13:41:20.718 [DEBUG ][deluge.core.alertmanager :81 ]
state_update_alert: state updates for 1 torrents
13:41:20.718 [DEBUG ][deluge.core.torrentmanager :81 ]
on_status_notification: state updates for 1 torrents
13:41:21.063 [DEBUG ][deluge.core.rpcserver :81 ] RPC dispatch
daemon.shutdown
13:41:21.063 [INFO ][deluge.core.daemon :85 ] Waiting for
components to shutdown..
13:41:21.063 [DEBUG ][deluge.core.core :81 ] Core
stopping...
13:41:21.073 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
torrent state file.
13:41:21.083 [INFO ][deluge.core.rpcserver :85 ] Deluge client
disconnected: Connection to the other side was lost in a non-clean
fashion: Connection lost.
13:41:21.113 [DEBUG ][deluge.core.alertmanager :81 ]
torrent_paused_alert: test_file.rar paused
13:41:21.113 [DEBUG ][deluge.core.alertmanager :81 ]
save_resume_data_alert: test_file.rar resume data generated
13:41:21.113 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_torrent_paused
13:41:21.113 [DEBUG ][deluge.core.torrent :81 ]
set_state_based_on_ltstate: Seeding
13:41:21.113 [DEBUG ][deluge.core.torrent :81 ]
session.is_paused: True
13:41:21.113 [DEBUG ][deluge.core.torrentmanager :81 ]
on_alert_save_resume_data
13:41:21.113 [DEBUG ][deluge.core.torrentmanager :81 ] Saving
fastresume file:
C:\Users\Michal\AppData\Roaming\deluge\state\torrents.fastresume
13:41:21.113 [INFO ][twisted :532 ] (TLS Port
58846 Closed)
13:41:21.113 [INFO ][twisted :532 ] Stopping
factory <twisted.internet.protocol.Factory instance at 0x036BBE68>
13:41:21.113 [INFO ][twisted :532 ] Main loop
terminated.
13:41:21.113 [INFO ][deluge.core.daemon :85 ] Waiting for
components to shutdown..
}}}
As expected while running the GUI the log doesn't "stay silent", since the
GUI keeps getting updated stats every second or two.
Hope my logs and explanations are at least remotely useful.
Please tell me if/what additional info would be useful.
Thanks in advance for your time.
--
Ticket URL: <http://dev.deluge-torrent.org/ticket/2291>
Deluge <http://deluge-torrent.org/>
Deluge project
Ticket URL: <http://dev.deluge-torrent.org/ticket/2291>
Deluge <http://deluge-torrent.org/>
Deluge project