Issues with Deluge 2.0

[jawilson]

I'm running Flexget in a docker container with cpoppema/docker-flexget:latest:

• Python: 3.7.7
• Flexget: 3.1.90
• deluge-client: 1.9.0 (tested back to 1.7.1 by manual install)

I'm running deluge in a docker container with linuxserver/deluge:latest, currently version 2.0.3-2-201906121747-ubuntu18.04.1 (tested back to the earliest 2.0.0 image they had).

I seem to only see this for some torrents, I think larger ones or ones with more files (others get added perfectly fine), but in flexget I see the following log lines from deluge-client (I manually updated the log level to get the debug info):

2020-12-02 08:13:12 INFO     deluge_client.client Local-Torrents-TV Connecting to localhost:58846
2020-12-02 08:13:12 DEBUG    deluge_client.client Local-Torrents-TV Connected to Deluge, detecting daemon version
2020-12-02 08:13:12 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 2 method 'daemon.info' with args:() kwargs:{}
2020-12-02 08:13:12 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 3 method 'daemon.info' with args:() kwargs:{}
2020-12-02 08:13:12 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 4 method 'daemon.info' with args:() kwargs:{}
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Daemon version 2 detected, logging in
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 5 method 'daemon.login' with args:['jawilson', '<password hidden>'] kwargs:{'client_version': 'deluge-client'}
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Logged in with value 10
2020-12-02 08:13:13 DEBUG    deluge        Local-Torrents-TV Rendered label: local-tv
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 6 method 'core.get_enabled_plugins' with args:() kwargs:{}
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 7 method 'label.get_labels' with args:() kwargs:{}
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 8 method 'core.get_session_state' with args:() kwargs:{}
2020-12-02 08:13:13 DEBUG    api_tvdb      Local-Torrents-TV Looking up tvdb information for 'Curb Your Enthusiasm'. TVDB ID: 76203
2020-12-02 08:13:13 DEBUG    api_tvdb      Local-Torrents-TV Series <name=Curb Your Enthusiasm,tvdb_id=76203> information restored from cache.
2020-12-02 08:13:13 VERBOSE  deluge        Local-Torrents-TV Adding Curb.Your.Enthusiasm.S01-S09.1080p.AMZN.WEB-DL.WEBRip.DDP2.0.H.264-Mixed (1) to deluge.
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 9 method 'core.add_torrent_file' with args:('Curb.Your.Enthusiasm.S01-S09.1080p.AMZN.WEB-DL.WEBRip.DDP2.0.H.264-Mixed', b'[REDACTED TORRENT DATA]'
2020-12-02 08:13:13 INFO     deluge        Local-Torrents-TV Curb.Your.Enthusiasm.S01-S09.1080p.AMZN.WEB-DL.WEBRip.DDP2.0.H.264-Mixed (1) successfully added to deluge.
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 10 method 'label.set_torrent' with args:('1fa77f95e2395fad2eb616c54a42f07127ba27c8', 'local-tv') kwargs:{}
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 11 method 'core.get_torrent_status' with args:('1fa77f95e2395fad2eb616c54a42f07127ba27c8', ['files', 'total_size', 'save_path', 'move_on_completed_path', 'move_on_completed', 'progress']) kwargs:{}
2020-12-02 08:13:13 WARNING  deluge        Local-Torrents-TV No files in "Curb.Your.Enthusiasm.S01-S09.1080p.AMZN.WEB-DL.WEBRip.DDP2.0.H.264-Mixed (1)" are > 90% of content size, no files renamed.
2020-12-02 08:13:13 VERBOSE  deluge        Local-Torrents-TV Renaming Folder Curb.Your.Enthusiasm.S01-S09.1080p.AMZN.WEB-DL.WEBRip.DDP2.0.H.264-Mixed to /
2020-12-02 08:13:13 DEBUG    deluge_client.client Local-Torrents-TV Calling reqid 12 method 'core.rename_folder' with args:('1fa77f95e2395fad2eb616c54a42f07127ba27c8', 'Curb.Your.Enthusiasm.S01-S09.1080p.AMZN.WEB-DL.WEBRip.DDP2.0.H.264-Mixed', '/') kwargs:{}

In the deluge log, I see:

08:13:12 [INFO    ][deluge.core.rpcserver         :171 ] Deluge Client connection made from: 127.0.0.1:57624
08:13:12 [WARNING ][deluge.transfer               :114 ] Error occurred when parsing message header: Received invalid protocol version: 120. PROTOCOL_VERSION is 1..
08:13:12 [WARNING ][deluge.transfer               :116 ] This version of Deluge cannot communicate with the sender of this data.
08:13:12 [WARNING ][deluge.transfer               :136 ] Failed to decompress (0 bytes) and load serialized data with rencode: Error -5 while decompressing data: incomplete or truncated stream
08:13:13 [WARNING ][deluge.transfer               :114 ] Error occurred when parsing message header: Received invalid protocol version: 68. PROTOCOL_VERSION is 1..
08:13:13 [WARNING ][deluge.transfer               :116 ] This version of Deluge cannot communicate with the sender of this data.
08:13:13 [WARNING ][deluge.transfer               :136 ] Failed to decompress (0 bytes) and load serialized data with rencode: Error -5 while decompressing data: incomplete or truncated stream
08:13:13 [WARNING ][deluge.transfer               :114 ] Error occurred when parsing message header: Received invalid protocol version: 120. PROTOCOL_VERSION is 1..
08:13:13 [WARNING ][deluge.transfer               :116 ] This version of Deluge cannot communicate with the sender of this data.
08:13:13 [WARNING ][deluge.transfer               :136 ] Failed to decompress (0 bytes) and load serialized data with rencode: Error -5 while decompressing data: incomplete or truncated stream
08:13:13 [INFO    ][deluge.core.torrentmanager    :672 ] Torrent Curb.Your.Enthusiasm.S01-S09.1080p.AMZN.WEB-DL.WEBRip.DDP2.0.H.264-Mixed from user "jawilson" added
08:13:13 [WARNING ][deluge.core.torrentmanager    :1255] Torrent id not in torrents loading list: '1fa77f95e2395fad2eb616c54a42f07127ba27c8'
08:13:14 [INFO    ][deluge.core.rpcserver         :197 ] Deluge client disconnected: Connection to the other side was lost in a non-clean fashion: Connection lost.

It seems deluge-client is correctly determining the protocol version, but deluge is still pissed off about it.

Related issues:

• Changes with deluge 2 transfer protocol #27
• Deluge plugin crashes with SSL error when run against Deluge 2.0 Flexget/Flexget#2287

[ngosang]

Any news?
I'm experiencing the same issue in the Prometheus Deluge exporter.
tobbez/deluge_exporter#22

[ngosang]

The warnings are caused by the version probe. In concrete, the lines 122 and 123.

deluge-client/deluge_client/client.py

Line 122 in 0c2e5a9

self._send_call(1, None, 'daemon.info')

I fixed my issues by patching deluge-client and commenting those lines.

Since Deluge 2.1.1 is the latest version and all users will update eventually, you should consider improving that code to not hit the warnings. For example:

# test the latest version first 2.1
try:
  self._send_call(2, 1, 'daemon.info')
  # set small socket timeout here
  result = self._socket.recv(1)
  if ord(result[:1]) == 1:
    self.deluge_version = 2
    self.deluge_protocol_version = 1
    # If we need the specific version of deluge 2, this is it.
    daemon_version = self._receive_response(2, 1, partial_data=result)
    return
catch:
   pass

# test 2.0

# test 1.x

Update 2:
I wrote my own Prometheus exporter for Deluge using the Web API. => https://github.com/ngosang/deluge-exporter

Got the same errors in my logs.