Fix race condition in back2back_test for UDP multicast bus

[lumagi]

Add debug prints to back2back_test to analyze race condition, see #1345.
Might fail if pytest does not print stdout

[codecov]

Codecov Report

Merging #1349 (fa42549) into develop (3ae0879) will increase coverage by 0.11%.
The diff coverage is n/a.

@@ Coverage Diff @@ ## develop #1349 +/- ## =========================================== + Coverage 66.01% 66.12% +0.11%  =========================================== Files 86 86 Lines 8960 8993 +33 =========================================== + Hits 5915 5947 +32  - Misses 3045 3046 +1 

[lumagi]

After three attempts, the race condition was triggered. Contrary to my initial assumption, the log output suggests that the message is returned to the receive buffer of the sender interface multiple times:

Send on Bus 1: Timestamp: 0.000000 ID: 0300 S Rx DL: 3 04 05 06 Received on Bus 2: Timestamp: 1659177979.270310 ID: 0300 S Rx DL: 3 04 05 06 Bus 1 msg cleared: Timestamp: 1659177979.270310 ID: 0300 S Rx DL: 3 04 05 06 Send on Bus 2: Timestamp: 0.000000 ID: 0301 S Rx DL: 3 04 05 06 Bus 2 msg cleared: Timestamp: 1659177979.270439 ID: 0300 S Rx DL: 3 04 05 06 Received on Bus 1: Timestamp: 1659177979.270439 ID: 0300 S Rx DL: 3 04 05 06 

The message is sent on bus 1 and is received four times, twice on each bus. It looks like the message is looped back by the kernel the first time (timesamp A) and then bounces back over the network (timestamp B).

Full log output of failing tests

____________ BasicTestUdpMulticastBusIPv6.test_dlc_less_than_eight _____________ self = <test.back2back_test.BasicTestUdpMulticastBusIPv6 testMethod=test_dlc_less_than_eight> def test_dlc_less_than_eight(self): msg = can.Message(is_extended_id=False, arbitration_id=0x300, data=[4, 5, 6]) > self._send_and_receive(msg) test/back2back_test.py:153: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ test/back2back_test.py:104: in _send_and_receive self._check_received_message(recv_msg, msg) test/back2back_test.py:69: in _check_received_message self.assertEqual(recv_msg.arbitration_id, sent_msg.arbitration_id) E AssertionError: 768 != 769 ----------------------------- Captured stdout call ----------------------------- Send on Bus 1: Timestamp: 0.000000 ID: 0300 S Rx DL: 3 04 05 06 Received on Bus 2: Timestamp: 1659177979.270310 ID: 0300 S Rx DL: 3 04 05 06 Bus 1 msg cleared: Timestamp: 1659177979.270310 ID: 0300 S Rx DL: 3 04 05 06 Send on Bus 2: Timestamp: 0.000000 ID: 0301 S Rx DL: 3 04 05 06 Bus 2 msg cleared: Timestamp: 1659177979.270439 ID: 0300 S Rx DL: 3 04 05 06 Received on Bus 1: Timestamp: 1659177979.270439 ID: 0300 S Rx DL: 3 04 05 06 ___ BasicTestUdpMulticastBusIPv6.test_dlc_less_than_eight_with_clear_timeout ___ self = <test.back2back_test.BasicTestUdpMulticastBusIPv6 testMethod=test_dlc_less_than_eight_with_clear_timeout> def test_dlc_less_than_eight_with_clear_timeout(self): msg = can.Message(is_extended_id=False, arbitration_id=0x300, data=[4, 5, 6]) > self._send_and_receive(msg, bus_clear_timeout=0.3) test/back2back_test.py:157: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ test/back2back_test.py:104: in _send_and_receive self._check_received_message(recv_msg, msg) test/back2back_test.py:69: in _check_received_message self.assertEqual(recv_msg.arbitration_id, sent_msg.arbitration_id) E AssertionError: 768 != 769 ----------------------------- Captured stdout call ----------------------------- Send on Bus 1: Timestamp: 0.000000 ID: 0300 S Rx DL: 3 04 05 06 Received on Bus 2: Timestamp: 1659177979.645180 ID: 0300 S Rx DL: 3 04 05 06 Bus 1 msg cleared: Timestamp: 1659177979.645180 ID: 0300 S Rx DL: 3 04 05 06 Send on Bus 2: Timestamp: 0.000000 ID: 0301 S Rx DL: 3 04 05 06 Bus 2 msg cleared: Timestamp: 1659177979.645577 ID: 0300 S Rx DL: 3 04 05 06 Received on Bus 1: Timestamp: 1659177979.645577 ID: 0300 S Rx DL: 3 04 05 06 ______________ BasicTestUdpMulticastBusIPv6.test_extended_message ______________ self = <test.back2back_test.BasicTestUdpMulticastBusIPv6 testMethod=test_extended_message> def test_extended_message(self): msg = can.Message( is_extended_id=True, arbitration_id=0x123456, data=[10, 11, 12, 13, 14, 15, 16, 17], ) > self._send_and_receive(msg) test/back2back_test.py:143: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ test/back2back_test.py:104: in _send_and_receive self._check_received_message(recv_msg, msg) test/back2back_test.py:69: in _check_received_message self.assertEqual(recv_msg.arbitration_id, sent_msg.arbitration_id) E AssertionError: 1193046 != 1193047 ----------------------------- Captured stdout call ----------------------------- Send on Bus 1: Timestamp: 0.000000 ID: 00123456 X Rx DL: 8 0a 0b 0c 0d 0e 0f 10 11 Received on Bus 2: Timestamp: 1659177979.848080 ID: 00123456 X Rx DL: 8 0a 0b 0c 0d 0e 0f 10 11 Bus 1 msg cleared: Timestamp: 1659177979.848080 ID: 00123456 X Rx DL: 8 0a 0b 0c 0d 0e 0f 10 11 Send on Bus 2: Timestamp: 0.000000 ID: 00123457 X Rx DL: 8 0a 0b 0c 0d 0e 0f 10 11 Bus 2 msg cleared: Timestamp: 1659177979.848243 ID: 00123456 X Rx DL: 8 0a 0b 0c 0d 0e 0f 10 11 Received on Bus 1: Timestamp: 1659177979.848243 ID: 00123456 X Rx DL: 8 0a 0b 0c 0d 0e 0f 10 11 _________________ BasicTestUdpMulticastBusIPv6.test_fd_message _________________ self = <test.back2back_test.BasicTestUdpMulticastBusIPv6 testMethod=test_fd_message> def test_fd_message(self): msg = can.Message( is_fd=True, is_extended_id=True, arbitration_id=0x56789, data=[0xFF] * 64 ) > self._send_and_receive(msg) test/back2back_test.py:233: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ test/back2back_test.py:104: in _send_and_receive self._check_received_message(recv_msg, msg) test/back2back_test.py:69: in _check_received_message self.assertEqual(recv_msg.arbitration_id, sent_msg.arbitration_id) E AssertionError: 354185 != 354186 ----------------------------- Captured stdout call ----------------------------- Send on Bus 1: Timestamp: 0.000000 ID: 00056789 X Rx F DL: 64 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Received on Bus 2: Timestamp: 1659177980.050729 ID: 00056789 X Rx F DL: 64 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Bus 1 msg cleared: Timestamp: 1659177980.050729 ID: 00056789 X Rx F DL: 64 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Send on Bus 2: Timestamp: 0.000000 ID: 0005678a X Rx F DL: 64 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Bus 2 msg cleared: Timestamp: 1659177980.050962 ID: 00056789 X Rx F DL: 64 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Received on Bus 1: Timestamp: 1659177980.050962 ID: 00056789 X Rx F DL: 64 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ____________ BasicTestUdpMulticastBusIPv6.test_fd_message_with_brs _____________ self = <test.back2back_test.BasicTestUdpMulticastBusIPv6 testMethod=test_fd_message_with_brs> def test_fd_message_with_brs(self): msg = can.Message( is_fd=True, bitrate_switch=True, is_extended_id=True, arbitration_id=0x98765, data=[0xFF] * 48, ) > self._send_and_receive(msg) test/back2back_test.py:243: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ test/back2back_test.py:104: in _send_and_receive self._check_received_message(recv_msg, msg) test/back2back_test.py:69: in _check_received_message self.assertEqual(recv_msg.arbitration_id, sent_msg.arbitration_id) E AssertionError: 624485 != 624486 ----------------------------- Captured stdout call ----------------------------- Send on Bus 1: Timestamp: 0.000000 ID: 00098765 X Rx F BS DL: 48 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Received on Bus 2: Timestamp: 1659177980.253407 ID: 00098765 X Rx F BS DL: 48 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Bus 1 msg cleared: Timestamp: 1659177980.253407 ID: 00098765 X Rx F BS DL: 48 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Send on Bus 2: Timestamp: 0.000000 ID: 00098766 X Rx F BS DL: 48 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Bus 2 msg cleared: Timestamp: 1659177980.253712 ID: 00098765 X Rx F BS DL: 48 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff Received on Bus 1: Timestamp: 1659177980.253712 ID: 00098765 X Rx F BS DL: 48 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff _______________ BasicTestUdpMulticastBusIPv6.test_remote_message _______________ self = <test.back2back_test.BasicTestUdpMulticastBusIPv6 testMethod=test_remote_message> def test_remote_message(self): msg = can.Message( is_extended_id=False, arbitration_id=0x200, is_remote_frame=True, dlc=4 ) > self._send_and_receive(msg) test/back2back_test.py:149: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ test/back2back_test.py:104: in _send_and_receive self._check_received_message(recv_msg, msg) test/back2back_test.py:69: in _check_received_message self.assertEqual(recv_msg.arbitration_id, sent_msg.arbitration_id) E AssertionError: 512 != 513 ----------------------------- Captured stdout call ----------------------------- Send on Bus 1: Timestamp: 0.000000 ID: 0200 S Rx R DL: 4 Received on Bus 2: Timestamp: 1659177980.601406 ID: 0200 S Rx R DL: 4 Bus 1 msg cleared: Timestamp: 1659177980.601406 ID: 0200 S Rx R DL: 4 Send on Bus 2: Timestamp: 0.000000 ID: 0201 S Rx R DL: 4 Bus 2 msg cleared: Timestamp: 1659177980.601806 ID: 0200 S Rx R DL: 4 Received on Bus 1: Timestamp: 1659177980.601806 ID: 0200 S Rx R DL: 4 ______________ BasicTestUdpMulticastBusIPv6.test_standard_message ______________ self = <test.back2back_test.BasicTestUdpMulticastBusIPv6 testMethod=test_standard_message> def test_standard_message(self): msg = can.Message( is_extended_id=False, arbitration_id=0x100, data=[1, 2, 3, 4, 5, 6, 7, 8] ) > self._send_and_receive(msg) test/back2back_test.py:135: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ test/back2back_test.py:104: in _send_and_receive self._check_received_message(recv_msg, msg) test/back2back_test.py:69: in _check_received_message self.assertEqual(recv_msg.arbitration_id, sent_msg.arbitration_id) E AssertionError: 256 != 257 ----------------------------- Captured stdout call ----------------------------- Send on Bus 1: Timestamp: 0.000000 ID: 0100 S Rx DL: 8 01 02 03 04 05 06 07 08 Received on Bus 2: Timestamp: 1659177980.806612 ID: 0100 S Rx DL: 8 01 02 03 04 05 06 07 08 Bus 1 msg cleared: Timestamp: 1659177980.806612 ID: 0100 S Rx DL: 8 01 02 03 04 05 06 07 08 Send on Bus 2: Timestamp: 0.000000 ID: 0101 S Rx DL: 8 01 02 03 04 05 06 07 08 Bus 2 msg cleared: Timestamp: 1659177980.806880 ID: 0100 S Rx DL: 8 01 02 03 04 05 06 07 08 Received on Bus 1: Timestamp: 1659177980.806880 ID: 0100 S Rx DL: 8 01 02 03 04 05 06 07 08 

[lumagi]

@felixdivo, @zariiii9003
I have tried tracking down the root issue of the failing IPv6 UDP Multicast unit tests as best as I could. I believe that under some circumstances, the multicast frames are echoed back to the sender more than once in the runner environment. In order to work around this issue, I would propose to use a interface-local multicast address (which is what this pull request will introduce). With this address, the frame should not exposed on the runner network and hence only be echoed back to the sender once. I triggered the unit tests several times in the runner environment, but the issue did not reappear with the interface-local multicast address.

[felixdivo]

@lumagi Thank you for taking the time to fix this!