Opened 9 months ago

Closed 9 months ago

Last modified 9 months ago

#3008 closed bug (Fixed)

Unhandled Error exceptions.KeyError: <type 'datetime.datetime'>

Reported by: adziahel Owned by: Cas
Priority: major Milestone: 1.3.15
Component: Core Version: 1.3.14
Keywords: Cc: sor.alexei@…

Description

Repro:

Not sure of exact steps, they were the nothing out of ordinary, I've added a magnet and next thing I know is the torrent list is empty.

Now the torrent list is empty every time, in both GTK and web UI

Classic mode: disabled Version: 1.3.14 (both deluge-gtk and deluged)

Here's deluged backtrace:

Сак 24 20:56:15 server deluged[18426]: [INFO    ] 20:56:15 rpcserver:206 Deluge Client connection made from: 192.168.1.125:60194
Сак 24 20:56:15 server deluged[18426]: Unhandled Error
Сак 24 20:56:15 server deluged[18426]: Traceback (most recent call last):
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/main.py", line 241, in start_daemon
Сак 24 20:56:15 server deluged[18426]:     Daemon(options, args)
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/core/daemon.py", line 180, in __init__
Сак 24 20:56:15 server deluged[18426]:     reactor.run()
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 1195, in run
Сак 24 20:56:15 server deluged[18426]:     self.mainLoop()
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 1204, in mainLoop
Сак 24 20:56:15 server deluged[18426]:     self.runUntilCurrent()
Сак 24 20:56:15 server deluged[18426]: --- <exception caught here> ---
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib64/python2.7/site-packages/twisted/internet/base.py", line 825, in runUntilCurren
Сак 24 20:56:15 server deluged[18426]:     call.func(*call.args, **call.kw)
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/core/rpcserver.py", line 324, in dispatch
Сак 24 20:56:15 server deluged[18426]:     self.sendData((RPC_RESPONSE, request_id, ret))
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/core/rpcserver.py", line 199, in sendData
Сак 24 20:56:15 server deluged[18426]:     self.transport.write(zlib.compress(rencode.dumps(data)))
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/rencode.py", line 391, in dumps
Сак 24 20:56:15 server deluged[18426]:     encode_func[type(x)](x, r)
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/rencode.py", line 338, in encode_list
Сак 24 20:56:15 server deluged[18426]:     encode_func[type(i)](i, r)
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/rencode.py", line 355, in encode_dict
Сак 24 20:56:15 server deluged[18426]:     encode_func[type(v)](v, r)
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/rencode.py", line 355, in encode_dict
Сак 24 20:56:15 server deluged[18426]:     encode_func[type(v)](v, r)
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/rencode.py", line 338, in encode_list
Сак 24 20:56:15 server deluged[18426]:     encode_func[type(i)](i, r)
Сак 24 20:56:15 server deluged[18426]:   File "/usr/lib/python2.7/site-packages/deluge/rencode.py", line 350, in encode_dict
Сак 24 20:56:15 server deluged[18426]:     encode_func[type(v)](v, r)
Сак 24 20:56:15 server deluged[18426]: exceptions.KeyError: <type 'datetime.datetime'>

Attachments (1)

Screenshot from 2017-03-24 20-27-45.png (60.5 KB) - added by adziahel 9 months ago.
empty torrent list

Download all attachments as: .zip

Change History (17)

Changed 9 months ago by adziahel

empty torrent list

comment:1 Changed 9 months ago by adziahel

I am using a https://build.opensuse.org/package/show/network/deluge package of openSUSE Tumbleweed's repository

comment:2 Changed 9 months ago by Cas

I'm not sure where datatime is coming from. Could you enable debug logs to see if any more info is provided. If you can modifying the rpcserver.py file with this logging line would be even more helpful.

diff --git deluge/core/rpcserver.py deluge/core/rpcserver.py
index e3c3db12d..1bdb3aa95 100644
--- deluge/core/rpcserver.py
+++ deluge/core/rpcserver.py
@@ -196,6 +196,7 @@ def sendData(self, data):
         :type data: object
 
         """
+        log.debug('rpc data: %s', data)
         self.transport.write(zlib.compress(rencode.dumps(data)))
 
     def connectionMade(self):

comment:3 Changed 9 months ago by adziahel

All right, found two entries like that in data related to one torrent

…'trackers': [
  {'send_stats': True, 'fails': 0, 'verified': True, 'scrape_incomplete': 9,
    'min_announce':'min_announce': datetime.datetime(2017, 3, 15, 21, 15, 1), 
    'source': 2, ... 'fail_limit': 0, 
    'next_announce': datetime.datetime(2017, 3, 15, 21, 15, 1)…

comment:4 follow-up: Changed 9 months ago by Cas

  • Milestone changed from needs verified to 1.3.15
  • Owner set to Cas
  • Status changed from new to assigned

Excellent, I wondered if it might be from changes in latest version of libtorrent (1.1.2), thanks.

comment:5 in reply to: ↑ 4 Changed 9 months ago by adziahel

Replying to Cas:

Excellent, I wondered if it might be from changes in latest version of libtorrent (1.1.2), thanks.

Awesome! Please let me know if you'll need anything else

comment:6 follow-up: Changed 9 months ago by Cas

I cannot replicate with the trackers I have here. Are you test this fix and confirm if it works:

  • deluge/core/torrent.py

    diff --git deluge/core/torrent.py deluge/core/torrent.py
    index 3b1a1e07c..acd6eb527 100644
    def __init__(self, handle, options, state=None, filename=None, magnet=None): 
    192192                    tracker["url"] = value.url 
    193193                    tracker["tier"] = value.tier 
    194194                else: 
    195                     tracker = value 
     195                    tracker["url"] = value["url"] 
     196                    tracker["tier"] = value["tier"] 
    196197                self.trackers.append(tracker) 
    197198 
    198199        # Various torrent options 
    def set_trackers(self, trackers, reannounce=True): 
    351352                    tracker["url"] = value.url 
    352353                    tracker["tier"] = value.tier 
    353354                else: 
    354                     tracker = value 
     355                    tracker["url"] = value["url"] 
     356                    tracker["tier"] = value["tier"] 
    355357                trackers.append(tracker) 
    356358            self.trackers = trackers 
    357359            self.tracker_host = None 

comment:7 in reply to: ↑ 6 Changed 9 months ago by adziahel

Replying to Cas:

I cannot replicate with the trackers I have here. Are you test this fix and confirm if it works:

Unfortunately it doesn't — the exception is still there

comment:8 Changed 9 months ago by Cas

Ah of course it will be stored in the torrent state and reloaded. This additional change should fix that:

diff --git deluge/core/torrent.py deluge/core/torrent.py
@@ -362,10 +352,13 @@ def set_trackers(self, trackers, reannounce=True):
         log.debug("Setting trackers for %s: %s", self.torrent_id, trackers)
         tracker_list = []
 
-        for tracker in trackers:
+        for idx, tracker in enumerate(trackers):
             new_entry = lt.announce_entry(tracker["url"])
             new_entry.tier = tracker["tier"]
             tracker_list.append(new_entry)
+            # Need to remove lt 1.1.2 tracker datetime entries for rencoding.
+            trackers[idx]["min_announce"] = trackers[idx]["next_announce"] = None
         self.handle.replace_trackers(tracker_list)
 
         # Print out the trackers

comment:9 Changed 9 months ago by adziahel

Thanks, it did work!

comment:10 Changed 9 months ago by adziahel

Although there's another possibly related exception popped up when adding magnet link rendering the functionality unusable:

Сак 29 14:46:19 server deluged[29676]: [ERROR   ] 14:46:19 rpcserver:306 Exception calling RPC request: local variable 'tracker' referenced before assignment
Сак 29 14:46:19 server deluged[29676]: Traceback (most recent call last):
Сак 29 14:46:19 server deluged[29676]:   File "/usr/lib/python2.7/site-packages/deluge/core/rpcserver.py", line 301, in dispatch
Сак 29 14:46:19 server deluged[29676]:     ret = self.factory.methods[method](*args, **kwargs)
Сак 29 14:46:19 server deluged[29676]:   File "/usr/lib/python2.7/site-packages/deluge/core/core.py", line 322, in add_torrent_magnet
Сак 29 14:46:19 server deluged[29676]:     return self.torrentmanager.add(magnet=uri, options=options)
Сак 29 14:46:19 server deluged[29676]:   File "/usr/lib/python2.7/site-packages/deluge/core/torrentmanager.py", line 491, in add
Сак 29 14:46:19 server deluged[29676]:     torrent = Torrent(handle, options, state, filename, magnet)
Сак 29 14:46:19 server deluged[29676]:   File "/usr/lib/python2.7/site-packages/deluge/core/torrent.py", line 195, in __init__
Сак 29 14:46:19 server deluged[29676]:     tracker["url"] = value["url"]
Сак 29 14:46:19 server deluged[29676]: UnboundLocalError: local variable 'tracker' referenced before assignment

comment:11 Changed 9 months ago by adziahel

Adding torrents via http url (is that OK to post links to rarbg here?) doesn't work as well

comment:12 Changed 9 months ago by Cas

Yeah that is an artefact of those changes. Line 195 in torrent.py needs to define trackers dict:

                        else: 
+                           tracker = {}
                            tracker["url"] = value["url"] 
                            tracker["tier"] = value["tier"]

comment:13 Changed 9 months ago by Cas

Oh and the same for Line 355.

I'll put together a complete commit later today.

comment:14 Changed 9 months ago by Cas

This was also fixed upstream in libtorrent so if you could inform openSuse libtorrent maintainer that would be useful: https://github.com/arvidn/libtorrent/commit/852fada77266903998ddf7a0ac07b5ba5edbd6e7

comment:15 follow-up: Changed 9 months ago by Cas

  • Resolution set to Fixed
  • Status changed from assigned to closed

Ok so this is now fixed in 1.3-stable with a smaller set of code changes: [dd08cb29e531d6]

Also for reference there is an lt upstream issue ticket: https://github.com/arvidn/libtorrent/issues/1863

comment:16 in reply to: ↑ 15 Changed 9 months ago by adziahel

Replying to Cas:

Ok so this is now fixed in 1.3-stable with a smaller set of code changes: [dd08cb29e531d6]

Also for reference there is an lt upstream issue ticket: https://github.com/arvidn/libtorrent/issues/1863

Thank you a lot!

if you could inform openSuse libtorrent maintainer that would be useful

He's in tickets' CC, so he might be very much aware of the matter :)

Note: See TracTickets for help on using tickets.