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

[adziahel]

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

[adziahel]

empty torrent list

[adziahel]

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

[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):

[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)…

[Cas]

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

[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

[Cas]

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

deluge/core/torrent.py

@@ -192 +192 @@
                     tracker["url"] = value.url
                     tracker["tier"] = value.tier
                 else:
-                    tracker = value
+                    tracker["url"] = value["url"]
+                    tracker["tier"] = value["tier"]
                 self.trackers.append(tracker)
 
         # Various torrent options
@@ -351 +352 @@
                     tracker["url"] = value.url
                     tracker["tier"] = value.tier
                 else:
-                    tracker = value
+                    tracker["url"] = value["url"]
+                    tracker["tier"] = value["tier"]
                 trackers.append(tracker)
             self.trackers = trackers
             self.tracker_host = None

[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

[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

[adziahel]

Thanks, it did work!

[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

[adziahel]

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

[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"]

[Cas]

Oh and the same for Line 355.

I'll put together a complete commit later today.

[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

[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

[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 :)