ardupilot/libraries/AP_Logger/LoggerMessageWriter.cpp
Peter Barker 553e320915 AP_Logger: avoid logging duplicate FMT/UNIT/FMTU/MULT messages
Failing due to being out of time meant we wouldn't incremement the counter, even though we'd emitted the item.

it is important we try to send something, so move this check to be after we increment whichever counter we are using.
2023-02-10 06:45:20 +11:00

498 lines
14 KiB
C++

#include "AP_Common/AP_FWVersion.h"
#include "LoggerMessageWriter.h"
#include <AP_Scheduler/AP_Scheduler.h>
#define FORCE_VERSION_H_INCLUDE
#include "ap_version.h"
#undef FORCE_VERSION_H_INCLUDE
// the message writers are mainly called at the end of periodic_fullrate() with a budget of 300us
// until they are finished calls to Write() will fail so we want to take up as much of
// the budget as possible in order that logging can begin in earnest as early as possible
#define MIN_LOOP_TIME_REMAINING_FOR_MESSAGE_WRITE_US 50
extern const AP_HAL::HAL& hal;
/* LogStartup - these are simple state machines which allow us to
* trickle out messages to the log files
*/
void LoggerMessageWriter::reset()
{
_finished = false;
}
bool LoggerMessageWriter::out_of_time_for_writing_messages() const
{
#if HAL_SCHEDULER_ENABLED
return AP::scheduler().time_available_usec() < MIN_LOOP_TIME_REMAINING_FOR_MESSAGE_WRITE_US;
#else
return false;
#endif
}
void LoggerMessageWriter_DFLogStart::reset()
{
LoggerMessageWriter::reset();
_fmt_done = false;
_params_done = false;
_writesysinfo.reset();
#if AP_MISSION_ENABLED
_writeentiremission.reset();
#endif
#if HAL_RALLY_ENABLED
_writeallrallypoints.reset();
#endif
#if HAL_LOGGER_FENCE_ENABLED
_writeallpolyfence.reset();
#endif
stage = Stage::FORMATS;
next_format_to_send = 0;
_next_unit_to_send = 0;
_next_multiplier_to_send = 0;
_next_format_unit_to_send = 0;
param_default = AP::logger().quiet_nanf();
ap = AP_Param::first(&token, &type, &param_default);
}
bool LoggerMessageWriter_DFLogStart::out_of_time_for_writing_messages() const
{
if (stage == Stage::FORMATS) {
// write out the FMT messages as fast as we can
#if HAL_SCHEDULER_ENABLED
return AP::scheduler().time_available_usec() == 0;
#else
return false;
#endif
}
return LoggerMessageWriter::out_of_time_for_writing_messages();
}
/*
check if we've taken too long in a process() stage
return true if we should stop processing now as we are out of time
*/
bool LoggerMessageWriter_DFLogStart::check_process_limit(uint32_t start_us)
{
const uint32_t limit_us = 1000U;
if (AP_HAL::micros() - start_us > limit_us) {
return true;
}
return false;
}
void LoggerMessageWriter_DFLogStart::process()
{
if (out_of_time_for_writing_messages()) {
return;
}
// allow any stage to run for max 1ms, to prevent a long loop on arming
const uint32_t start_us = AP_HAL::micros();
switch(stage) {
case Stage::FORMATS:
// write log formats so the log is self-describing
while (next_format_to_send < _logger_backend->num_types()) {
if (!_logger_backend->Write_Format(_logger_backend->structure(next_format_to_send))) {
return; // call me again!
}
next_format_to_send++;
if (check_process_limit(start_us)) {
return; // call me again!
}
}
_fmt_done = true;
stage = Stage::PARMS;
FALLTHROUGH;
case Stage::PARMS: {
while (ap) {
if (!_logger_backend->Write_Parameter(ap, token, type, param_default)) {
return;
}
param_default = AP::logger().quiet_nanf();
ap = AP_Param::next_scalar(&token, &type, &param_default);
if (check_process_limit(start_us)) {
return; // call me again!
}
}
_params_done = true;
stage = Stage::UNITS;
}
FALLTHROUGH;
case Stage::UNITS:
while (_next_unit_to_send < _logger_backend->num_units()) {
if (!_logger_backend->Write_Unit(_logger_backend->unit(_next_unit_to_send))) {
return; // call me again!
}
_next_unit_to_send++;
if (check_process_limit(start_us)) {
return; // call me again!
}
}
stage = Stage::MULTIPLIERS;
FALLTHROUGH;
case Stage::MULTIPLIERS:
while (_next_multiplier_to_send < _logger_backend->num_multipliers()) {
if (!_logger_backend->Write_Multiplier(_logger_backend->multiplier(_next_multiplier_to_send))) {
return; // call me again!
}
_next_multiplier_to_send++;
if (check_process_limit(start_us)) {
return; // call me again!
}
}
stage = Stage::UNITS;
FALLTHROUGH;
case Stage::FORMAT_UNITS:
while (_next_format_unit_to_send < _logger_backend->num_types()) {
if (!_logger_backend->Write_Format_Units(_logger_backend->structure(_next_format_unit_to_send))) {
return; // call me again!
}
_next_format_unit_to_send++;
if (check_process_limit(start_us)) {
return; // call me again!
}
}
stage = Stage::RUNNING_SUBWRITERS;
FALLTHROUGH;
case Stage::RUNNING_SUBWRITERS:
if (!_writesysinfo.finished()) {
_writesysinfo.process();
if (!_writesysinfo.finished()) {
return;
}
}
#if AP_MISSION_ENABLED
if (!_writeentiremission.finished()) {
_writeentiremission.process();
if (!_writeentiremission.finished()) {
return;
}
}
#endif
#if HAL_RALLY_ENABLED
if (!_writeallrallypoints.finished()) {
_writeallrallypoints.process();
if (!_writeallrallypoints.finished()) {
return;
}
}
#endif
#if HAL_LOGGER_FENCE_ENABLED
if (!_writeallpolyfence.finished()) {
_writeallpolyfence.process();
if (!_writeallpolyfence.finished()) {
return;
}
}
#endif
stage = Stage::VEHICLE_MESSAGES;
FALLTHROUGH;
case Stage::VEHICLE_MESSAGES:
// we guarantee 200 bytes of space for the vehicle startup
// messages. This allows them to be simple functions rather
// than e.g. LoggerMessageWriter-based state machines
if (_logger_backend->vehicle_message_writer()) {
if (_logger_backend->bufferspace_available() < 200) {
return;
}
(_logger_backend->vehicle_message_writer())();
}
stage = Stage::DONE;
FALLTHROUGH;
case Stage::DONE:
break;
}
_finished = true;
}
#if AP_MISSION_ENABLED
bool LoggerMessageWriter_DFLogStart::writeentiremission()
{
if (stage != Stage::DONE) {
return false;
}
stage = Stage::RUNNING_SUBWRITERS;
_finished = false;
_writeentiremission.reset();
return true;
}
#endif
#if HAL_RALLY_ENABLED
bool LoggerMessageWriter_DFLogStart::writeallrallypoints()
{
if (stage != Stage::DONE) {
return false;
}
stage = Stage::RUNNING_SUBWRITERS;
_finished = false;
_writeallrallypoints.reset();
return true;
}
#endif
#if HAL_LOGGER_FENCE_ENABLED
bool LoggerMessageWriter_DFLogStart::writeallfence()
{
if (stage != Stage::DONE) {
return false;
}
stage = Stage::RUNNING_SUBWRITERS;
_finished = false;
_writeallpolyfence.reset();
return true;
}
#endif
void LoggerMessageWriter_WriteSysInfo::reset()
{
LoggerMessageWriter::reset();
stage = Stage::FIRMWARE_STRING;
}
void LoggerMessageWriter_WriteSysInfo::process() {
const AP_FWVersion &fwver = AP::fwversion();
switch(stage) {
case Stage::FIRMWARE_STRING:
#ifdef AP_CUSTOM_FIRMWARE_STRING
// also log original firmware string if different
if (! _logger_backend->Write_MessageF("%s [%s]",
fwver.fw_string,
fwver.fw_string_original)) {
return; // call me again
}
#else
if (! _logger_backend->Write_Message(fwver.fw_string)) {
return; // call me again
}
#endif
stage = Stage::GIT_VERSIONS;
FALLTHROUGH;
case Stage::GIT_VERSIONS:
if (fwver.middleware_name && fwver.os_name) {
if (! _logger_backend->Write_MessageF("%s: %s %s: %s",
fwver.middleware_name,
fwver.middleware_hash_str,
fwver.os_name,
fwver.os_hash_str)) {
return; // call me again
}
} else if (fwver.os_name) {
if (! _logger_backend->Write_MessageF("%s: %s",
fwver.os_name,
fwver.os_hash_str)) {
return; // call me again
}
}
stage = Stage::VER;
FALLTHROUGH;
case Stage::VER: {
if (!_logger_backend->Write_VER()) {
return;
}
stage = Stage::SYSTEM_ID;
FALLTHROUGH;
}
case Stage::SYSTEM_ID:
char sysid[50];
if (hal.util->get_system_id(sysid)) {
if (! _logger_backend->Write_Message(sysid)) {
return; // call me again
}
}
stage = Stage::PARAM_SPACE_USED;
FALLTHROUGH;
case Stage::PARAM_SPACE_USED:
if (! _logger_backend->Write_MessageF("Param space used: %u/%u", AP_Param::storage_used(), AP_Param::storage_size())) {
return; // call me again
}
stage = Stage::RC_PROTOCOL;
FALLTHROUGH;
case Stage::RC_PROTOCOL:
const char *prot = hal.rcin->protocol();
if (prot == nullptr) {
prot = "None";
}
if (! _logger_backend->Write_MessageF("RC Protocol: %s", prot)) {
return; // call me again
}
}
_finished = true; // all done!
}
void LoggerMessageWriter_WriteAllRallyPoints::process()
{
const AP_Rally *_rally = AP::rally();
if (_rally == nullptr) {
_finished = true;
return;
}
switch(stage) {
case Stage::WRITE_NEW_RALLY_MESSAGE:
if (! _logger_backend->Write_Message("New rally")) {
return; // call me again
}
stage = Stage::WRITE_ALL_RALLY_POINTS;
FALLTHROUGH;
case Stage::WRITE_ALL_RALLY_POINTS:
while (_rally_number_to_send < _rally->get_rally_total()) {
if (out_of_time_for_writing_messages()) {
return;
}
RallyLocation rallypoint;
if (_rally->get_rally_point_with_index(_rally_number_to_send, rallypoint)) {
if (!_logger_backend->Write_RallyPoint(
_rally->get_rally_total(),
_rally_number_to_send,
rallypoint)) {
return; // call me again
}
}
_rally_number_to_send++;
}
stage = Stage::DONE;
FALLTHROUGH;
case Stage::DONE:
break;
}
_finished = true;
}
void LoggerMessageWriter_WriteAllRallyPoints::reset()
{
LoggerMessageWriter::reset();
stage = Stage::WRITE_NEW_RALLY_MESSAGE;
_rally_number_to_send = 0;
}
void LoggerMessageWriter_WriteEntireMission::process() {
const AP_Mission *_mission = AP::mission();
if (_mission == nullptr) {
_finished = true;
return;
}
switch(stage) {
case Stage::WRITE_NEW_MISSION_MESSAGE:
if (! _logger_backend->Write_Message("New mission")) {
return; // call me again
}
stage = Stage::WRITE_MISSION_ITEMS;
FALLTHROUGH;
case Stage::WRITE_MISSION_ITEMS: {
AP_Mission::Mission_Command cmd;
while (_mission_number_to_send < _mission->num_commands()) {
if (out_of_time_for_writing_messages()) {
return;
}
// upon failure to write the mission we will re-read from
// storage; this could be improved.
if (_mission->read_cmd_from_storage(_mission_number_to_send,cmd)) {
if (!_logger_backend->Write_Mission_Cmd(*_mission, cmd)) {
return; // call me again
}
}
_mission_number_to_send++;
}
stage = Stage::DONE;
FALLTHROUGH;
}
case Stage::DONE:
break;
}
_finished = true;
}
void LoggerMessageWriter_WriteEntireMission::reset()
{
LoggerMessageWriter::reset();
stage = Stage::WRITE_NEW_MISSION_MESSAGE;
_mission_number_to_send = 0;
}
#if HAL_LOGGER_FENCE_ENABLED
#if APM_BUILD_TYPE(APM_BUILD_Replay)
// dummy methods to allow build with Replay
void LoggerMessageWriter_Write_Polyfence::process() { };
void LoggerMessageWriter_Write_Polyfence::reset() { };
#else
void LoggerMessageWriter_Write_Polyfence::process() {
AC_Fence *fence = AP::fence();
if (fence == nullptr) {
return;
}
switch(stage) {
case Stage::WRITE_NEW_FENCE_MESSAGE:
if (!_logger_backend->Write_Message("New fence")) {
return; // call me again
}
stage = Stage::WRITE_FENCE_ITEMS;
FALLTHROUGH;
case Stage::WRITE_FENCE_ITEMS: {
while (_fence_number_to_send < fence->polyfence().num_stored_items()) {
if (out_of_time_for_writing_messages()) {
return;
}
// upon failure to write the fence we will re-read from
// storage; this could be improved.
AC_PolyFenceItem fenceitem {};
if (fence->polyfence().get_item(_fence_number_to_send, fenceitem)) {
if (!_logger_backend->Write_FencePoint(fence->polyfence().num_stored_items(), _fence_number_to_send, fenceitem)) {
return; // call me again
}
}
_fence_number_to_send++;
}
stage = Stage::DONE;
FALLTHROUGH;
}
case Stage::DONE:
break;
}
_finished = true;
}
void LoggerMessageWriter_Write_Polyfence::reset()
{
LoggerMessageWriter::reset();
stage = Stage::WRITE_NEW_FENCE_MESSAGE;
_fence_number_to_send = 0;
}
#endif // !APM_BUILD_TYPE(APM_BUILD_Replay)
#endif // AP_FENCE_ENABLED