5: [ RUN ] RecordIntegrationTestFixture.can_record_again_after_stop
15: stdin is not a terminal device. Keyboard handling disabled.[INFO] [1739949727.541278352] [rosbag2_recorder]: Press SPACE for pausing/resuming
15: [INFO] [1739949727.543589196] [rosbag2_recorder]: Listening for topics...
15: [INFO] [1739949727.544010616] [rosbag2_recorder]: Event publisher thread: Starting
15: [INFO] [1739949727.545092141] [rosbag2_recorder]: Subscribed to topic '/can_record_again_after_stop_topic'
15: [INFO] [1739949727.545195423] [rosbag2_recorder]: Recording...
15: [INFO] [1739949727.545510770] [rosbag2_recorder]: All requested topics are subscribed. Stopping discovery...
15: [INFO] [1739949727.665805436] [rosbag2_recorder]: Pausing recording.
15: [INFO] [1739949727.666431920] [rosbag2_recorder]: Event publisher thread: Exiting
15: [INFO] [1739949727.666767578] [rosbag2_recorder]: Recording stopped
15: [INFO] [1739949727.668759854] [rosbag2_recorder]: Listening for topics...
15: [INFO] [1739949727.668783415] [rosbag2_recorder]: Event publisher thread: Starting
15: [INFO] [1739949727.669554603] [rosbag2_recorder]: Subscribed to topic '/can_record_again_after_stop_topic'
15: [INFO] [1739949727.669638865] [rosbag2_recorder]: Recording...
15: [INFO] [1739949727.669854790] [rosbag2_recorder]: All requested topics are subscribed. Stopping discovery...
15: /tmp/ws/src/rosbag2/rosbag2_transport/test/rosbag2_transport/test_record.cpp:171: Failure
15: Value of: recorded_messages
15: Expected: has a size that is equal to 4
15: Actual: { (ptr = 0x7ff7200023a0, value = 64-byte object <20-23 00-20 F7-7F 00-00 B0-22 00-20 F7-7F 00-00 D6-53 93-FE 0E-8B 25-18 CD-C0 92-FE 0E-8B 25-18 A0-17 00-20 F7-7F 00-00 22-00 00-00 00-00 00-00 22-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>), (ptr = 0x7ff7200034b0, value = 64-byte object <B0-1E 00-20 F7-7F 00-00 10-34 00-20 F7-7F 00-00 E8-3D 91-01 0F-8B 25-18 5F-67 90-01 0F-8B 25-18 80-1E 00-20 F7-7F 00-00 22-00 00-00 00-00 00-00 22-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>), (ptr = 0x7ff720003620, value = 64-byte object <C0-35 00-20 F7-7F 00-00 50-32 00-20 F7-7F 00-00 2B-CF C9-04 0F-8B 25-18 41-AA C9-04 0F-8B 25-18 20-32 00-20 F7-7F 00-00 22-00 00-00 00-00 00-00 22-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>), (ptr = 0x557aa0467840, value = 64-byte object <70-0D 46-A0 7A-55 00-00 80-32 00-20 F7-7F 00-00 68-E8 C9-04 0F-8B 25-18 41-AA C9-04 0F-8B 25-18 50-90 48-A0 7A-55 00-00 22-00 00-00 00-00 00-00 22-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>), (ptr = 0x557aa046ac00, value = 64-byte object <10-BF 3A-A0 7A-55 00-00 D0-36 00-20 F7-7F 00-00 7B-5D C7-07 0F-8B 25-18 98-B3 C6-07 0F-8B 25-18 30-35 00-20 F7-7F 00-00 22-00 00-00 00-00 00-00 22-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>) }, whose size 5 doesn't match
15:
15: => recorded_messages[0].send_timestamp = 1739949727565398221
15: recorded_messages[0].recv_timestamp = 1739949727565435862
15: => recorded_messages[1].send_timestamp = 1739949727615575903
15: recorded_messages[1].recv_timestamp = 1739949727615630824
15: => recorded_messages[2].send_timestamp = 1739949727669660225
15: recorded_messages[2].recv_timestamp = 1739949727669669675
15: => recorded_messages[3].send_timestamp = 1739949727669660225
15: recorded_messages[3].recv_timestamp = 1739949727669676136
15: => recorded_messages[4].send_timestamp = 1739949727719797656
15: recorded_messages[4].recv_timestamp = 1739949727719841147
15: /tmp/ws/src/rosbag2/rosbag2_transport/test/rosbag2_transport/test_record.cpp:194: Failure
15: Value of: basic_type_messages
15: Expected: has a size that is equal to 4
15: Actual: { (ptr = 0x557aa0307d60, value = 48-byte object <00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 54-2C 31-0B DC-1E 01-00 00-00 00-00 00-00 00-00>), (ptr = 0x557aa0749ee0, value = 48-byte object <00-00 00-2E 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 65-20 00-00 00-00 00-00 00-00 72-C9 2E-0E DC-1E 01-00 01-00 00-00 00-00 00-00>), (ptr = 0x557aa0749fc0, value = 48-byte object <00-00 00-2E 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 65-20 00-00 00-00 00-00 00-00 E2-1E 68-11 DC-1E 01-00 00-00 00-00 00-00 00-00>), (ptr = 0x557aa0575490, value = 48-byte object <00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 E2-1E 68-11 DC-1E 01-00 00-00 00-00 00-00 00-00>), (ptr = 0x557aa0592510, value = 48-byte object <00-00 00-2E 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 65-20 00-00 00-00 00-00 00-00 1D-12 65-14 DC-1E 01-00 01-00 00-00 00-00 00-00>) }, whose size 5 doesn't match
15:
15: => basic_type_messages[0].uint64_value = 0
15: basic_type_messages[0].int64_value = 315405406121044
15: => basic_type_messages[1].uint64_value = 1
15: basic_type_messages[1].int64_value = 315405456296306
15: => basic_type_messages[2].uint64_value = 0
15: basic_type_messages[2].int64_value = 315405510385378
15: => basic_type_messages[3].uint64_value = 0
15: basic_type_messages[3].int64_value = 315405510385378
15: => basic_type_messages[4].uint64_value = 1
15: basic_type_messages[4].int64_value = 315405560517149
15: /tmp/ws/src/rosbag2/rosbag2_transport/test/rosbag2_transport/test_record.cpp:208: Failure
15: Value of: basic_type_messages[i]->uint64_value
15: Expected: is equal to 1
15: Actual: 0 (of type unsigned long)
15:
15: /tmp/ws/src/rosbag2/rosbag2_transport/test/rosbag2_transport/test_record.cpp:208: Failure
15: Value of: basic_type_messages[i]->uint64_value
15: Expected: is equal to 0
15: Actual: 1 (of type unsigned long)
15:
15: [INFO] [1739949727.772790963] [rosbag2_recorder]: Pausing recording.
15: [INFO] [1739949727.773680534] [rosbag2_recorder]: Event publisher thread: Exiting
15: [INFO] [1739949727.773726605] [rosbag2_recorder]: Recording stopped
15: [ FAILED ] RecordIntegrationTestFixture.can_record_again_after_stop (253 ms)
Description
Sometimes, on CI the RecordIntegrationTestFixture.can_record_again_after_stop test fails because recorder receiving 5 messages while expected only 4.
It seems that the subscription from the first run hasn't been deleted and triggered callback twice.
It was added debug information in the #1871 PR.
Expected Behavior
The test shall pass without errors and the Recorder shall not receive extra unexpected messages
Actual Behavior
Sometimes Rosbag2 recorder receives one extra message after calling
recorder::stop()and thenrecorder::record()again.To Reproduce
The issue reproduces on CI only.
Link to the failed CI job https://build.ros2.org/job/Rpr__rosbag2__ubuntu_noble_amd64/528/testReport/junit/rosbag2_transport/RecordIntegrationTestFixture/can_record_again_after_stop/
Full log with debug info available here https://build.ros2.org/job/Rpr__rosbag2__ubuntu_noble_amd64/528/consoleText
Log for failing test: Click to expand
System (please complete the following information)
Additional context
** Add any other context about the problem here **