We're seeing test_on_af_message_callback fail on 0.11.6 from zigpy==0.59.0 as required by home-assistant==2023.11.0.
zigpy-znp> FAILED tests/application/test_zigpy_callbacks.py::test_on_af_message_callback[FormedLaunchpadCC26X2R1] - AssertionError: Expected 'handle_message' to be called once. Called 0 times.
zigpy-znp> FAILED tests/application/test_zigpy_callbacks.py::test_on_af_message_callback[FormedZStack3CC2531] - AssertionError: Expected 'handle_message' to be called once. Called 0 times.
zigpy-znp> FAILED tests/application/test_zigpy_callbacks.py::test_on_af_message_callback[FormedZStack1CC2531] - AssertionError: Expected 'handle_message' to be called once. Called 0 times.
Full log
zigpy-znp> _____________ test_on_af_message_callback[FormedLaunchpadCC26X2R1] _____________
zigpy-znp>
zigpy-znp> self = , args = ()
zigpy-znp> kwargs = {'cluster': 2, 'dst_addressing': , 'dst_ep': 1, 'message': b'test', ...}
zigpy-znp> msg = "Expected 'handle_message' to be called once. Called 0 times."
zigpy-znp>
zigpy-znp> def assert_called_once_with(self, /, *args, **kwargs):
zigpy-znp> """assert that the mock was called exactly once and that that call was
zigpy-znp> with the specified arguments."""
zigpy-znp> if not self.call_count == 1:
zigpy-znp> msg = ("Expected '%s' to be called once. Called %s times.%s"
zigpy-znp> % (self._mock_name or 'mock',
zigpy-znp> self.call_count,
zigpy-znp> self._calls_repr()))
zigpy-znp> > raise AssertionError(msg)
zigpy-znp> E AssertionError: Expected 'handle_message' to be called once. Called 0 times.
zigpy-znp>
zigpy-znp> args = ()
zigpy-znp> kwargs = {'cluster': 2, 'dst_addressing': , 'dst_ep': 1, 'message': b'test', ...}
zigpy-znp> msg = "Expected 'handle_message' to be called once. Called 0 times."
zigpy-znp> self =
zigpy-znp>
zigpy-znp> /nix/store/ffll6glz3gwx342z0ch8wx30p5cnqz1z-python3-3.11.5/lib/python3.11/unittest/mock.py:950: AssertionError
zigpy-znp>
zigpy-znp> During handling of the above exception, another exception occurred:
zigpy-znp>
zigpy-znp> device =
zigpy-znp> make_application = .inner at 0x7ffff45dd440>
zigpy-znp> mocker =
zigpy-znp>
zigpy-znp> @pytest.mark.parametrize("device", FORMED_DEVICES)
zigpy-znp> async def test_on_af_message_callback(device, make_application, mocker):
zigpy-znp> app, znp_server = make_application(server_cls=device)
zigpy-znp> await app.startup(auto_form=False)
zigpy-znp>
zigpy-znp> mocker.patch.object(app, "handle_message")
zigpy-znp> device = app.add_initialized_device(ieee=t.EUI64(range(8)), nwk=0xAABB)
zigpy-znp>
zigpy-znp> af_message = c.AF.IncomingMsg.Callback(
zigpy-znp> GroupId=0x0000,
zigpy-znp> ClusterId=2,
zigpy-znp> SrcAddr=device.nwk,
zigpy-znp> SrcEndpoint=4,
zigpy-znp> DstEndpoint=1, # ZHA endpoint
zigpy-znp> WasBroadcast=False,
zigpy-znp> LQI=19,
zigpy-znp> SecurityUse=False,
zigpy-znp> TimeStamp=0,
zigpy-znp> TSN=0,
zigpy-znp> Data=b"test",
zigpy-znp> MacSrcAddr=0x0000,
zigpy-znp> MsgResultRadius=1,
zigpy-znp> )
zigpy-znp>
zigpy-znp> # Normal message
zigpy-znp> znp_server.send(af_message)
zigpy-znp> await asyncio.sleep(0.1)
zigpy-znp>
zigpy-znp> > app.handle_message.assert_called_once_with(
zigpy-znp> sender=device,
zigpy-znp> profile=260,
zigpy-znp> cluster=2,
zigpy-znp> src_ep=4,
zigpy-znp> dst_ep=1,
zigpy-znp> message=b"test",
zigpy-znp> dst_addressing=zigpy_t.AddrMode.NWK,
zigpy-znp> )
zigpy-znp> E AssertionError: Expected 'handle_message' to be called once. Called 0 times.
zigpy-znp>
zigpy-znp> af_message = AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=2, SrcAddr=0xAABB, SrcEndpoint=4, DstEndpoint=1, WasBroadcast=, TimeStamp=0, TSN=0, Data=b'\x74\x65\x73\x74', MacSrcAddr=0x0000, MsgResultRadius=1)
zigpy-znp> app =
zigpy-znp> device =
zigpy-znp> make_application = .inner at 0x7ffff45dd440>
zigpy-znp> mocker =
zigpy-znp> znp_server =
zigpy-znp>
zigpy-znp> tests/application/test_zigpy_callbacks.py:128: AssertionError
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:41.158 ERROR Task was destroyed but it is pending!
zigpy-znp> task: .callback() running at /build/source/tests/conftest.py:388> wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:43.671 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:43.672 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:46.192 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:46.193 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:41.158 ERROR Task was destroyed but it is pending!
zigpy-znp> task: .callback() running at /build/source/tests/conftest.py:388> wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:43.671 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:43.672 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:46.192 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:46.193 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:48.701 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:48.701 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> _______________ test_on_af_message_callback[FormedZStack3CC2531] _______________
zigpy-znp>
zigpy-znp> self = , args = ()
zigpy-znp> kwargs = {'cluster': 2, 'dst_addressing': , 'dst_ep': 1, 'message': b'test', ...}
zigpy-znp> msg = "Expected 'handle_message' to be called once. Called 0 times."
zigpy-znp>
zigpy-znp> def assert_called_once_with(self, /, *args, **kwargs):
zigpy-znp> """assert that the mock was called exactly once and that that call was
zigpy-znp> with the specified arguments."""
zigpy-znp> if not self.call_count == 1:
zigpy-znp> msg = ("Expected '%s' to be called once. Called %s times.%s"
zigpy-znp> % (self._mock_name or 'mock',
zigpy-znp> self.call_count,
zigpy-znp> self._calls_repr()))
zigpy-znp> > raise AssertionError(msg)
zigpy-znp> E AssertionError: Expected 'handle_message' to be called once. Called 0 times.
zigpy-znp>
zigpy-znp> args = ()
zigpy-znp> kwargs = {'cluster': 2, 'dst_addressing': , 'dst_ep': 1, 'message': b'test', ...}
zigpy-znp> msg = "Expected 'handle_message' to be called once. Called 0 times."
zigpy-znp> self =
zigpy-znp>
zigpy-znp> /nix/store/ffll6glz3gwx342z0ch8wx30p5cnqz1z-python3-3.11.5/lib/python3.11/unittest/mock.py:950: AssertionError
zigpy-znp>
zigpy-znp> During handling of the above exception, another exception occurred:
zigpy-znp>
zigpy-znp> device =
zigpy-znp> make_application = .inner at 0x7ffff43734c0>
zigpy-znp> mocker =
zigpy-znp>
zigpy-znp> @pytest.mark.parametrize("device", FORMED_DEVICES)
zigpy-znp> async def test_on_af_message_callback(device, make_application, mocker):
zigpy-znp> app, znp_server = make_application(server_cls=device)
zigpy-znp> await app.startup(auto_form=False)
zigpy-znp>
zigpy-znp> mocker.patch.object(app, "handle_message")
zigpy-znp> device = app.add_initialized_device(ieee=t.EUI64(range(8)), nwk=0xAABB)
zigpy-znp>
zigpy-znp> af_message = c.AF.IncomingMsg.Callback(
zigpy-znp> GroupId=0x0000,
zigpy-znp> ClusterId=2,
zigpy-znp> SrcAddr=device.nwk,
zigpy-znp> SrcEndpoint=4,
zigpy-znp> DstEndpoint=1, # ZHA endpoint
zigpy-znp> WasBroadcast=False,
zigpy-znp> LQI=19,
zigpy-znp> SecurityUse=False,
zigpy-znp> TimeStamp=0,
zigpy-znp> TSN=0,
zigpy-znp> Data=b"test",
zigpy-znp> MacSrcAddr=0x0000,
zigpy-znp> MsgResultRadius=1,
zigpy-znp> )
zigpy-znp>
zigpy-znp> # Normal message
zigpy-znp> znp_server.send(af_message)
zigpy-znp> await asyncio.sleep(0.1)
zigpy-znp>
zigpy-znp> > app.handle_message.assert_called_once_with(
zigpy-znp> sender=device,
zigpy-znp> profile=260,
zigpy-znp> cluster=2,
zigpy-znp> src_ep=4,
zigpy-znp> dst_ep=1,
zigpy-znp> message=b"test",
zigpy-znp> dst_addressing=zigpy_t.AddrMode.NWK,
zigpy-znp> )
zigpy-znp> E AssertionError: Expected 'handle_message' to be called once. Called 0 times.
zigpy-znp>
zigpy-znp> af_message = AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=2, SrcAddr=0xAABB, SrcEndpoint=4, DstEndpoint=1, WasBroadcast=, TimeStamp=0, TSN=0, Data=b'\x74\x65\x73\x74', MacSrcAddr=0x0000, MsgResultRadius=1)
zigpy-znp> app =
zigpy-znp> device =
zigpy-znp> make_application = .inner at 0x7ffff43734c0>
zigpy-znp> mocker =
zigpy-znp> znp_server =
zigpy-znp>
zigpy-znp> tests/application/test_zigpy_callbacks.py:128: AssertionError
zigpy-znp> ------------------------------ Captured log call -------------------------------
zigpy-znp> 2023-11-01 21:16:48.721 WARNING Server does not have a handler for command SYS.NVLength.Req(SysId=1, ItemId=4, SubId=0)
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:49.192 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:49.193 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ------------------------------ Captured log call -------------------------------
zigpy-znp> 2023-11-01 21:16:49.211 WARNING Server does not have a handler for command SYS.NVLength.Req(SysId=1, ItemId=4, SubId=0)
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:49.683 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:49.684 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ------------------------------ Captured log call -------------------------------
zigpy-znp> 2023-11-01 21:16:49.706 WARNING Server does not have a handler for command SYS.NVLength.Req(SysId=1, ItemId=4, SubId=0)
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:50.179 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:50.180 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ------------------------------ Captured log call -------------------------------
zigpy-znp> 2023-11-01 21:16:50.203 WARNING Server does not have a handler for command SYS.NVLength.Req(SysId=1, ItemId=4, SubId=0)
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:49.192 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:49.193 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:49.683 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:49.684 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:50.179 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:50.180 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:50.677 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:50.677 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> _______________ test_on_af_message_callback[FormedZStack1CC2531] _______________
zigpy-znp>
zigpy-znp> self = , args = ()
zigpy-znp> kwargs = {'cluster': 2, 'dst_addressing': , 'dst_ep': 1, 'message': b'test', ...}
zigpy-znp> msg = "Expected 'handle_message' to be called once. Called 0 times."
zigpy-znp>
zigpy-znp> def assert_called_once_with(self, /, *args, **kwargs):
zigpy-znp> """assert that the mock was called exactly once and that that call was
zigpy-znp> with the specified arguments."""
zigpy-znp> if not self.call_count == 1:
zigpy-znp> msg = ("Expected '%s' to be called once. Called %s times.%s"
zigpy-znp> % (self._mock_name or 'mock',
zigpy-znp> self.call_count,
zigpy-znp> self._calls_repr()))
zigpy-znp> > raise AssertionError(msg)
zigpy-znp> E AssertionError: Expected 'handle_message' to be called once. Called 0 times.
zigpy-znp>
zigpy-znp> args = ()
zigpy-znp> kwargs = {'cluster': 2, 'dst_addressing': , 'dst_ep': 1, 'message': b'test', ...}
zigpy-znp> msg = "Expected 'handle_message' to be called once. Called 0 times."
zigpy-znp> self =
zigpy-znp>
zigpy-znp> /nix/store/ffll6glz3gwx342z0ch8wx30p5cnqz1z-python3-3.11.5/lib/python3.11/unittest/mock.py:950: AssertionError
zigpy-znp>
zigpy-znp> During handling of the above exception, another exception occurred:
zigpy-znp>
zigpy-znp> device =
zigpy-znp> make_application = .inner at 0x7ffff4ad4f40>
zigpy-znp> mocker =
zigpy-znp>
zigpy-znp> @pytest.mark.parametrize("device", FORMED_DEVICES)
zigpy-znp> async def test_on_af_message_callback(device, make_application, mocker):
zigpy-znp> app, znp_server = make_application(server_cls=device)
zigpy-znp> await app.startup(auto_form=False)
zigpy-znp>
zigpy-znp> mocker.patch.object(app, "handle_message")
zigpy-znp> device = app.add_initialized_device(ieee=t.EUI64(range(8)), nwk=0xAABB)
zigpy-znp>
zigpy-znp> af_message = c.AF.IncomingMsg.Callback(
zigpy-znp> GroupId=0x0000,
zigpy-znp> ClusterId=2,
zigpy-znp> SrcAddr=device.nwk,
zigpy-znp> SrcEndpoint=4,
zigpy-znp> DstEndpoint=1, # ZHA endpoint
zigpy-znp> WasBroadcast=False,
zigpy-znp> LQI=19,
zigpy-znp> SecurityUse=False,
zigpy-znp> TimeStamp=0,
zigpy-znp> TSN=0,
zigpy-znp> Data=b"test",
zigpy-znp> MacSrcAddr=0x0000,
zigpy-znp> MsgResultRadius=1,
zigpy-znp> )
zigpy-znp>
zigpy-znp> # Normal message
zigpy-znp> znp_server.send(af_message)
zigpy-znp> await asyncio.sleep(0.1)
zigpy-znp>
zigpy-znp> > app.handle_message.assert_called_once_with(
zigpy-znp> sender=device,
zigpy-znp> profile=260,
zigpy-znp> cluster=2,
zigpy-znp> src_ep=4,
zigpy-znp> dst_ep=1,
zigpy-znp> message=b"test",
zigpy-znp> dst_addressing=zigpy_t.AddrMode.NWK,
zigpy-znp> )
zigpy-znp> E AssertionError: Expected 'handle_message' to be called once. Called 0 times.
zigpy-znp>
zigpy-znp> af_message = AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=2, SrcAddr=0xAABB, SrcEndpoint=4, DstEndpoint=1, WasBroadcast=, TimeStamp=0, TSN=0, Data=b'\x74\x65\x73\x74', MacSrcAddr=0x0000, MsgResultRadius=1)
zigpy-znp> app =
zigpy-znp> device =
zigpy-znp> make_application = .inner at 0x7ffff4ad4f40>
zigpy-znp> mocker =
zigpy-znp> znp_server =
zigpy-znp>
zigpy-znp> tests/application/test_zigpy_callbacks.py:128: AssertionError
zigpy-znp> ------------------------------ Captured log call -------------------------------
zigpy-znp> 2023-11-01 21:16:50.855 WARNING Your network is using the insecure Zigbee2MQTT network key!
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:51.179 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:51.179 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ------------------------------ Captured log call -------------------------------
zigpy-znp> 2023-11-01 21:16:51.356 WARNING Your network is using the insecure Zigbee2MQTT network key!
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:51.680 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:51.680 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ------------------------------ Captured log call -------------------------------
zigpy-znp> 2023-11-01 21:16:51.856 WARNING Your network is using the insecure Zigbee2MQTT network key!
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:52.180 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:52.180 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ------------------------------ Captured log call -------------------------------
zigpy-znp> 2023-11-01 21:16:52.356 WARNING Your network is using the insecure Zigbee2MQTT network key!
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:51.179 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:51.179 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:51.680 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:51.680 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:52.180 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:52.180 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> ---------------------------- Captured log teardown -----------------------------
zigpy-znp> 2023-11-01 21:16:52.679 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
zigpy-znp> 2023-11-01 21:16:52.680 ERROR Task was destroyed but it is pending!
zigpy-znp> task: wait_for=>
We're seeing
test_on_af_message_callbackfail on 0.11.6 fromzigpy==0.59.0as required byhome-assistant==2023.11.0.Full log