Opened 18 months ago

Last modified 4 months ago

#3565 new bug

deluged hangs spamming logs with "Logging.findCaller() takes from 1 to 2 positional arguments but 3 were given"

Reported by: iconoclasthero Owned by:
Priority: critical Milestone: needs verified
Component: Core Version: 2.0.3
Keywords: twisted Cc: arvidbrodin

Description

​https://forum.deluge-torrent.org/viewtopic.php?f=7&t=56323'

# htop shows: /usr/bin/python3 /usr/bin/deluged -d -c /var/lib/deluged/config -l /var/log/deluged/daemon.log -L info really hogging a processor and there are a ton of errors in the log. The errors show that twisted is involved but the twisted folks don't seem to think that is the issue. 2.0.3 is what is in the ubuntu repo so i would have to compile from source or get a .deb to upgrade to 2.0.5

Attachments (1)

Screenshot from 2022-10-25 09-28-35.png​ (62.7 KB) - added by iconoclasthero 18 months ago.
htop

Download all attachments as: .zip

Change History (6)

Changed 18 months ago by iconoclasthero

htop

comment:2 Changed 4 months ago by arvidbrodin

I can confirm this (or a very similar?) issue on a fresh debian-12.4.0 headless install (only system tools + ssh server + deluged + deluge-web).

deluged immediately starts flooding the logs when started. (I assume using 100 % cpu although I didn't check.) 

# apt update
...
All packages are up to date.

# apt install deluged
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
deluged is already the newest version (2.0.3-4).

# head /var/log/deluged/daemon.log 
06:17:25 [INFO    ][deluge.configmanager:52  ] Setting config directory to: /var/lib/deluged/config
06:17:25 [CRITICAL][twisted                       :147 ] Unhandled error in Deferred:
06:17:25 [CRITICAL][twisted                       :147 ] Unhandled error in Deferred:
06:17:25 [CRITICAL][twisted                       :147 ] Unhandled error in Deferred:
06:17:25 [CRITICAL][twisted                       :147 ] Unhandled error in Deferred:
06:17:25 [CRITICAL][twisted                       :147 ] Unhandled error in Deferred:
06:17:25 [INFO    ][twisted                       :147 ] Factory (TLS) starting on 58846
06:17:25 [INFO    ][twisted                       :147 ] Starting factory <twisted.internet.protocol.Factory object at 0x7f976df4e110>
06:17:25 [CRITICAL][twisted                       :147 ] Unhandled error in Deferred:
06:17:25 [CRITICAL][twisted                       :147 ] Unhandled error in Deferred:
(lots more of these lines in the log...)

# journalctl _SYSTEMD_UNIT=deluged.service --since "2023-12-15 06:17:00" | head -n 100
Dec 15 06:17:25 deluge deluged[3938]: Unhandled error in Deferred:
Dec 15 06:17:25 deluge deluged[3938]: Traceback (most recent call last):
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/deluge/core/daemon_entry.py", line 112, in run_daemon
Dec 15 06:17:25 deluge deluged[3938]:     daemon = Daemon(
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/deluge/core/daemon.py", line 94, in __init__
Dec 15 06:17:25 deluge deluged[3938]:     log.info('Deluge daemon %s', get_version())
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1905, in unwindGenerator
Dec 15 06:17:25 deluge deluged[3938]:     return _cancellableInlineCallbacks(gen)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1815, in _cancellableInlineCallbacks
Dec 15 06:17:25 deluge deluged[3938]:     _inlineCallbacks(None, gen, status)
Dec 15 06:17:25 deluge deluged[3938]: --- <exception caught here> ---
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
Dec 15 06:17:25 deluge deluged[3938]:     result = current_context.run(gen.send, result)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/deluge/log.py", line 69, in info
Dec 15 06:17:25 deluge deluged[3938]:     yield LoggingLoggerClass.info(self, msg, *args, **kwargs)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3.11/logging/__init__.py", line 1489, in info
Dec 15 06:17:25 deluge deluged[3938]:     self._log(INFO, msg, args, **kwargs)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3.11/logging/__init__.py", line 1622, in _log
Dec 15 06:17:25 deluge deluged[3938]:     fn, lno, func, sinfo = self.findCaller(stack_info, stacklevel)
Dec 15 06:17:25 deluge deluged[3938]: builtins.TypeError: Logging.findCaller() takes from 1 to 2 positional arguments but 3 were given
Dec 15 06:17:25 deluge deluged[3938]: Temporarily disabling observer LegacyLogObserverWrapper(<bound method TwistedLoggingObserver.emit of <deluge.log.TwistedLoggingObserver object at 0x7f976fb113d0>>) due to exception: [Failure instance: Traceback: <class 'TypeError'>: Logging.findCaller() takes from 1 to 2 positional arguments but 3 were given
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/pkg_resources/_vendor/pyparsing/core.py:4112:parseImpl
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/internet/defer.py:344:__del__
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/logger/_logger.py:190:failure
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/logger/_logger.py:142:emit
Dec 15 06:17:25 deluge deluged[3938]: --- <exception caught here> ---
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/logger/_observer.py:81:__call__
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/logger/_legacy.py:90:__call__
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/deluge/log.py:204:emit
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3.11/logging/__init__.py:1536:critical
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3.11/logging/__init__.py:1622:_log
Dec 15 06:17:25 deluge deluged[3938]: ]
Dec 15 06:17:25 deluge deluged[3938]: Traceback (most recent call last):
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/pkg_resources/_vendor/pyparsing/core.py", line 4112, in parseImpl
Dec 15 06:17:25 deluge deluged[3938]:     for e in self.exprs:
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 344, in __del__
Dec 15 06:17:25 deluge deluged[3938]:     log.failure(format, self.failResult, debugInfo=debugInfo)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/logger/_logger.py", line 190, in failure
Dec 15 06:17:25 deluge deluged[3938]:     self.emit(level, format, log_failure=failure, **kwargs)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/logger/_logger.py", line 142, in emit
Dec 15 06:17:25 deluge deluged[3938]:     self.observer(event)
Dec 15 06:17:25 deluge deluged[3938]: --- <exception caught here> ---
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/logger/_observer.py", line 81, in __call__
Dec 15 06:17:25 deluge deluged[3938]:     observer(event)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/logger/_legacy.py", line 90, in __call__
Dec 15 06:17:25 deluge deluged[3938]:     self.legacyObserver(event)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/deluge/log.py", line 204, in emit
Dec 15 06:17:25 deluge deluged[3938]:     getattr(LoggingLoggerClass, event_dict['log_level'].name)(
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3.11/logging/__init__.py", line 1536, in critical
Dec 15 06:17:25 deluge deluged[3938]:     self._log(CRITICAL, msg, args, **kwargs)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3.11/logging/__init__.py", line 1622, in _log
Dec 15 06:17:25 deluge deluged[3938]:     fn, lno, func, sinfo = self.findCaller(stack_info, stacklevel)
Dec 15 06:17:25 deluge deluged[3938]: builtins.TypeError: Logging.findCaller() takes from 1 to 2 positional arguments but 3 were given
Dec 15 06:17:25 deluge deluged[3938]: Unhandled error in Deferred:
Dec 15 06:17:25 deluge deluged[3938]: Traceback (most recent call last):
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/deluge/core/core.py", line 134, in __init__
Dec 15 06:17:25 deluge deluged[3938]:     self._load_session_state()
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/deluge/core/core.py", line 339, in _load_session_state
Dec 15 06:17:25 deluge deluged[3938]:     log.info('Successfully loaded %s: %s', filename, _filepath)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1905, in unwindGenerator
Dec 15 06:17:25 deluge deluged[3938]:     return _cancellableInlineCallbacks(gen)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1815, in _cancellableInlineCallbacks
Dec 15 06:17:25 deluge deluged[3938]:     _inlineCallbacks(None, gen, status)
Dec 15 06:17:25 deluge deluged[3938]: --- <exception caught here> ---
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
Dec 15 06:17:25 deluge deluged[3938]:     result = current_context.run(gen.send, result)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/deluge/log.py", line 69, in info
Dec 15 06:17:25 deluge deluged[3938]:     yield LoggingLoggerClass.info(self, msg, *args, **kwargs)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3.11/logging/__init__.py", line 1489, in info
Dec 15 06:17:25 deluge deluged[3938]:     self._log(INFO, msg, args, **kwargs)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3.11/logging/__init__.py", line 1622, in _log
Dec 15 06:17:25 deluge deluged[3938]:     fn, lno, func, sinfo = self.findCaller(stack_info, stacklevel)
Dec 15 06:17:25 deluge deluged[3938]: builtins.TypeError: Logging.findCaller() takes from 1 to 2 positional arguments but 3 were given
Dec 15 06:17:25 deluge deluged[3938]: Temporarily disabling observer LegacyLogObserverWrapper(<bound method TwistedLoggingObserver.emit of <deluge.log.TwistedLoggingObserver object at 0x7f976fb113d0>>) due to exception: [Failure instance: Traceback: <class 'TypeError'>: Logging.findCaller() takes from 1 to 2 positional arguments but 3 were given
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/pkg_resources/_vendor/pyparsing/core.py:4112:parseImpl
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/internet/defer.py:344:__del__
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/logger/_logger.py:190:failure
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/logger/_logger.py:142:emit
Dec 15 06:17:25 deluge deluged[3938]: --- <exception caught here> ---
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/logger/_observer.py:81:__call__
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/twisted/logger/_legacy.py:90:__call__
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3/dist-packages/deluge/log.py:204:emit
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3.11/logging/__init__.py:1536:critical
Dec 15 06:17:25 deluge deluged[3938]: /usr/lib/python3.11/logging/__init__.py:1622:_log
Dec 15 06:17:25 deluge deluged[3938]: ]
Dec 15 06:17:25 deluge deluged[3938]: Traceback (most recent call last):
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/pkg_resources/_vendor/pyparsing/core.py", line 4112, in parseImpl
Dec 15 06:17:25 deluge deluged[3938]:     for e in self.exprs:
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 344, in __del__
Dec 15 06:17:25 deluge deluged[3938]:     log.failure(format, self.failResult, debugInfo=debugInfo)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/logger/_logger.py", line 190, in failure
Dec 15 06:17:25 deluge deluged[3938]:     self.emit(level, format, log_failure=failure, **kwargs)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/logger/_logger.py", line 142, in emit
Dec 15 06:17:25 deluge deluged[3938]:     self.observer(event)
Dec 15 06:17:25 deluge deluged[3938]: --- <exception caught here> ---
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/logger/_observer.py", line 81, in __call__
Dec 15 06:17:25 deluge deluged[3938]:     observer(event)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/twisted/logger/_legacy.py", line 90, in __call__
Dec 15 06:17:25 deluge deluged[3938]:     self.legacyObserver(event)
Dec 15 06:17:25 deluge deluged[3938]:   File "/usr/lib/python3/dist-packages/deluge/log.py", line 204, in emit

Again, lots and lots and lots of these errors, it goes on and on.

So it seems the issue is 

builtins.TypeError: Logging.findCaller() takes from 1 to 2 positional arguments but 3 were given

Any ideas how to work around this?

comment:3 Changed 4 months ago by arvidbrodin

  • Cc arvidbrodin added
  • Priority changed from minor to critical
  • Summary changed from deluged is using 100% to deluged hangs spamming logs with "Logging.findCaller() takes from 1 to 2 positional arguments but 3 were given"

comment:4 Changed 4 months ago by arvidbrodin

Doing more research, this bug was reported in debian bug tracker and has apparently been fixed upstream, in version 2.1.1-1. See ​https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1005411

Unfortunately 2.0.3-4 is still (two years later!) the current version in debian 12.4 for some reason, so the bug persists there.

Last edited 4 months ago by arvidbrodin (previous) (diff)

comment:5 Changed 4 months ago by arvidbrodin

To work around this:

Follow the official instructions here (​https://www.debian.org/doc/manuals/debian-reference/ch02.en.html#_packages_from_mixed_source_of_archives) on how to mix packages from different archives. That is, move /etc/apt/sources.list somewhere safe and create a new version of the file containing: 

deb http://deb.debian.org/debian/ testing main non-free-firmware
deb-src http://deb.debian.org/debian/ testing main non-free-firmware

Then run 

# apt update
# apt install deluge-common deluged deluge-web

(Perhaps run 'apt install --dry-run deluge-common deluged deluge-web' first and make sure this won't replace any system packages, like glibc! In my case, just the listed packages were updated.)

This will upgrade deluge to whatever version is in testing at the moment, 2.1.2~dev0+20230918-1 in my case, which fixes the bug described above.

Finally restore the original version of /etc/apt/sources.list. (And run 'apt update' again, if you wish.)

Note: See TracTickets for help on using tickets.