1 #include "AP_Logger_config.h"
3 #if HAL_LOGGING_ENABLED
5 #include "AP_Logger_Backend.h"
7 #include "LoggerMessageWriter.h"
9 #include "AP_Common/AP_FWVersion.h"
10 #include <AP_InternalError/AP_InternalError.h>
11 #include <AP_Scheduler/AP_Scheduler.h>
12 #include <AP_Rally/AP_Rally.h>
13 #include <AP_Vehicle/AP_Vehicle_Type.h>
14 #include <Filter/Filter.h>
15 #include "AP_Logger.h"
16 #include <AP_IOMCU/AP_IOMCU.h>
18 #if HAL_LOGGER_FENCE_ENABLED
19 #include <AC_Fence/AC_Fence.h>
22 extern const AP_HAL::HAL
& hal
;
24 AP_Logger_Backend::AP_Logger_Backend(AP_Logger
&front
,
25 class LoggerMessageWriter_DFLogStart
*writer
) :
27 _startup_messagewriter(writer
)
29 writer
->set_logger_backend(this);
32 uint8_t AP_Logger_Backend::num_types() const
34 return _front
._num_types
;
37 const struct LogStructure
*AP_Logger_Backend::structure(uint8_t num
) const
39 return _front
.structure(num
);
42 uint8_t AP_Logger_Backend::num_units() const
44 return _front
._num_units
;
47 const struct UnitStructure
*AP_Logger_Backend::unit(uint8_t num
) const
49 return _front
.unit(num
);
52 uint8_t AP_Logger_Backend::num_multipliers() const
54 return _front
._num_multipliers
;
57 const struct MultiplierStructure
*AP_Logger_Backend::multiplier(uint8_t num
) const
59 return _front
.multiplier(num
);
62 AP_Logger_Backend::vehicle_startup_message_Writer
AP_Logger_Backend::vehicle_message_writer() const {
63 return _front
._vehicle_messages
;
66 void AP_Logger_Backend::periodic_10Hz(const uint32_t now
)
70 void AP_Logger_Backend::periodic_1Hz()
72 if (_rotate_pending
&& !logging_enabled()) {
73 _rotate_pending
= false;
74 // handle log rotation once we stop logging
80 void AP_Logger_Backend::periodic_fullrate()
85 void AP_Logger_Backend::periodic_tasks()
87 uint32_t now
= AP_HAL::millis();
88 if (now
- _last_periodic_1Hz
> 1000) {
90 _last_periodic_1Hz
= now
;
92 if (now
- _last_periodic_10Hz
> 100) {
94 _last_periodic_10Hz
= now
;
99 void AP_Logger_Backend::start_new_log_reset_variables()
102 _startup_messagewriter
->reset();
103 _front
.backend_starting_new_log(this);
104 _formats_written
.clearall();
107 // We may need to make sure data is loggable before starting the
108 // EKF; when allow_start_ekf we should be able to log that data
109 bool AP_Logger_Backend::allow_start_ekf() const
111 if (!_startup_messagewriter
->fmt_done()) {
114 // we need to push all startup messages out, or the code in
115 // WriteBlockCheckStartupMessages bites us.
116 if (!_startup_messagewriter
->finished()) {
122 // this method can be overridden to do extra things with your buffer.
123 // for example, in AP_Logger_MAVLink we may push messages into the UART.
124 void AP_Logger_Backend::push_log_blocks() {
125 WriteMoreStartupMessages();
128 // source more messages from the startup message writer:
129 void AP_Logger_Backend::WriteMoreStartupMessages()
131 #if APM_BUILD_TYPE(APM_BUILD_Replay)
135 if (_startup_messagewriter
->finished()) {
139 _writing_startup_messages
= true;
140 _startup_messagewriter
->process();
141 _writing_startup_messages
= false;
145 * support for Write():
149 // output a FMT message if not already done so
150 void AP_Logger_Backend::Safe_Write_Emit_FMT(uint8_t msg_type
)
152 if (have_emitted_format_for_type(LogMessages(msg_type
))) {
155 Write_Emit_FMT(msg_type
);
158 bool AP_Logger_Backend::Write_Emit_FMT(uint8_t msg_type
)
160 #if APM_BUILD_TYPE(APM_BUILD_Replay)
161 if (msg_type
< REPLAY_LOG_NEW_MSG_MIN
|| msg_type
> REPLAY_LOG_NEW_MSG_MAX
) {
162 // don't re-emit FMU msgs unless they are in the replay range
167 // get log structure from front end:
168 struct AP_Logger::log_write_fmt_strings ls
= {};
169 struct LogStructure logstruct
= {
170 // these will be overwritten, but need to keep the compiler happy:
179 if (!_front
.fill_logstructure(logstruct
, msg_type
)) {
180 // this is a bug; we've been asked to write out the FMT
181 // message for a msg_type, but the frontend can't supply the
182 // required information
183 INTERNAL_ERROR(AP_InternalError::error_t::logger_missing_logstructure
);
187 if (!Write_Format(&logstruct
)) {
190 if (!Write_Format_Units(&logstruct
)) {
197 bool AP_Logger_Backend::Write(const uint8_t msg_type
, va_list arg_list
, bool is_critical
, bool is_streaming
)
199 // stack-allocate a buffer so we can WriteBlock(); this could be
200 // 255 bytes! If we were willing to lose the WriteBlock
201 // abstraction we could do WriteBytes() here instead?
202 const char *fmt
= nullptr;
204 AP_Logger::log_write_fmt
*f
;
205 for (f
= _front
.log_write_fmts
; f
; f
=f
->next
) {
206 if (f
->msg_type
== msg_type
) {
208 msg_len
= f
->msg_len
;
212 if (fmt
== nullptr) {
213 INTERNAL_ERROR(AP_InternalError::error_t::logger_logwrite_missingfmt
);
216 if (bufferspace_available() < msg_len
) {
220 uint8_t buffer
[msg_len
];
222 buffer
[offset
++] = HEAD_BYTE1
;
223 buffer
[offset
++] = HEAD_BYTE2
;
224 buffer
[offset
++] = msg_type
;
225 for (uint8_t i
=0; i
<strlen(fmt
); i
++) {
229 int8_t tmp
= va_arg(arg_list
, int);
230 memcpy(&buffer
[offset
], &tmp
, sizeof(int8_t));
231 offset
+= sizeof(int8_t);
236 int16_t tmp
= va_arg(arg_list
, int);
237 memcpy(&buffer
[offset
], &tmp
, sizeof(int16_t));
238 offset
+= sizeof(int16_t);
242 double tmp
= va_arg(arg_list
, double);
243 memcpy(&buffer
[offset
], &tmp
, sizeof(double));
244 offset
+= sizeof(double);
250 int32_t tmp
= va_arg(arg_list
, int);
251 memcpy(&buffer
[offset
], &tmp
, sizeof(int32_t));
252 offset
+= sizeof(int32_t);
256 float tmp
= va_arg(arg_list
, double);
257 memcpy(&buffer
[offset
], &tmp
, sizeof(float));
258 offset
+= sizeof(float);
263 tmp
.set(va_arg(arg_list
, double));;
264 memcpy(&buffer
[offset
], &tmp
, sizeof(tmp
));
265 offset
+= sizeof(tmp
);
273 uint8_t tmp
= va_arg(arg_list
, int);
274 memcpy(&buffer
[offset
], &tmp
, sizeof(uint8_t));
275 offset
+= sizeof(uint8_t);
280 uint16_t tmp
= va_arg(arg_list
, int);
281 memcpy(&buffer
[offset
], &tmp
, sizeof(uint16_t));
282 offset
+= sizeof(uint16_t);
287 uint32_t tmp
= va_arg(arg_list
, uint32_t);
288 memcpy(&buffer
[offset
], &tmp
, sizeof(uint32_t));
289 offset
+= sizeof(uint32_t);
299 int64_t tmp
= va_arg(arg_list
, int64_t);
300 memcpy(&buffer
[offset
], &tmp
, sizeof(int64_t));
301 offset
+= sizeof(int64_t);
305 uint64_t tmp
= va_arg(arg_list
, uint64_t);
306 memcpy(&buffer
[offset
], &tmp
, sizeof(uint64_t));
307 offset
+= sizeof(uint64_t);
311 int16_t *tmp
= va_arg(arg_list
, int16_t*);
312 const uint8_t bytes
= 32*2;
313 memcpy(&buffer
[offset
], tmp
, bytes
);
319 char *tmp
= va_arg(arg_list
, char*);
320 uint8_t len
= strnlen(tmp
, charlen
);
321 memcpy(&buffer
[offset
], tmp
, len
);
322 memset(&buffer
[offset
+len
], 0, charlen
-len
);
327 return WritePrioritisedBlock(buffer
, msg_len
, is_critical
, is_streaming
);
330 bool AP_Logger_Backend::StartNewLogOK() const
332 if (logging_started()) {
335 if (_front
._log_bitmask
== 0) {
338 if (_front
.in_log_download()) {
341 if (!hal
.scheduler
->in_main_thread()) {
347 // validate that pBuffer looks like a message, extract message type.
348 // Returns false if this doesn't look like a valid message.
349 bool AP_Logger_Backend::message_type_from_block(const void *pBuffer
, uint16_t size
, LogMessages
&type
) const
354 if (((uint8_t*)pBuffer
)[0] != HEAD_BYTE1
||
355 ((uint8_t*)pBuffer
)[1] != HEAD_BYTE2
) {
356 // Not passed a message
357 INTERNAL_ERROR(AP_InternalError::error_t::flow_of_control
);
360 type
= LogMessages(((uint8_t*)pBuffer
)[2]);
364 #if CONFIG_HAL_BOARD == HAL_BOARD_SITL
365 void AP_Logger_Backend::validate_WritePrioritisedBlock(const void *pBuffer
,
368 // just check the first few packets to avoid too much overhead
369 // (finding the structures is expensive)
370 static uint16_t count
= 0;
376 // we assume here that we ever WritePrioritisedBlock for a single
377 // message. If this assumption becomes false we can't do these
380 AP_HAL::panic("Short prioritised block");
383 if (!message_type_from_block(pBuffer
, size
, type
)) {
384 AP_HAL::panic("Not passed a message");
387 const char *name_src
;
388 const struct LogStructure
*s
= _front
.structure_for_msg_type(type
);
390 const struct AP_Logger::log_write_fmt
*t
= _front
.log_write_fmt_for_msg_type(type
);
392 AP_HAL::panic("No structure for msg_type=%u", type
);
394 type_len
= t
->msg_len
;
397 type_len
= s
->msg_len
;
400 if (type_len
!= size
) {
401 char name
[5] = {}; // get a null-terminated string
402 if (name_src
!= nullptr) {
403 memcpy(name
, name_src
, 4);
405 strncpy(name
, "?NM?", ARRAY_SIZE(name
));
407 AP_HAL::panic("Size mismatch for %u (%s) (expected=%u got=%u)",
408 type
, name
, type_len
, size
);
413 bool AP_Logger_Backend::ensure_format_emitted(const void *pBuffer
, uint16_t size
)
415 #if APM_BUILD_TYPE(APM_BUILD_Replay)
416 // we trust that Replay will correctly emit formats as required
422 if (!message_type_from_block(pBuffer
, size
, type
)) {
425 if (have_emitted_format_for_type(type
)) {
429 // make sure the FMT message has gone out!
430 if (type
== LOG_FORMAT_MSG
) {
431 // kind of? Our caller is just about to emit this....
434 if (!have_emitted_format_for_type(LOG_FORMAT_MSG
) &&
435 !Write_Emit_FMT(LOG_FORMAT_MSG
)) {
439 return Write_Emit_FMT(type
);
442 bool AP_Logger_Backend::WritePrioritisedBlock(const void *pBuffer
, uint16_t size
, bool is_critical
, bool writev_streaming
)
444 #if CONFIG_HAL_BOARD == HAL_BOARD_SITL && !APM_BUILD_TYPE(APM_BUILD_Replay)
445 validate_WritePrioritisedBlock(pBuffer
, size
);
447 if (!ShouldLog(is_critical
)) {
450 if (StartNewLogOK()) {
457 if (!is_critical
&& rate_limiter
!= nullptr) {
458 const uint8_t *msgbuf
= (const uint8_t *)pBuffer
;
459 if (!rate_limiter
->should_log(msgbuf
[2], writev_streaming
)) {
464 if (!ensure_format_emitted(pBuffer
, size
)) {
468 return _WritePrioritisedBlock(pBuffer
, size
, is_critical
);
471 bool AP_Logger_Backend::ShouldLog(bool is_critical
)
473 if (!_front
.WritesEnabled()) {
480 if (!_startup_messagewriter
->finished() &&
481 !hal
.scheduler
->in_main_thread()) {
482 // only the main thread may write startup messages out
486 if (_front
.in_log_download() &&
487 _front
._last_mavlink_log_transfer_message_handled_ms
!= 0) {
488 if (AP_HAL::millis() - _front
._last_mavlink_log_transfer_message_handled_ms
< 10000) {
489 if (!_front
.vehicle_is_armed()) {
490 // user is transferring files via mavlink
494 _front
._last_mavlink_log_transfer_message_handled_ms
= 0;
498 if (is_critical
&& have_logged_armed
&& !_front
._params
.file_disarm_rot
) {
499 // if we have previously logged while armed then we log all
500 // critical messages from then on. That fixes a problem where
501 // logs show the wrong flight mode if you disarm then arm again
505 if (!_front
.vehicle_is_armed() && !_front
.log_while_disarmed()) {
509 if (_front
.vehicle_is_armed()) {
510 have_logged_armed
= true;
516 void AP_Logger_Backend::PrepForArming()
518 if (_rotate_pending
) {
519 _rotate_pending
= false;
522 if (logging_started()) {
525 PrepForArming_start_logging();
528 bool AP_Logger_Backend::Write_MessageF(const char *fmt
, ...)
530 char msg
[65] {}; // sizeof(log_Message.msg) + null-termination
534 hal
.util
->vsnprintf(msg
, sizeof(msg
), fmt
, ap
);
537 return Write_Message(msg
);
540 #if HAL_RALLY_ENABLED
541 // Write rally points
542 bool AP_Logger_Backend::Write_RallyPoint(uint8_t total
,
544 const RallyLocation
&rally_point
)
546 const struct log_Rally pkt_rally
{
547 LOG_PACKET_HEADER_INIT(LOG_RALLY_MSG
),
548 time_us
: AP_HAL::micros64(),
551 latitude
: rally_point
.lat
,
552 longitude
: rally_point
.lng
,
553 altitude
: rally_point
.alt
,
554 flags
: rally_point
.flags
556 return WriteBlock(&pkt_rally
, sizeof(pkt_rally
));
559 // Write rally points
560 bool AP_Logger_Backend::Write_Rally()
562 // kick off asynchronous write:
563 return _startup_messagewriter
->writeallrallypoints();
567 #if HAL_LOGGER_FENCE_ENABLED
568 // Write a fence point
569 bool AP_Logger_Backend::Write_FencePoint(uint8_t total
, uint8_t sequence
, const AC_PolyFenceItem
&fence_point
)
571 const struct log_Fence pkt_fence
{
572 LOG_PACKET_HEADER_INIT(LOG_FENCE_MSG
),
573 time_us
: AP_HAL::micros64(),
576 type
: uint8_t(fence_point
.type
),
577 latitude
: fence_point
.loc
.x
,
578 longitude
: fence_point
.loc
.y
,
579 vertex_count
: fence_point
.vertex_count
,
580 radius
: fence_point
.radius
582 return WriteBlock(&pkt_fence
, sizeof(pkt_fence
));
585 // Write all fence points
586 bool AP_Logger_Backend::Write_Fence()
588 // kick off asynchronous write:
589 return _startup_messagewriter
->writeallfence();
591 #endif // HAL_LOGGER_FENCE_ENABLED
594 bool AP_Logger_Backend::Write_VER()
596 const AP_FWVersion
&fwver
= AP::fwversion();
599 LOG_PACKET_HEADER_INIT(LOG_VER_MSG
),
600 time_us
: AP_HAL::micros64(),
601 board_type
: fwver
.board_type
,
602 board_subtype
: fwver
.board_subtype
,
606 fw_type
: fwver
.fw_type
,
607 git_hash
: fwver
.fw_hash
,
609 iomcu_mcu_id
: AP::iomcu()->get_mcu_id(),
610 iomcu_cpu_id
: AP::iomcu()->get_cpu_id(),
614 #endif // HAL_WITH_IO_MCU
616 strncpy(pkt
.fw_string
, fwver
.fw_string
, ARRAY_SIZE(pkt
.fw_string
)-1);
619 pkt
._APJ_BOARD_ID
= APJ_BOARD_ID
;
621 pkt
.build_type
= fwver
.vehicle_type
;
622 pkt
.filter_version
= AP_FILTER_VERSION
;
624 return WriteCriticalBlock(&pkt
, sizeof(pkt
));
628 convert a list entry number back into a log number (which can then
629 be converted into a filename). A "list entry number" is a sequence
630 where the oldest log has a number of 1, the second-from-oldest 2,
631 and so on. Thus the highest list entry number is equal to the
634 uint16_t AP_Logger_Backend::log_num_from_list_entry(const uint16_t list_entry
)
636 uint16_t oldest_log
= find_oldest_log();
637 if (oldest_log
== 0) {
641 uint32_t log_num
= oldest_log
+ list_entry
- 1;
642 const auto max_logs_num
= _front
.get_max_num_logs();
643 if (log_num
> (uint32_t)max_logs_num
) {
644 log_num
-= max_logs_num
;
646 return (uint16_t)log_num
;
649 // find_oldest_log - find oldest log
650 // returns 0 if no log was found
651 uint16_t AP_Logger_Backend::find_oldest_log()
653 if (_cached_oldest_log
!= 0) {
654 return _cached_oldest_log
;
657 uint16_t last_log_num
= find_last_log();
658 if (last_log_num
== 0) {
662 _cached_oldest_log
= last_log_num
- get_num_logs() + 1;
664 return _cached_oldest_log
;
667 void AP_Logger_Backend::vehicle_was_disarmed()
669 if (_front
._params
.file_disarm_rot
&&
670 !_front
._params
.log_replay
) {
671 // rotate our log. Closing the current one and letting the
672 // logging restart naturally based on log_disarmed should do
674 _rotate_pending
= true;
678 // this sensor is enabled if we should be logging at the moment
679 bool AP_Logger_Backend::logging_enabled() const
681 if (hal
.util
->get_soft_armed() ||
682 _front
.log_while_disarmed()) {
688 void AP_Logger_Backend::Write_AP_Logger_Stats_File(const struct df_stats
&_stats
)
690 const struct log_DSF pkt
{
691 LOG_PACKET_HEADER_INIT(LOG_DF_FILE_STATS
),
692 time_us
: AP_HAL::micros64(),
694 blocks
: _stats
.blocks
,
695 bytes
: _stats
.bytes
,
696 buf_space_min
: _stats
.buf_space_min
,
697 buf_space_max
: _stats
.buf_space_max
,
698 buf_space_avg
: (_stats
.blocks
) ? (_stats
.buf_space_sigma
/ _stats
.blocks
) : 0,
700 WriteBlock(&pkt
, sizeof(pkt
));
703 void AP_Logger_Backend::df_stats_gather(const uint16_t bytes_written
, uint32_t space_remaining
)
705 if (space_remaining
< stats
.buf_space_min
) {
706 stats
.buf_space_min
= space_remaining
;
708 if (space_remaining
> stats
.buf_space_max
) {
709 stats
.buf_space_max
= space_remaining
;
711 stats
.buf_space_sigma
+= space_remaining
;
712 stats
.bytes
+= bytes_written
;
716 void AP_Logger_Backend::df_stats_clear() {
717 memset(&stats
, '\0', sizeof(stats
));
718 stats
.buf_space_min
= -1;
721 void AP_Logger_Backend::df_stats_log() {
722 Write_AP_Logger_Stats_File(stats
);
727 // class to handle rate limiting of log messages
728 AP_Logger_RateLimiter::AP_Logger_RateLimiter(const AP_Logger
&_front
, const AP_Float
&_limit_hz
, const AP_Float
&_disarm_limit_hz
)
730 rate_limit_hz(_limit_hz
),
731 disarm_rate_limit_hz(_disarm_limit_hz
)
736 return false if a streaming message should not be sent yet
738 bool AP_Logger_RateLimiter::should_log_streaming(uint8_t msgid
, float rate_hz
)
740 if (front
._log_pause
) {
743 const uint16_t now
= AP_HAL::millis16();
744 uint16_t delta_ms
= now
- last_send_ms
[msgid
];
745 if (is_positive(rate_hz
) && delta_ms
< 1000.0 / rate_hz
) {
749 last_send_ms
[msgid
] = now
;
754 return true if the message is not a streaming message or the gap
755 from the last message is more than the message rate
757 bool AP_Logger_RateLimiter::should_log(uint8_t msgid
, bool writev_streaming
)
759 float rate_hz
= rate_limit_hz
;
760 if (!hal
.util
->get_soft_armed() &&
761 !AP::logger().in_log_persistance() &&
762 !is_zero(disarm_rate_limit_hz
)) {
763 rate_hz
= disarm_rate_limit_hz
;
765 if (!is_positive(rate_hz
) && !front
._log_pause
) {
766 // no rate limiting if not paused and rate is zero(user changed the parameter)
769 if (last_send_ms
[msgid
] == 0 && !writev_streaming
) {
770 // might be non streaming. check the not_streaming bitmask
772 if (not_streaming
.get(msgid
)) {
775 const auto *mtype
= front
.structure_for_msg_type(msgid
);
776 if (mtype
== nullptr ||
777 mtype
->streaming
== false) {
778 not_streaming
.set(msgid
);
783 #if !defined(HAL_BUILD_AP_PERIPH)
784 // if we've already decided on sending this msgid in this tick then use the
785 // same decision again
786 const uint16_t sched_ticks
= AP::scheduler().ticks();
787 if (sched_ticks
== last_sched_count
[msgid
]) {
788 return last_return
.get(msgid
);
790 last_sched_count
[msgid
] = sched_ticks
;
793 bool ret
= should_log_streaming(msgid
, rate_hz
);
795 last_return
.set(msgid
);
797 last_return
.clear(msgid
);
802 #endif // HAL_LOGGING_ENABLED