Skip to content

Python 3.12+ breaks backwards compatibility for logging QueueHandler with some Queue classes #119819

New issue
New issue
Closed
Closed
Python 3.12+ breaks backwards compatibility for logging QueueHandler with some Queue classes#119819
Labels
stdlibStandard Library Python modules in the Lib/ directorytype-bugAn unexpected behavior, bug, or error

Description

@shmilee
shmilee
opened on May 31, 2024

Bug report

Bug description:

Related bug: #111615
Related pull: #111638
Related codes:

cpython/Lib/logging/config.py

Lines 789 to 804 in bd0d97c

if 'queue' in config:
from multiprocessing.queues import Queue as MPQueue
qspec = config['queue']
if not isinstance(qspec, (queue.Queue, MPQueue)):
if isinstance(qspec, str):
q = self.resolve(qspec)
if not callable(q):
raise TypeError('Invalid queue specifier %r' % qspec)
q = q()
elif isinstance(qspec, dict):
if '()' not in qspec:
raise TypeError('Invalid queue specifier %r' % qspec)
q = self.configure_custom(dict(qspec))
else:
raise TypeError('Invalid queue specifier %r' % qspec)
config['queue'] = q

reproducible example using Python 3.12.3

import logging.config


def main(q):
    config = {
        'version': 1,
        'handlers': {
            'sink': {
                'class': 'logging.handlers.QueueHandler',
                'queue': q,
            },
        },
        'root': {
            'handlers': ['sink'],
        },
    }
    logging.config.dictConfig(config)


if __name__ == '__main__':
    import multiprocessing as mp
    main(mp.Manager().Queue())
    #import asyncio
    #main(asyncio.Queue())  # broken too

error:

Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/config.py", line 581, in configure
    handler = self.configure_handler(handlers[name])
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/logging/config.py", line 801, in configure_handler
    raise TypeError('Invalid queue specifier %r' % qspec)
TypeError: Invalid queue specifier <AutoProxy[Queue] object, typeid 'Queue' at 0x7f8b07189d90>

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/xxx/logging-queue-handler-bug.py", line 33, in <module>
    main(mp.Manager().Queue())
  File "/home/xxx/logging-queue-handler-bug.py", line 29, in main
    logging.config.dictConfig(config)
  File "/usr/lib/python3.12/logging/config.py", line 914, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib/python3.12/logging/config.py", line 588, in configure
    raise ValueError('Unable to configure handler '
ValueError: Unable to configure handler 'sink'

Queue classes to check for logging QueueHandler

  • queue.Queue(), <queue.Queue at 0x7fb86eeef170>, works.
  • multiprocessing
    • multiprocessing.Queue(), <multiprocessing.queues.Queue at 0x7fb871790500>, works.
    • multiprocessing.Manager().Queue() <AutoProxy[Queue] object, typeid 'Queue' at 0x7fb86ef4a840>, broken.
      Its class is multiprocessing.managers.AutoProxy[Queue], a subclass of multiprocessing.managers.BaseProxy.
  • asyncio.queues.Queue() <Queue at 0x7fb86f0be4e0 maxsize=0>, broken.
  • any other Queue?

discuss: how to fix

Check all Queue classes mentioned above in

cpython/Lib/logging/config.py

Line 792 in bd0d97c

if not isinstance(qspec, (queue.Queue, MPQueue)):

or just focus on handling special cases: str and dict, while leaving other cases un-checked (e.g., queue.Queue, multiprocessing.queues.Queue).

CPython versions tested on:

3.12

Operating systems tested on:

Linux

Linked PRs

Activity

  1. picnixz commented on Jun 2, 2024

    @picnixz
    picnixz
    on Jun 2, 2024
    Member

    My 2 cents: one concrete use case I can imagine is when you want to pass that queue to a pool without using a global variable and a custom initializer. AFAIK, you need a manager-based queue since multiprocessing.Queue cannot be pickled. There are other (possibly rare) issues mentioned at the end of the https://docs.python.org/3.10/library/multiprocessing.html#pipes-and-queues paragraph, so maybe some people might be affected?

    When I suggested the protocol-based approach, it was mostly to deal with the issue arising from the proxy interface because checking the runtime type would not help in that case.

  2. shmilee commented on Jun 3, 2024

    @shmilee
    shmilee
    on Jun 3, 2024
    Author

    Why should it not be excluded, since multiprocessing.Queue () is available to be used?

    Except for the mentioned reasons, 1) some people may get errors when updating to py3.12 due to their previous code using proxy queue, 2) py3.12 excludes but doesn't completely exclude proxy queue (dict qspec), I don't have any other new reasons.

    You can't check the class easily as AutoProxy could be used to proxy other things, not just queues.

    Yes, that's true and makes checking the type of proxy indeed tricky.

    1. If it really needs to be checked, I think picnixz's suggestion is quite good.
      (PS: In my personal code, I might directly use its __class__ to check the class, because, for personal projects, I treat the class names in the standard library basically unchanged. Of course, in a standard library this will be weird.)

    2. If the final decision is not to check proxy, perhaps the documentation should explicitly mention it.
      Because even though its class name is <class 'multiprocessing.managers.AutoProxy[Queue]'>, it still is a <queue.Queue object at xxx>. Perhaps, besides me, someone also believes they are the same AutoProxy[Queue] can be treated as queue.Queue.

    cpython/Lib/multiprocessing/managers.py

    Lines 1224 to 1225 in 367adc9

    SyncManager.register('Queue', queue.Queue)
    SyncManager.register('JoinableQueue', queue.Queue)

  3. vsajip
    added a commit that references this issue on Jun 4, 2024

    pythongh-119819: Fix regression to allow logging configuration with m…

    6125ac2

  4. vsajip commented on Jun 4, 2024

    @vsajip
    vsajip
    on Jun 4, 2024
    Member

    Please check if the changes in the linked PR #120030 fix the problem reported..

  5. vsajip
    added a commit that references this issue on Jun 4, 2024

    gh-119819: Fix regression to allow logging configuration with multipr… (

    99d945c
  6. miss-islington
    added 2 commits that reference this issue on Jun 4, 2024

    pythongh-119819: Fix regression to allow logging configuration with m…

    e8abbdb

    pythongh-119819: Fix regression to allow logging configuration with m…

    24dde16
  7. vsajip
    added 4 commits that reference this issue on Jun 4, 2024

    [3.12] gh-119819: Fix regression to allow logging configuration with …

    0e150c3

    [3.13] gh-119819: Fix regression to allow logging configuration with …

    720a44d

    pythongh-119819: Update test to skip if _multiprocessing is unavailable.

    911beda

    gh-119819: Update test to skip if _multiprocessing is unavailable. (G…

    109e108
  8. miss-islington
    added 2 commits that reference this issue on Jun 4, 2024

    pythongh-119819: Update test to skip if _multiprocessing is unavailab…

    ce97454

    pythongh-119819: Update test to skip if _multiprocessing is unavailab…

    e13464b
  9. vsajip
    added 2 commits that reference this issue on Jun 4, 2024

    [3.12] gh-119819: Update test to skip if _multiprocessing is unavaila…

    008f9dd

    [3.13] gh-119819: Update test to skip if _multiprocessing is unavaila…

    7edc6bd

  10. shmilee commented on Jun 5, 2024

    @shmilee
    shmilee
    on Jun 5, 2024
    Author

    I just checked. The PR fixes the problem. Thanks!

    #!/bin/bash
TEST_DIR='/tmp/py3.12-logging-queue-fdjsa'
mkdir -v $TEST_DIR
cd $TEST_DIR/
wget -c https://github.com/python/cpython/pull/120030.patch
filterdiff --include=a/Lib/logging/config.py ./120030.patch > ./120030-part.patch
cat > ./test-mp.py <<EOF
import logging.config
import multiprocessing as mp
def main(q):
    config = {
        'version': 1,
        'handlers': {
            'sink': {
                'class': 'logging.handlers.QueueHandler',
                'queue': q,
            },
        },
        'root': {
            'handlers': ['sink'],
        },
    }
    logging.config.dictConfig(config)
if __name__ == '__main__':
    main(mp.Manager().Queue())
    print('===> PASS. Manager().Queue()')
    #print('-'*20)
    #main(mp.Manager().JoinableQueue())
    #print('===> PASS. Manager().JoinableQueue()')
EOF

echo -e '\n--------before and test--------\n'
python3.12 $TEST_DIR/test-mp.py

echo -e '\n--------patch and test--------\n'
md5sum /usr/lib/python3.12/logging/*.py
sudo cp -iv /usr/lib/python3.12/logging/config.py /usr/lib/python3.12/logging/config.py-backup
sudo patch -p3 -i  $TEST_DIR/120030-part.patch -d /usr/lib/python3.12/logging
diff -Nur /usr/lib/python3.12/logging/config.py-backup /usr/lib/python3.12/logging/config.py
python3.12 $TEST_DIR/test-mp.py

echo -e '\n--------back--------\n'
sudo mv -iv /usr/lib/python3.12/logging/config.py-backup /usr/lib/python3.12/logging/config.py
sudo rm -iv /usr/lib/python3.12/logging/config.py.orig
md5sum /usr/lib/python3.12/logging/*.py

    Output:

    --------patch and test--------

5bbe3f40092754f7c0048141d8e18d46  /usr/lib/python3.12/logging/config.py
9e8979dac3100e20627ffb5ec3eb0f88  /usr/lib/python3.12/logging/handlers.py
1b36e4639409218821586449d57ed36b  /usr/lib/python3.12/logging/__init__.py
'/usr/lib/python3.12/logging/config.py' -> '/usr/lib/python3.12/logging/config.py-backup'
patching file config.py
Hunk #1 succeeded at 786 (offset 5 lines).
--- /usr/lib/python3.12/logging/config.py-backup	2024-06-05 10:54:15.791962361 +0800
+++ /usr/lib/python3.12/logging/config.py	2024-06-05 10:54:15.813962361 +0800
@@ -786,8 +786,10 @@
                     # raise ValueError('No handlers specified for a QueueHandler')
                 if 'queue' in config:
                     from multiprocessing.queues import Queue as MPQueue
+                    from multiprocessing import Manager as MM
+                    proxy_queue = MM().Queue()
                     qspec = config['queue']
-                    if not isinstance(qspec, (queue.Queue, MPQueue)):
+                    if not isinstance(qspec, (queue.Queue, MPQueue, type(proxy_queue))):
                         if isinstance(qspec, str):
                             q = self.resolve(qspec)
                             if not callable(q):
===> PASS. Manager().Queue()

  11. shmilee commented on Jun 5, 2024

    @shmilee
    shmilee
    on Jun 5, 2024
    Author

    Before closing the issue, I will paste a potential error that may never happen. Not sure if anyone has used JoinableQueue and logging together, so only paste it here and let someone who is searching JoinableQueue issue confirm their problem.

    if __name__ == '__main__':
    main(mp.Manager().Queue())
    print('===> PASS. Manager().Queue()')
    print('-'*20)
    main(mp.Manager().JoinableQueue())
    print('===> PASS. Manager().JoinableQueue()')
    --------------------
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/config.py", line 581, in configure
    handler = self.configure_handler(handlers[name])
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/logging/config.py", line 803, in configure_handler
    raise TypeError('Invalid queue specifier %r' % qspec)
TypeError: Invalid queue specifier <AutoProxy[JoinableQueue] object, typeid 'JoinableQueue' at 0x7fc795981e80>

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/tmp/py3.12-logging-queue-fdjsa/test-mp.py", line 23, in <module>
    main(mp.Manager().JoinableQueue())
  File "/tmp/py3.12-logging-queue-fdjsa/test-mp.py", line 17, in main
    logging.config.dictConfig(config)
  File "/usr/lib/python3.12/logging/config.py", line 916, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib/python3.12/logging/config.py", line 588, in configure
    raise ValueError('Unable to configure handler '
ValueError: Unable to configure handler 'sink'

  12. shmilee commented on Jun 5, 2024

    @shmilee
    shmilee
    on Jun 5, 2024
    Author

    Thank you again! @vsajip @picnixz

  13. shmilee
    closed this as completedon Jun 5, 2024
  14. github-project-automation
    moved this to Done in Logging issues 🪵on Jun 5, 2024
  15. vsajip
    added 2 commits that reference this issue on Jun 5, 2024

    pythongh-119819: Update logging configuration to support joinable mul…

    b3aa655

    gh-119819: Update logging configuration to support joinable multiproc… (

    983efcf
  16. miss-islington
    added 2 commits that reference this issue on Jun 5, 2024

    pythongh-119819: Update logging configuration to support joinable mul…

    69cb391

    pythongh-119819: Update logging configuration to support joinable mul…

    30c2774
  17. vsajip
    added 2 commits that reference this issue on Jun 5, 2024

    [3.12] gh-119819: Update logging configuration to support joinable mu…

    8d19977

    [3.13] gh-119819: Update logging configuration to support joinable mu…

    71f86ee
  18. barneygale
    added 3 commits that reference this issue on Jun 5, 2024

    pythongh-119819: Fix regression to allow logging configuration with m…

    aff9a10

    pythongh-119819: Update test to skip if _multiprocessing is unavailab…

    a6fb23a

    pythongh-119819: Update logging configuration to support joinable mul…

    0cdb827
  19. freakboy3742
    added a commit that references this issue on Jun 15, 2024

    gh-119819: Conditional skip of logging tests that require multiproces…

    92f6d40
  20. miss-islington
    added 2 commits that reference this issue on Jun 15, 2024

    pythongh-119819: Conditional skip of logging tests that require multi…

    33d9ebc

    pythongh-119819: Conditional skip of logging tests that require multi…

    9048ecf
  21. freakboy3742
    added 2 commits that reference this issue on Jun 15, 2024

    [3.13] gh-119819: Conditional skip of logging tests that require mult…

    3c88898

    [3.12] gh-119819: Conditional skip of logging tests that require mult…

    92c1687
  22. mrahtz
    added a commit that references this issue on Jun 30, 2024

    pythongh-119819: Conditional skip of logging tests that require multi…

    9ee48b7

  23. noreentry commented on Jul 13, 2024

    @noreentry
    noreentry
    on Jul 13, 2024

    multiprocessing.Pool with spawn method breaks logging.handlers.QueueHandler configuration

    import logging
import logging.config
import multiprocessing
import time


def _init(q):
    logging.config.dictConfig({
        'version': 1,
        'disable_existing_loggers': True,
        'handlers': {'log_to_parent': {'class': 'logging.handlers.QueueHandler', 'queue': q}},
        'root': {'handlers': ['log_to_parent'], 'level': 'DEBUG'}
    })
    logging.getLogger().info('log from child')


if __name__ == '__main__':    
    multiprocessing.set_start_method('spawn')
    with multiprocessing.Manager() as manager:
        # q = manager.Queue()
        q = multiprocessing.Queue()
        
        # listen for log messages from child processes
        # ...

        with multiprocessing.Pool(processes=1, maxtasksperchild=1, initializer=_init, initargs=(q,)) as pool:
            time.sleep(1)

    got exception (when q = manager.Queue() or q = multiprocessing.Queue())

    Process SpawnPoolWorker-2:
Traceback (most recent call last):
  File "/home/foo/miniconda3/envs/py312forge/lib/python3.12/logging/config.py", line 581, in configure
    handler = self.configure_handler(handlers[name])
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/foo/miniconda3/envs/py312forge/lib/python3.12/logging/config.py", line 792, in configure_handler
    proxy_queue = MM().Queue()
                  ^^^^
  File "/home/foo/miniconda3/envs/py312forge/lib/python3.12/multiprocessing/context.py", line 57, in Manager
    m.start()
  File "/home/foo/miniconda3/envs/py312forge/lib/python3.12/multiprocessing/managers.py", line 562, in start
    self._process.start()
  File "/home/foo/miniconda3/envs/py312forge/lib/python3.12/multiprocessing/process.py", line 118, in start
    assert not _current_process._config.get('daemon'), \
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: daemonic processes are not allowed to have children

The above exception was the direct cause of the following exception:
...

  24. vsajip commented on Jul 13, 2024

    @vsajip
    vsajip
    on Jul 13, 2024
    Member

    Not sure this is the same error - what exact version of 3.12 is in use? What happens with 3.13?

  25. noreentry commented on Jul 13, 2024

    @noreentry
    noreentry
    on Jul 13, 2024

    it works on 3.12.3
    doesn't work on 3.12.4
    can't test it on 3.13

  26. estyxx
    added 4 commits that reference this issue on Jul 17, 2024

    pythongh-119819: Fix regression to allow logging configuration with m…

    f01bcec

    pythongh-119819: Update test to skip if _multiprocessing is unavailab…

    d6019a9

    pythongh-119819: Update logging configuration to support joinable mul…

    a9d6e7a

    pythongh-119819: Conditional skip of logging tests that require multi…

    1d65c11
  27. freakboy3742
    added a commit that references this issue on Aug 5, 2024

    [3.12] pythongh-119819: Conditional skip of logging tests that requir…

    902e79f
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    stdlibStandard Library Python modules in the Lib/ directorytype-bugAn unexpected behavior, bug, or error

    Projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions