ardupilot
ardupilot copied to clipboard
ArduPilot
Add ID and Seq to MSG, allowing for long-message reassembly by log analyzers
MAVLink's STATUSTEXT has had these fields for years, but MSG has not.
When we try to log a message we will break it into chunks which fit into MSG packets and add extra information so a tool can reassemble the long text.
This is MAVExplorer looking at the logs from the new autotest:
New:
2025-06-25 20:52:47.900 SRC=250/250:AT-0002.2: ##################################################################################
2025-06-25 20:52:47.900 SRC=250/250:AT-0002.2: ########## LoggerMsgChunks (create MSG dataflash entries for very long messages) ##########
2025-06-25 20:52:47.920 SRC=250/250:AT-0002.2: ##################################################################################
2025-06-25 20:52:47.920 SRC=250/250:AT-0002.2: Doing timesync roundtrip
2025-06-25 20:52:48.900 SRC=250/250:AT-0002.3: Received: TIMESYNC {tc1 : 9104781000, ts1 : 142250}
2025-06-25 20:52:48.900 SRC=250/250:AT-0002.3: Received TIMESYNC response after 0.000000s
2025-06-25 20:52:51.000 GPS 1: probing for u-blox at 230400 baud
2025-06-25 20:52:51.100 GPS 1: detected u-blox
2025-06-25 20:52:51.860 SRC=250/250:AT-0002.3: RC values good
2025-06-25 20:52:52.820 SRC=250/250:AT-0002.3: Changing mode to AUTO
2025-06-25 20:52:52.820 SRC=250/250:AT-0002.3: Sending COMMAND_LONG to (2,1) (MAV_CMD_DO_SET_MODE=176) (p1=1.000000 p2=10.000000 p3=0.000000 p4=0.000000 p5=0.000000 p6=0.000000 p7=0.000000)
2025-06-25 20:52:54.820 SRC=250/250:AT-0002.3: Got mode AUTO
2025-06-25 20:52:54.880 SRC=250/250:AT-0002.3: Sending param_request_read for (LOG_DISARMED)
2025-06-25 20:52:56.020 SRC=250/250:AT-0002.3: get_parameter(LOG_DISARMED): PARAM_VALUE {param_id : LOG_DISARMED, param_value : 1.0, param_type : 2, param_count : 1041, param_index : 65535}
2025-06-25 20:52:56.040 SRC=250/250:AT-0002.3: LOG_DISARMED has expected value 1.000000
2025-06-25 20:52:56.040 SRC=250/250:This is a short message
2025-06-25 20:52:56.040 SRC=250/250:This is undubitably a ridiculously verbose and needlessly wordy missive, unavoidably designed to exceed disappointingly miniscule log buffers
2025-06-25 20:52:56.920 SRC=250/250:AT-0002.3: Delaying 10.000000 seconds
2025-06-25 20:53:01.420 EKF3 IMU0 origin set
2025-06-25 20:53:02.000 Event: DATA_SET_HOME
2025-06-25 20:53:01.420 EKF3 IMU1 origin set
2025-06-25 20:53:06.940 SRC=250/250:AT-0002.5: log list: ['logs/00000001.BIN', 'logs/00000002.BIN']
2025-06-25 20:53:08.020 SRC=250/250:AT-0002.5: Disarm motors with MAVLink cmd
2025-06-25 20:53:08.920 SRC=250/250:AT-0002.5: Sending COMMAND_LONG to (2,1) (MAV_CMD_COMPONENT_ARM_DISARM=400) (p1=0.000000 p2=0.000000 p3=0.000000 p4=0.000000 p5=0.000000 p6=0.000000 p7=0.000000)
2025-06-25 20:53:08.940 SRC=250/250:AT-0002.5: ACK received: COMMAND_ACK {command : 400, result : 0, progress : 0, result_param2 : 0, target_system : 250, target_component : 250} (0.000000s)
2025-06-25 20:53:08.940 SRC=250/250:AT-0002.5: Waiting for DISARM
2025-06-25 20:53:09.000 Field Elevation Set: 343m
2025-06-25 20:53:09.900 SRC=250/250:AT-0002.5: Waiting for disarm (0.00s so far of allowed 30.00)
2025-06-25 20:53:09.999 PreArm: 3D Accel calibration needed
2025-06-25 20:53:10.820 SRC=250/250:AT-0002.5: DISARMED after 0.00 seconds (allowed=30.00)
2025-06-25 20:53:11.840 SRC=250/250:AT-0002.5: Rebooting SITL
2025-06-25 20:53:11.840 SRC=250/250:AT-0002.5: Sending param_request_read for (STAT_RESET)
2025-06-25 20:53:12.059 SRC=250/250:AT-0002.5: get_parameter(STAT_RESET): PARAM_VALUE {param_id : STAT_RESET, param_value : 1.0, param_type : 6, param_count : 1041, param_index : 65535}
2025-06-25 20:53:12.079 SRC=250/250:AT-0002.5: Sending param_request_read for (STAT_BOOTCNT)
Old:
1970-01-01 10:00:05.791 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: #####
1970-01-01 10:00:05.791 ##################################'
1970-01-01 10:00:05.791 SRC=250/250:AT-0003.6: m.Message='############################
1970-01-01 10:00:05.791 ###############'
1970-01-01 10:00:05.791 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: #####
1970-01-01 10:00:05.791 ##### LoggerMsgChunks (create MSG '
1970-01-01 10:00:05.791 SRC=250/250:AT-0003.6: m.Message='dataflash entries for very l
1970-01-01 10:00:05.791 ong messages) #######'
1970-01-01 10:00:05.791 SRC=250/250:AT-0003.6: m.Message='###'
1970-01-01 10:00:05.811 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: #####
1970-01-01 10:00:05.811 ##################################'
1970-01-01 10:00:05.811 SRC=250/250:AT-0003.6: m.Message='############################
1970-01-01 10:00:05.811 ###############'
1970-01-01 10:00:05.811 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: Doing
1970-01-01 10:00:05.811 timesync roundtrip'
1970-01-01 10:00:05.811 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: Recei
1970-01-01 10:00:05.811 ved: TIMESYNC {tc1 : 9122274000, t'
1970-01-01 10:00:05.811 SRC=250/250:AT-0003.6: m.Message='s1 : 142250}'
1970-01-01 10:00:05.811 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: Recei
1970-01-01 10:00:05.811 ved TIMESYNC response after 0.0000'
1970-01-01 10:00:05.811 SRC=250/250:AT-0003.6: m.Message='00s'
1970-01-01 10:00:05.811 SRC=250/250:AT-0003.6: m.Message='GPS 1: probing for u-blox at
1970-01-01 10:00:05.811 230400 baud'
1970-01-01 10:00:05.831 SRC=250/250:AT-0003.6: m.Message='GPS 1: detected u-blox'
1970-01-01 10:00:05.831 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: RC va
1970-01-01 10:00:05.831 lues good'
1970-01-01 10:00:05.831 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: Chang
1970-01-01 10:00:05.831 ing mode to AUTO'
1970-01-01 10:00:05.831 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: Sendi
1970-01-01 10:00:05.831 ng COMMAND_LONG to (2,1) (MAV_CMD_'
1970-01-01 10:00:05.831 SRC=250/250:AT-0003.6: m.Message='DO_SET_MODE=176) (p1=1.00000
1970-01-01 10:00:05.831 0 p2=10.000000 p3=0.00'
1970-01-01 10:00:05.831 SRC=250/250:AT-0003.6: m.Message='0000 p4=0.000000 p5=0.000000
1970-01-01 10:00:05.831 p6=0.000000 p7=0.000'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='000)'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: Got m
1970-01-01 10:00:05.851 ode AUTO'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.3: Sendi
1970-01-01 10:00:05.851 ng param_request_read for (LOG_DIS'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='ARMED)'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.4: get_p
1970-01-01 10:00:05.851 arameter(LOG_DISARMED): PARAM_VALU'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='E {param_id : LOG_DISARMED,
1970-01-01 10:00:05.851 param_value : 1.0, par'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='am_type : 2, param_count : 1
1970-01-01 10:00:05.851 041, param_index : 655'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='35}'
1970-01-01 10:00:05.851 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:AT-0002.4: LOG_D
1970-01-01 10:00:05.871 ISARMED has expected value 1.00000'
1970-01-01 10:00:05.871 SRC=250/250:AT-0003.6: m.Message='0'
1970-01-01 10:00:05.871 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:This is a short
1970-01-01 10:00:05.871 message'
1970-01-01 10:00:05.871 SRC=250/250:AT-0003.6: Received short message
1970-01-01 10:00:05.871 SRC=250/250:AT-0003.6: m.Message='SRC=250/250:This is undubita
1970-01-01 10:00:05.871 bly a ridiculously verbose and nee'
1970-01-01 10:00:05.871 SRC=250/250:AT-0003.6: Text: This is undubitably a ridiculousl
1970-01-01 10:00:05.871 y verbose and nee
1970-01-01 10:00:05.871 SRC=250/250:AT-0003.6: m.Message='dlessly wordy missive, unavo
1970-01-01 10:00:05.871 idably designed to exc'
1970-01-01 10:00:05.871 SRC=250/250:AT-0003.6: Text: This is undubitably a ridiculousl
1970-01-01 10:00:05.871 y verbose and needlessly wordy missive, unavoidabl
1970-01-01 10:00:05.871 y designed to exc
1970-01-01 10:00:05.891 SRC=250/250:AT-0003.6: m.Message='eed disappointingly miniscul
1970-01-01 10:00:05.891 e log buffers'
1970-01-01 10:00:05.891 SRC=250/250:AT-0003.6: Text: This is undubitably a ridiculousl
1970-01-01 10:00:05.891 y verbose and needlessly wordy missive, unavoidabl
1970-01-01 10:00:05.891 y designed to exceed disappointingly miniscule log
1970-01-01 10:00:05.891 buffers
1970-01-01 10:00:06.051 SRC=250/250:AT-0003.6: set_parameters: ({})
1970-01-01 10:00:06.111 SRC=250/250:AT-0003.6: Doing implicit context-pop reboot
1970-01-01 10:00:06.111 SRC=250/250:AT-0003.6: Disarm motors with MAVLink cmd
1970-01-01 10:00:06.271 AHRS: EKF3 active
1970-01-01 10:00:06.871 EKF3 IMU0 tilt alignment complete
1970-01-01 10:00:06.871 EKF3 IMU1 tilt alignment complete
1970-01-01 10:00:06.951 EKF3 IMU0 MAG0 initial yaw alignment complete
1970-01-01 10:00:06.951 EKF3 IMU1 MAG0 initial yaw alignment complete
1970-01-01 10:00:07.111 SRC=250/250:AT-0003.6: Sending COMMAND_LONG to (2,1) (MAV_CMD_
1970-01-01 10:00:07.111 COMPONENT_ARM_DISARM=400) (p1=0.000000 p2=0.000000
1970-01-01 10:00:07.111 p3=0.000000 p4=0.000000 p5=0.000000 p6=0.000000
1970-01-01 10:00:07.111 p7=0.000000)
1970-01-01 10:00:07.131 SRC=250/250:AT-0003.6: ACK received: COMMAND_ACK {command : 40
1970-01-01 10:00:07.131 0, result : 0, progress : 0, result_param2 : 0, ta
1970-01-01 10:00:07.131 rget_system : 250, target_component : 250} (0.0000
1970-01-01 10:00:07.131 00s)
1970-01-01 10:00:07.131 SRC=250/250:AT-0003.6: Waiting for DISARM
1970-01-01 10:00:08.131 SRC=250/250:AT-0003.6: Waiting for disarm (0.00s so far of all
1970-01-01 10:00:08.131 owed 30.00)
1970-01-01 10:00:09.071 SRC=250/250:AT-0003.6: DISARMED after 0.00 seconds (allowed=30
1970-01-01 10:00:09.071 .00)
1970-01-01 10:00:10.071 SRC=250/250:AT-0003.7: Rebooting SITL
1970-01-01 10:00:10.071 SRC=250/250:AT-0003.7: Sending param_request_read for (STAT_RE
1970-01-01 10:00:10.071 SET)
1970-01-01 10:00:10.251 SRC=250/250:AT-0003.7: get_parameter(STAT_RESET): PARAM_VALUE
1970-01-01 10:00:10.251 {param_id : STAT_RESET, param_value : 1.0, param_t
1970-01-01 10:00:10.251 ype : 6, param_count : 1041, param_index : 65535}
1970-01-01 10:00:10.251 SRC=250/250:AT-0003.7: Sending param_request_read for (STAT_BO
1970-01-01 10:00:10.251 OTCNT)
1970-01-01 10:00:11.231 GPS 1: probing for u-blox at 230400 baud
1970-01-01 10:00:11.251 SRC=250/250:AT-0003.7: get_parameter(STAT_BOOTCNT): PARAM_VALU
1970-01-01 10:00:11.251 E {param_id : STAT_BOOTCNT, param_value : 3.0, par
1970-01-01 10:00:11.251 am_type : 4, param_count : 1041, param_index : 655
1970-01-01 10:00:11.251 35}
1970-01-01 10:00:11.271 SRC=250/250:AT-0003.7: Sending reboot command
Board AP_Periph blimp bootloader copter heli iofirmware plane rover sub
CubeOrange-periph-heavy 216 *
Durandal 208 * 216 216 208 208 208
Hitec-Airspeed * *
KakuteH7-bdshot 208 * 208 208 216 208 208
MatekF405 208 * 208 208 208 208 208
Pixhawk1-1M-bdshot 208 208 208 208 208 208
SITL_x86_64_linux_gnu 136 4232 136 136 136 136
f103-QiotekPeriph * *
f303-Universal * *
iomcu *
revo-mini 192 * 192 192 192 192 200
skyviper-v2450 192