apprise==1.9.1 causes test failures in the client test suite #16440

mjpieters · 2024-12-18T19:41:35Z

Bug summary

apprise version 1.9.1 was released, and now several tests have started to fail:

FAILED tests/blocks/test_notifications.py::TestMattermostWebhook::test_notify_async - AssertionError: expected call not found.
FAILED tests/blocks/test_notifications.py::TestMattermostWebhook::test_notify_sync - AssertionError: expected call not found.
FAILED tests/blocks/test_notifications.py::TestMattermostWebhook::test_notify_with_multiple_channels - AssertionError: expected call not found.

Downgrading to `apprise==1.9.01 resolves the issues.

Version info

Version:             3.1.9.dev1+2.g81a122a04b
API version:         0.8.4
Python version:      3.12.6
Git commit:          81a122a0
Built:               Wed, Dec 18, 2024 12:20 PM
OS/Arch:             darwin/arm64
Profile:             local
Server type:         server
Pydantic version:    2.10.3

Additional context

Full output for these tests:

--- Logging error ---
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/logging/__init__.py", line 2264, in shutdown
    h.flush()
  File "/home/runner/work/prefect/prefect/src/prefect/logging/handlers.py", line 118, in flush
    return APILogWorker.drain_all(timeout=5)
  File "/home/runner/work/prefect/prefect/src/prefect/_internal/concurrency/services.py", line 240, in drain_all
    futures.append(instance._drain())
  File "/home/runner/work/prefect/prefect/src/prefect/_internal/concurrency/services.py", line 203, in _drain
    logger.debug("Draining service %r", self)
Message: 'Draining service %r'
Arguments: (<test_services.test_queue_service_start_failure_contains_traceback_only_at_debug.<locals>.ExceptionOnHandleService object at 0x7fcfb43f5970>,)
--- Logging error ---
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/logging/__init__.py", line 2264, in shutdown
    h.flush()
  File "/home/runner/work/prefect/prefect/src/prefect/logging/handlers.py", line 118, in flush
    return APILogWorker.drain_all(timeout=5)
  File "/home/runner/work/prefect/prefect/src/prefect/_internal/concurrency/services.py", line 240, in drain_all
    futures.append(instance._drain())
  File "/home/runner/work/prefect/prefect/src/prefect/_internal/concurrency/services.py", line 203, in _drain
    logger.debug("Draining service %r", self)
Message: 'Draining service %r'
Arguments: (<test_services.test_queue_service_start_failure_contains_traceback_only_at_debug.<locals>.ExceptionOnHandleService object at 0x7fcfb43f5970>,)
..                                                                       [100%]
=================================== FAILURES ===================================
___________________ TestMattermostWebhook.test_notify_async ____________________
[gw1] linux -- Python 3.12.8 /opt/hostedtoolcache/Python/3.12.8/x64/bin/python

self = <test_notifications.TestMattermostWebhook object at 0x7fcfb9ae8e60>

    async def test_notify_async(self):
        with patch("apprise.Apprise", autospec=True) as AppriseMock:
            apprise_instance_mock = AppriseMock.return_value
            apprise_instance_mock.async_notify = AsyncMock()
    
            mm_block = MattermostWebhook(
                hostname="example.com",
                token="token",
                include_image=True,
            )
            await mm_block.notify("test")
    
            AppriseMock.assert_called_once()
>           apprise_instance_mock.add.assert_called_once_with(
                f"mmost://{mm_block.hostname}/{mm_block.token.get_secret_value()}/"
                "?image=yes&format=text&overflow=upstream"
            )

tests/blocks/test_notifications.py:165: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/unittest/mock.py:961: in assert_called_once_with
    return self.assert_called_with(*args, **kwargs)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <MagicMock name='Apprise().add' spec='function' id='140529058186304'>
args = ('mmost://example.com/token/?image=yes&format=text&overflow=upstream',)
kwargs = {}
expected = call('', ('mmost://example.com/token/?image=yes&format=text&overflow=upstream',), {})
actual = call('', ('mmost://example.com:8065/token/?image=yes&format=text&overflow=upstream',), {})
_error_message = <function NonCallableMock.assert_called_with.<locals>._error_message at 0x7fcf78970d60>
cause = None

    def assert_called_with(self, /, *args, **kwargs):
        """assert that the last call was made with the specified arguments.
    
        Raises an AssertionError if the args and keyword args passed in are
        different to the last call to the mock."""
        if self.call_args is None:
            expected = self._format_mock_call_signature(args, kwargs)
            actual = 'not called.'
            error_message = ('expected call not found.\nExpected: %s\n  Actual: %s'
                    % (expected, actual))
            raise AssertionError(error_message)
    
        def _error_message():
            msg = self._format_mock_failure_message(args, kwargs)
            return msg
        expected = self._call_matcher(_Call((args, kwargs), two=True))
        actual = self._call_matcher(self.call_args)
        if actual != expected:
            cause = expected if isinstance(expected, Exception) else None
>           raise AssertionError(_error_message()) from cause
E           AssertionError: expected call not found.
E           Expected: add('mmost://example.com/token/?image=yes&format=text&overflow=upstream')
E             Actual: add('mmost://example.com:8065/token/?image=yes&format=text&overflow=upstream')

/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/unittest/mock.py:949: AssertionError
--------------------------- Captured stderr teardown ---------------------------
18:41:10.913 | DEBUG   | MainThread   | prefect._internal.concurrency - Draining service <test_services.test_queue_service_start_failure_contains_traceback_only_at_debug.<locals>.ExceptionOnHandleService object at 0x7fcfb43f5970>
____________________ TestMattermostWebhook.test_notify_sync ____________________
[gw1] linux -- Python 3.12.8 /opt/hostedtoolcache/Python/3.12.8/x64/bin/python

self = <test_notifications.TestMattermostWebhook object at 0x7fcfb9ae9580>

    def test_notify_sync(self):
        with patch("apprise.Apprise", autospec=True) as AppriseMock:
            apprise_instance_mock = AppriseMock.return_value
            apprise_instance_mock.async_notify = AsyncMock()
    
            mm_block = MattermostWebhook(hostname="example.com", token="token")
    
            @flow
            def test_flow():
                mm_block.notify("test")
    
            test_flow()
    
            AppriseMock.assert_called_once()
>           apprise_instance_mock.add.assert_called_once_with(
                f"mmost://{mm_block.hostname}/{mm_block.token.get_secret_value()}/"
                "?image=no&format=text&overflow=upstream"
            )

tests/blocks/test_notifications.py:187: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/unittest/mock.py:961: in assert_called_once_with
    return self.assert_called_with(*args, **kwargs)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <MagicMock name='Apprise().add' spec='function' id='140529056093664'>
args = ('mmost://example.com/token/?image=no&format=text&overflow=upstream',)
kwargs = {}
expected = call('', ('mmost://example.com/token/?image=no&format=text&overflow=upstream',), {})
actual = call('', ('mmost://example.com:8065/token/?image=no&format=text&overflow=upstream',), {})
_error_message = <function NonCallableMock.assert_called_with.<locals>._error_message at 0x7fcf78a61bc0>
cause = None

    def assert_called_with(self, /, *args, **kwargs):
        """assert that the last call was made with the specified arguments.
    
        Raises an AssertionError if the args and keyword args passed in are
        different to the last call to the mock."""
        if self.call_args is None:
            expected = self._format_mock_call_signature(args, kwargs)
            actual = 'not called.'
            error_message = ('expected call not found.\nExpected: %s\n  Actual: %s'
                    % (expected, actual))
            raise AssertionError(error_message)
    
        def _error_message():
            msg = self._format_mock_failure_message(args, kwargs)
            return msg
        expected = self._call_matcher(_Call((args, kwargs), two=True))
        actual = self._call_matcher(self.call_args)
        if actual != expected:
            cause = expected if isinstance(expected, Exception) else None
>           raise AssertionError(_error_message()) from cause
E           AssertionError: expected call not found.
E           Expected: add('mmost://example.com/token/?image=no&format=text&overflow=upstream')
E             Actual: add('mmost://example.com:8065/token/?image=no&format=text&overflow=upstream')

/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/unittest/mock.py:949: AssertionError
----------------------------- Captured stderr call -----------------------------
18:41:11.173 | INFO    | uvicorn.access - 127.0.0.1:56004 - "GET /api/admin/version HTTP/1.1" 200
18:41:11.178 | INFO    | uvicorn.access - 127.0.0.1:56004 - "GET /api/csrf-token?client=f7e92d4f-1ce6-4c55-8120-f4b3489d3399 HTTP/1.1" 422
18:41:11.186 | INFO    | uvicorn.access - 127.0.0.1:56004 - "POST /api/flows/ HTTP/1.1" 201
18:41:11.211 | DEBUG   | prefect.server.events.messaging - Publishing event: prefect.flow-run.Pending with id: 2d1278b4-74b8-437b-b721-96cccec33e3d for resource: prefect.flow-run.6531a346-508d-4218-8977-12bf165027e7
18:41:11.216 | INFO    | uvicorn.access - 127.0.0.1:56004 - "POST /api/flow_runs/ HTTP/1.1" 201
18:41:11.218 | INFO    | prefect.engine - Created flow run 'refined-kiwi' for flow 'test-flow'
        if actual != expected:
            cause = expected if isinstance(expected, Exception) else None
>           raise AssertionError(_error_message()) from cause
E           AssertionError: expected call not found.
E           Expected: add('mmost://example.com/token/?image=no&format=text&overflow=upstream&channel=death-metal-anonymous%2Cgeneral')
E             Actual: add('mmost://example.com:8065/token/?image=no&format=text&overflow=upstream&channel=death-metal-anonymous%2Cgeneral')

/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/unittest/mock.py:949: AssertionError
----------------------------- Captured stderr call -----------------------------
18:41:11.659 | INFO    | uvicorn.access - 127.0.0.1:56010 - "GET /api/admin/version HTTP/1.1" 200
18:41:11.663 | INFO    | uvicorn.access - 127.0.0.1:56010 - "GET /api/csrf-token?client=57eab70d-554c-4d3d-bad6-984748f53b20 HTTP/1.1" 422
18:41:11.671 | INFO    | uvicorn.access - 127.0.0.1:56010 - "POST /api/flows/ HTTP/1.1" 201
18:41:11.695 | DEBUG   | prefect.server.events.messaging - Publishing event: prefect.flow-run.Pending with id: bcdfdd02-a277-4948-8b86-6ac6176800dc for resource: prefect.flow-run.515955c1-ff8b-4b0a-b370-fed[139](https://github.com/PrefectHQ/prefect/actions/runs/12399190036/job/34613590288?pr=16405#step:11:140)76e99d
18:41:11.700 | INFO    | uvicorn.access - 127.0.0.1:56010 - "POST /api/flow_runs/ HTTP/1.1" 201
18:41:11.702 | INFO    | prefect.engine - Created flow run 'bright-camel' for flow 'test-flow'
18:41:11.703 | INFO    | prefect.engine - View at http://localhost:37115/runs/flow-run/515955c1-ff8b-4b0a-b370-fed13976e99d
18:41:11.728 | DEBUG   | prefect.server.events.messaging - Publishing event: prefect.flow-run.Running with id: 9d86362e-289f-4a80-8b7f-98dbc42d7592 for resource: prefect.flow-run.515955c1-ff8b-4b0a-b370-fed13976e99d
18:41:11.733 | INFO    | uvicorn.access - 127.0.0.1:56010 - "POST /api/flow_runs/515955c1-ff8b-4b0a-b370-fed13976e99d/set_state HTTP/1.1" 201
18:41:11.742 | INFO    | uvicorn.access - 127.0.0.1:56010 - "GET /api/flow_runs/515955c1-ff8b-4b0a-b370-fed13976e99d HTTP/1.1" 200
18:41:11.744 | DEBUG   | prefect.task_runner.threadpool - Starting task runner
18:41:11.746 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Running call coroutine_wrapper() in thread 'RunSyncEventLoopThread'
18:41:11.746 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <WatcherThreadCancelScope, name='coroutine_wrapper' RUNNING, runtime=0.00> entered
18:41:11.746 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <WatcherThreadCancelScope, name='coroutine_wrapper' COMPLETED, runtime=0.00> exited
18:41:11.747 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Scheduling coroutine for call coroutine_wrapper(<dropped>) in running loop <_UnixSelectorEventLoop running=True closed=False debug=False>
18:41:11.747 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <AsyncCancelScope, name='coroutine_wrapper' RUNNING, runtime=0.00> entered
18:41:11.747 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <AsyncCancelScope, name='coroutine_wrapper' COMPLETED, runtime=0.00> exited
18:41:11.748 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Finished async call coroutine_wrapper(<dropped>)
18:41:11.748 | DEBUG   | Flow run 'bright-camel' - Executing flow 'test-flow' for flow run 'bright-camel'...
18:41:11.750 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Running call coroutine_wrapper() in thread 'RunSyncEventLoopThread'
18:41:11.750 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <WatcherThreadCancelScope, name='coroutine_wrapper' RUNNING, runtime=0.00> entered
18:41:11.751 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <WatcherThreadCancelScope, name='coroutine_wrapper' COMPLETED, runtime=0.00> exited
18:41:11.751 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Scheduling coroutine for call coroutine_wrapper(<dropped>) in running loop <_UnixSelectorEventLoop running=True closed=False debug=False>
18:41:11.751 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <AsyncCancelScope, name='coroutine_wrapper' RUNNING, runtime=0.00> entered
18:41:11.752 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <AsyncCancelScope, name='coroutine_wrapper' COMPLETED, runtime=0.00> exited
18:41:11.752 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Finished async call coroutine_wrapper(<dropped>)
18:41:11.753 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Running call coroutine_wrapper() in thread 'RunSyncEventLoopThread'
18:41:11.753 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <WatcherThreadCancelScope, name='coroutine_wrapper' RUNNING, runtime=0.00> entered
18:41:11.754 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <WatcherThreadCancelScope, name='coroutine_wrapper' COMPLETED, runtime=0.00> exited
18:41:11.754 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Scheduling coroutine for call coroutine_wrapper(<dropped>) in running loop <_UnixSelectorEventLoop running=True closed=False debug=False>
18:41:11.754 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <AsyncCancelScope, name='coroutine_wrapper' RUNNING, runtime=0.00> entered
18:41:11.755 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - <AsyncCancelScope, name='coroutine_wrapper' COMPLETED, runtime=0.00> exited
18:41:11.755 | DEBUG   | RunSyncEventLoopThread | prefect._internal.concurrency - Finished async call coroutine_wrapper(<dropped>)
18:41:11.776 | DEBUG   | prefect.server.events.messaging - Publishing event: prefect.flow-run.Completed with id: 1d910910-bb22-47b1-829f-08c008ae95a9 for resource: prefect.flow-run.5[159](https://github.com/PrefectHQ/prefect/actions/runs/12399190036/job/34613590288?pr=16405#step:11:160)55c1-ff8b-4b0a-b370-fed13976e99d
18:41:11.782 | INFO    | uvicorn.access - 127.0.0.1:56010 - "POST /api/flow_runs/515955c1-ff8b-4b0a-b370-fed13976e99d/set_state HTTP/1.1" 201
18:41:11.784 | DEBUG   | prefect.task_runner.threadpool - Stopping task runner
18:41:11.787 | INFO    | Flow run 'bright-camel' - Finished in state Completed()
------------------------------ Captured log call -------------------------------
INFO     prefect.engine:flow_engine.py:506 Created flow run 'bright-camel' for flow 'test-flow'
INFO     prefect.engine:flow_engine.py:641 View at http://localhost:37115/runs/flow-run/515955c1-ff8b-4b0a-b370-fed13976e99d
DEBUG    prefect.task_runner.threadpool:task_runners.py:211 Starting task runner
DEBUG    prefect.flow_runs:flow_engine.py:727 Executing flow 'test-flow' for flow run 'bright-camel'...
DEBUG    prefect.task_runner.threadpool:task_runners.py:216 Stopping task runner
INFO     prefect.flow_runs:flow_engine.py:691 Finished in state Completed()
--------------------------- Captured stderr teardown ---------------------------
18:41:11.864 | DEBUG   | MainThread   | prefect._internal.concurrency - Draining service <test_services.test_queue_service_start_failure_contains_traceback_only_at_debug.<locals>.ExceptionOnHandleService object at 0x7fcfb43f5970>

The text was updated successfully, but these errors were encountered:

mjpieters · 2024-12-18T19:43:40Z

Ah, I just saw the fix roll in, so this is a duplicate of #16433.

mjpieters added the bug Something isn't working label Dec 18, 2024

This was referenced Dec 18, 2024

Clean up PrefectDBInterface, use the models consistently #16392

Merged

Refactor prefect.flow decorator #16405

Merged

mjpieters closed this as completed Dec 18, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

apprise==1.9.1 causes test failures in the client test suite #16440

apprise==1.9.1 causes test failures in the client test suite #16440

mjpieters commented Dec 18, 2024

mjpieters commented Dec 18, 2024

apprise==1.9.1 causes test failures in the client test suite #16440

apprise==1.9.1 causes test failures in the client test suite #16440

Comments

mjpieters commented Dec 18, 2024

Bug summary

Version info

Additional context

mjpieters commented Dec 18, 2024