2013-04-17 08:32:53 -03:00
|
|
|
/*
|
2019-01-18 00:23:42 -04:00
|
|
|
AP_Logger logging - file oriented variant
|
2013-04-17 08:32:53 -03:00
|
|
|
|
2013-04-23 02:03:10 -03:00
|
|
|
This uses posix file IO to create log files called logs/NN.bin in the
|
2013-04-17 08:32:53 -03:00
|
|
|
given directory
|
2015-10-20 07:32:31 -03:00
|
|
|
|
|
|
|
SD Card Rates on PixHawk:
|
|
|
|
- deletion rate seems to be ~50 files/second.
|
|
|
|
- stat seems to be ~150/second
|
|
|
|
- readdir loop of 511 entry directory ~62,000 microseconds
|
2013-04-17 08:32:53 -03:00
|
|
|
*/
|
|
|
|
|
2023-06-23 21:16:04 -03:00
|
|
|
#include "AP_Logger_config.h"
|
|
|
|
|
|
|
|
#if HAL_LOGGING_FILESYSTEM_ENABLED
|
|
|
|
|
2015-08-11 03:28:46 -03:00
|
|
|
#include <AP_HAL/AP_HAL.h>
|
2019-08-01 02:14:22 -03:00
|
|
|
#include <AP_Filesystem/AP_Filesystem.h>
|
2013-04-17 08:32:53 -03:00
|
|
|
|
2023-06-23 21:16:04 -03:00
|
|
|
#include "AP_Logger.h"
|
2019-01-18 00:23:42 -04:00
|
|
|
#include "AP_Logger_File.h"
|
2015-08-06 09:18:28 -03:00
|
|
|
|
2015-12-08 19:53:20 -04:00
|
|
|
#include <AP_Common/AP_Common.h>
|
2018-08-07 07:22:21 -03:00
|
|
|
#include <AP_InternalError/AP_InternalError.h>
|
2019-07-03 21:37:15 -03:00
|
|
|
#include <AP_RTC/AP_RTC.h>
|
2022-10-27 22:38:07 -03:00
|
|
|
#include <AP_Vehicle/AP_Vehicle_Type.h>
|
2023-06-23 21:16:04 -03:00
|
|
|
#include <AP_AHRS/AP_AHRS.h>
|
2018-01-05 03:16:47 -04:00
|
|
|
|
|
|
|
#include <AP_Math/AP_Math.h>
|
|
|
|
#include <GCS_MAVLink/GCS.h>
|
2019-08-01 02:14:22 -03:00
|
|
|
#include <stdio.h>
|
2018-01-05 03:16:47 -04:00
|
|
|
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
extern const AP_HAL::HAL& hal;
|
|
|
|
|
2019-02-11 04:38:01 -04:00
|
|
|
#define LOGGER_PAGE_SIZE 1024UL
|
2013-04-17 08:32:53 -03:00
|
|
|
|
2020-06-01 17:07:07 -03:00
|
|
|
#define MB_to_B 1000000
|
|
|
|
#define B_to_MB 0.000001
|
|
|
|
|
2019-10-03 23:10:39 -03:00
|
|
|
// time between tries to open log
|
|
|
|
#define LOGGER_FILE_REOPEN_MS 5000
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
/*
|
|
|
|
constructor
|
|
|
|
*/
|
2019-01-18 00:23:42 -04:00
|
|
|
AP_Logger_File::AP_Logger_File(AP_Logger &front,
|
2021-11-02 22:34:52 -03:00
|
|
|
LoggerMessageWriter_DFLogStart *writer) :
|
2019-01-18 00:23:42 -04:00
|
|
|
AP_Logger_Backend(front, writer),
|
2021-11-02 22:34:52 -03:00
|
|
|
_log_directory(HAL_BOARD_LOG_DIRECTORY)
|
2017-08-25 04:18:26 -03:00
|
|
|
{
|
|
|
|
df_stats_clear();
|
|
|
|
}
|
2013-04-17 08:32:53 -03:00
|
|
|
|
|
|
|
|
2020-05-10 23:15:11 -03:00
|
|
|
void AP_Logger_File::ensure_log_directory_exists()
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
|
|
|
int ret;
|
2013-12-14 00:32:39 -04:00
|
|
|
struct stat st;
|
2014-01-13 21:39:49 -04:00
|
|
|
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2019-08-01 02:14:22 -03:00
|
|
|
ret = AP::FS().stat(_log_directory, &st);
|
2013-12-14 00:32:39 -04:00
|
|
|
if (ret == -1) {
|
2019-08-01 02:14:22 -03:00
|
|
|
ret = AP::FS().mkdir(_log_directory);
|
2013-12-14 00:32:39 -04:00
|
|
|
}
|
2019-02-27 20:21:14 -04:00
|
|
|
if (ret == -1 && errno != EEXIST) {
|
2018-01-05 03:16:47 -04:00
|
|
|
printf("Failed to create log directory %s : %s\n", _log_directory, strerror(errno));
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
2020-05-10 23:15:11 -03:00
|
|
|
}
|
|
|
|
|
|
|
|
void AP_Logger_File::Init()
|
|
|
|
{
|
2015-12-03 07:01:53 -04:00
|
|
|
// determine and limit file backend buffersize
|
2016-07-29 21:52:21 -03:00
|
|
|
uint32_t bufsize = _front._params.file_bufsize;
|
|
|
|
bufsize *= 1024;
|
2015-12-03 07:01:53 -04:00
|
|
|
|
2019-09-22 22:48:16 -03:00
|
|
|
const uint32_t desired_bufsize = bufsize;
|
|
|
|
|
2016-07-29 21:52:21 -03:00
|
|
|
// If we can't allocate the full size, try to reduce it until we can allocate it
|
|
|
|
while (!_writebuf.set_size(bufsize) && bufsize >= _writebuf_chunk) {
|
2019-09-22 22:48:16 -03:00
|
|
|
bufsize *= 0.9;
|
|
|
|
}
|
|
|
|
if (bufsize >= _writebuf_chunk && bufsize != desired_bufsize) {
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("AP_Logger: reduced buffer %u/%u\n", (unsigned)bufsize, (unsigned)desired_bufsize);
|
2014-09-09 04:32:35 -03:00
|
|
|
}
|
2016-07-29 21:52:21 -03:00
|
|
|
|
|
|
|
if (!_writebuf.get_size()) {
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("Out of memory for logging\n");
|
2016-07-29 21:52:21 -03:00
|
|
|
return;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
2016-07-29 21:52:21 -03:00
|
|
|
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("AP_Logger_File: buffer size=%u\n", (unsigned)bufsize);
|
2016-07-29 21:52:21 -03:00
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
_initialised = true;
|
2020-10-19 15:27:06 -03:00
|
|
|
|
|
|
|
const char* custom_dir = hal.util->get_custom_log_directory();
|
|
|
|
if (custom_dir != nullptr){
|
|
|
|
_log_directory = custom_dir;
|
|
|
|
}
|
2021-01-06 00:32:16 -04:00
|
|
|
|
2023-04-11 07:14:09 -03:00
|
|
|
uint16_t last_log_num = find_last_log();
|
|
|
|
if (last_log_is_marked_discard) {
|
|
|
|
// delete the last log leftover from LOG_DISARMED=3
|
|
|
|
char *filename = _log_file_name(last_log_num);
|
|
|
|
if (filename != nullptr) {
|
|
|
|
AP::FS().unlink(filename);
|
|
|
|
free(filename);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2021-01-06 00:32:16 -04:00
|
|
|
Prep_MinSpace();
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
bool AP_Logger_File::file_exists(const char *filename) const
|
2015-10-20 07:32:31 -03:00
|
|
|
{
|
|
|
|
struct stat st;
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2019-08-01 02:14:22 -03:00
|
|
|
if (AP::FS().stat(filename, &st) == -1) {
|
2015-10-20 07:32:31 -03:00
|
|
|
// hopefully errno==ENOENT. If some error occurs it is
|
|
|
|
// probably better to assume this file exists.
|
|
|
|
return false;
|
|
|
|
}
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
bool AP_Logger_File::log_exists(const uint16_t lognum) const
|
2015-10-20 07:32:31 -03:00
|
|
|
{
|
|
|
|
char *filename = _log_file_name(lognum);
|
2016-10-30 02:24:21 -03:00
|
|
|
if (filename == nullptr) {
|
2015-10-20 07:32:31 -03:00
|
|
|
return false; // ?!
|
|
|
|
}
|
|
|
|
bool ret = file_exists(filename);
|
|
|
|
free(filename);
|
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
void AP_Logger_File::periodic_1Hz()
|
2016-11-06 02:09:39 -04:00
|
|
|
{
|
2020-05-05 14:00:54 -03:00
|
|
|
AP_Logger_Backend::periodic_1Hz();
|
2019-10-01 22:05:56 -03:00
|
|
|
|
2021-03-28 22:05:57 -03:00
|
|
|
if (_initialised &&
|
|
|
|
_write_fd == -1 && _read_fd == -1 &&
|
|
|
|
erase.log_num == 0 &&
|
|
|
|
erase.was_logging) {
|
|
|
|
// restart logging after an erase if needed
|
|
|
|
erase.was_logging = false;
|
2021-10-31 04:44:17 -03:00
|
|
|
// setup to open the log in the backend thread
|
|
|
|
start_new_log_pending = true;
|
2021-03-28 22:05:57 -03:00
|
|
|
}
|
|
|
|
|
2019-10-03 23:10:39 -03:00
|
|
|
if (_initialised &&
|
2021-07-01 00:40:16 -03:00
|
|
|
!start_new_log_pending &&
|
2019-10-03 23:10:39 -03:00
|
|
|
_write_fd == -1 && _read_fd == -1 &&
|
|
|
|
logging_enabled() &&
|
2021-07-01 00:40:16 -03:00
|
|
|
!recent_open_error()) {
|
2021-10-31 04:44:17 -03:00
|
|
|
// setup to open the log in the backend thread
|
|
|
|
start_new_log_pending = true;
|
2019-10-03 23:10:39 -03:00
|
|
|
}
|
|
|
|
|
2016-11-06 02:09:39 -04:00
|
|
|
if (!io_thread_alive()) {
|
2018-07-31 02:30:28 -03:00
|
|
|
if (io_thread_warning_decimation_counter == 0 && _initialised) {
|
|
|
|
// we don't print this error unless we did initialise. When _initialised is set to true
|
|
|
|
// we register the IO timer callback
|
2021-05-19 23:34:13 -03:00
|
|
|
GCS_SEND_TEXT(MAV_SEVERITY_CRITICAL, "AP_Logger: stuck thread (%s)", last_io_operation);
|
2017-04-17 07:42:30 -03:00
|
|
|
}
|
2021-09-25 21:13:14 -03:00
|
|
|
if (io_thread_warning_decimation_counter++ > 30) {
|
2017-04-17 07:42:30 -03:00
|
|
|
io_thread_warning_decimation_counter = 0;
|
|
|
|
}
|
2016-11-06 02:09:39 -04:00
|
|
|
}
|
2021-07-27 05:47:45 -03:00
|
|
|
|
2023-04-11 07:16:41 -03:00
|
|
|
if (rate_limiter == nullptr &&
|
|
|
|
(_front._params.file_ratemax > 0 ||
|
|
|
|
_front._params.disarm_ratemax > 0 ||
|
|
|
|
_front._log_pause)) {
|
2022-07-26 20:41:04 -03:00
|
|
|
// setup rate limiting if log rate max > 0Hz or log pause of streaming entries is requested
|
2024-05-26 22:24:12 -03:00
|
|
|
rate_limiter = NEW_NOTHROW AP_Logger_RateLimiter(_front, _front._params.file_ratemax, _front._params.disarm_ratemax);
|
2021-07-27 05:47:45 -03:00
|
|
|
}
|
2016-11-06 02:09:39 -04:00
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
void AP_Logger_File::periodic_fullrate()
|
2015-08-06 09:18:28 -03:00
|
|
|
{
|
2019-01-18 00:23:42 -04:00
|
|
|
AP_Logger_Backend::push_log_blocks();
|
2015-08-06 09:18:28 -03:00
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
uint32_t AP_Logger_File::bufferspace_available()
|
2015-08-06 09:18:28 -03:00
|
|
|
{
|
2016-07-29 21:52:21 -03:00
|
|
|
const uint32_t space = _writebuf.space();
|
2020-05-05 14:00:54 -03:00
|
|
|
const uint32_t crit = critical_message_reserved_space(_writebuf.get_size());
|
2016-09-12 23:32:01 -03:00
|
|
|
|
|
|
|
return (space > crit) ? space - crit : 0;
|
2015-08-06 09:18:28 -03:00
|
|
|
}
|
|
|
|
|
2019-10-03 23:10:39 -03:00
|
|
|
bool AP_Logger_File::recent_open_error(void) const
|
|
|
|
{
|
|
|
|
if (_open_error_ms == 0) {
|
|
|
|
return false;
|
|
|
|
}
|
|
|
|
return AP_HAL::millis() - _open_error_ms < LOGGER_FILE_REOPEN_MS;
|
|
|
|
}
|
|
|
|
|
2016-07-29 21:52:21 -03:00
|
|
|
// return true for CardInserted() if we successfully initialized
|
2019-01-18 00:23:42 -04:00
|
|
|
bool AP_Logger_File::CardInserted(void) const
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2019-10-03 23:10:39 -03:00
|
|
|
return _initialised && !recent_open_error();
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
|
2015-10-20 07:32:31 -03:00
|
|
|
// returns the amount of disk space available in _log_directory (in bytes)
|
|
|
|
// returns -1 on error
|
2019-01-18 00:23:42 -04:00
|
|
|
int64_t AP_Logger_File::disk_space_avail()
|
2015-08-08 03:13:38 -03:00
|
|
|
{
|
2019-08-01 02:14:22 -03:00
|
|
|
return AP::FS().disk_free(_log_directory);
|
2015-08-08 03:13:38 -03:00
|
|
|
}
|
|
|
|
|
2015-10-20 07:32:31 -03:00
|
|
|
// returns the total amount of disk space (in use + available) in
|
|
|
|
// _log_directory (in bytes).
|
|
|
|
// returns -1 on error
|
2019-01-18 00:23:42 -04:00
|
|
|
int64_t AP_Logger_File::disk_space()
|
2015-08-08 03:13:38 -03:00
|
|
|
{
|
2019-08-01 02:14:22 -03:00
|
|
|
return AP::FS().disk_space(_log_directory);
|
2015-08-08 03:13:38 -03:00
|
|
|
}
|
|
|
|
|
2022-04-17 21:25:16 -03:00
|
|
|
/*
|
|
|
|
convert a dirent to a log number
|
|
|
|
*/
|
|
|
|
bool AP_Logger_File::dirent_to_log_num(const dirent *de, uint16_t &log_num) const
|
|
|
|
{
|
|
|
|
uint8_t length = strlen(de->d_name);
|
|
|
|
if (length < 5) {
|
|
|
|
return false;
|
|
|
|
}
|
|
|
|
if (strncmp(&de->d_name[length-4], ".BIN", 4) != 0) {
|
|
|
|
// doesn't end in .BIN
|
|
|
|
return false;
|
|
|
|
}
|
|
|
|
|
|
|
|
uint16_t thisnum = strtoul(de->d_name, nullptr, 10);
|
2023-09-20 12:35:17 -03:00
|
|
|
if (thisnum > _front.get_max_num_logs()) {
|
2022-04-17 21:25:16 -03:00
|
|
|
return false;
|
|
|
|
}
|
|
|
|
log_num = thisnum;
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2015-10-20 07:32:31 -03:00
|
|
|
// find_oldest_log - find oldest log in _log_directory
|
2015-08-08 03:13:38 -03:00
|
|
|
// returns 0 if no log was found
|
2019-01-18 00:23:42 -04:00
|
|
|
uint16_t AP_Logger_File::find_oldest_log()
|
2015-08-08 03:13:38 -03:00
|
|
|
{
|
2015-11-10 23:51:03 -04:00
|
|
|
if (_cached_oldest_log != 0) {
|
|
|
|
return _cached_oldest_log;
|
|
|
|
}
|
|
|
|
|
2015-10-20 07:32:31 -03:00
|
|
|
uint16_t last_log_num = find_last_log();
|
|
|
|
if (last_log_num == 0) {
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
uint16_t current_oldest_log = 0; // 0 is invalid
|
|
|
|
|
2015-08-08 03:13:38 -03:00
|
|
|
// We could count up to find_last_log(), but if people start
|
|
|
|
// relying on the min_avail_space_percent feature we could end up
|
|
|
|
// doing a *lot* of asprintf()s and stat()s
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2020-03-11 22:58:41 -03:00
|
|
|
auto *d = AP::FS().opendir(_log_directory);
|
2016-10-30 02:24:21 -03:00
|
|
|
if (d == nullptr) {
|
2018-08-07 07:22:21 -03:00
|
|
|
// SD card may have died? On linux someone may have rm-rf-d
|
2015-08-08 03:13:38 -03:00
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
// we only remove files which look like xxx.BIN
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2019-08-01 02:14:22 -03:00
|
|
|
for (struct dirent *de=AP::FS().readdir(d); de; de=AP::FS().readdir(d)) {
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2022-04-17 21:25:16 -03:00
|
|
|
uint16_t thisnum;
|
|
|
|
if (!dirent_to_log_num(de, thisnum)) {
|
|
|
|
// not a log filename
|
2015-10-20 07:32:31 -03:00
|
|
|
continue;
|
|
|
|
}
|
|
|
|
if (current_oldest_log == 0) {
|
|
|
|
current_oldest_log = thisnum;
|
|
|
|
} else {
|
|
|
|
if (current_oldest_log <= last_log_num) {
|
|
|
|
if (thisnum > last_log_num) {
|
|
|
|
current_oldest_log = thisnum;
|
|
|
|
} else if (thisnum < current_oldest_log) {
|
|
|
|
current_oldest_log = thisnum;
|
|
|
|
}
|
|
|
|
} else { // current_oldest_log > last_log_num
|
|
|
|
if (thisnum > last_log_num) {
|
|
|
|
if (thisnum < current_oldest_log) {
|
|
|
|
current_oldest_log = thisnum;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
2015-08-08 03:13:38 -03:00
|
|
|
}
|
|
|
|
}
|
2019-08-01 02:14:22 -03:00
|
|
|
AP::FS().closedir(d);
|
2015-11-10 23:51:03 -04:00
|
|
|
_cached_oldest_log = current_oldest_log;
|
2015-08-08 03:13:38 -03:00
|
|
|
|
2015-10-20 07:32:31 -03:00
|
|
|
return current_oldest_log;
|
2015-08-08 03:13:38 -03:00
|
|
|
}
|
2013-04-17 08:32:53 -03:00
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
void AP_Logger_File::Prep_MinSpace()
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2019-04-19 22:26:05 -03:00
|
|
|
if (hal.util->was_watchdog_reset()) {
|
|
|
|
// don't clear space if watchdog reset, it takes too long
|
|
|
|
return;
|
|
|
|
}
|
2021-01-06 00:32:16 -04:00
|
|
|
|
|
|
|
if (!CardInserted()) {
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2015-10-20 07:32:31 -03:00
|
|
|
const uint16_t first_log_to_remove = find_oldest_log();
|
|
|
|
if (first_log_to_remove == 0) {
|
2015-08-08 03:13:38 -03:00
|
|
|
// no files to remove
|
|
|
|
return;
|
|
|
|
}
|
2015-10-20 07:32:31 -03:00
|
|
|
|
2020-06-01 17:07:07 -03:00
|
|
|
const int64_t target_free = (int64_t)_front._params.min_MB_free * MB_to_B;
|
|
|
|
|
2015-10-20 07:32:31 -03:00
|
|
|
uint16_t log_to_remove = first_log_to_remove;
|
|
|
|
|
2015-08-08 03:13:38 -03:00
|
|
|
uint16_t count = 0;
|
2015-10-20 07:32:31 -03:00
|
|
|
do {
|
2020-06-01 17:07:07 -03:00
|
|
|
int64_t avail = disk_space_avail();
|
|
|
|
if (avail == -1) {
|
2015-10-20 07:32:31 -03:00
|
|
|
break;
|
|
|
|
}
|
2020-06-01 17:07:07 -03:00
|
|
|
if (avail >= target_free) {
|
2015-10-20 07:32:31 -03:00
|
|
|
break;
|
|
|
|
}
|
2023-09-20 12:35:17 -03:00
|
|
|
if (count++ > _front.get_max_num_logs() + 10) {
|
2015-08-08 03:13:38 -03:00
|
|
|
// *way* too many deletions going on here. Possible internal error.
|
2020-04-29 21:40:46 -03:00
|
|
|
INTERNAL_ERROR(AP_InternalError::error_t::logger_too_many_deletions);
|
2015-08-08 03:13:38 -03:00
|
|
|
break;
|
|
|
|
}
|
|
|
|
char *filename_to_remove = _log_file_name(log_to_remove);
|
2016-10-30 02:24:21 -03:00
|
|
|
if (filename_to_remove == nullptr) {
|
2020-04-29 21:40:46 -03:00
|
|
|
INTERNAL_ERROR(AP_InternalError::error_t::logger_bad_getfilename);
|
2015-08-08 03:13:38 -03:00
|
|
|
break;
|
|
|
|
}
|
2015-10-20 07:32:31 -03:00
|
|
|
if (file_exists(filename_to_remove)) {
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("Removing (%s) for minimum-space requirements (%.0fMB < %.0fMB)\n",
|
2020-06-01 17:07:07 -03:00
|
|
|
filename_to_remove, (double)avail*B_to_MB, (double)target_free*B_to_MB);
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(2000);
|
2019-08-01 02:14:22 -03:00
|
|
|
if (AP::FS().unlink(filename_to_remove) == -1) {
|
2021-01-06 00:32:16 -04:00
|
|
|
_cached_oldest_log = 0;
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("Failed to remove %s: %s\n", filename_to_remove, strerror(errno));
|
2015-10-20 07:32:31 -03:00
|
|
|
free(filename_to_remove);
|
|
|
|
if (errno == ENOENT) {
|
|
|
|
// corruption - should always have a continuous
|
|
|
|
// sequence of files... however, there may be still
|
|
|
|
// files out there, so keep going.
|
|
|
|
} else {
|
2015-08-08 03:13:38 -03:00
|
|
|
break;
|
|
|
|
}
|
|
|
|
} else {
|
2015-10-20 07:32:31 -03:00
|
|
|
free(filename_to_remove);
|
2015-08-08 03:13:38 -03:00
|
|
|
}
|
|
|
|
}
|
2015-10-20 07:32:31 -03:00
|
|
|
log_to_remove++;
|
2023-09-20 12:35:17 -03:00
|
|
|
if (log_to_remove > _front.get_max_num_logs()) {
|
2015-10-20 07:32:31 -03:00
|
|
|
log_to_remove = 1;
|
|
|
|
}
|
|
|
|
} while (log_to_remove != first_log_to_remove);
|
2015-08-08 03:13:38 -03:00
|
|
|
}
|
|
|
|
|
2017-02-10 22:39:50 -04:00
|
|
|
/*
|
|
|
|
construct a log file name given a log number.
|
|
|
|
The number in the log filename will be zero-padded.
|
|
|
|
Note: Caller must free.
|
|
|
|
*/
|
2024-07-06 23:49:27 -03:00
|
|
|
char *AP_Logger_File::_log_file_name(const uint16_t log_num) const
|
2017-02-10 22:39:50 -04:00
|
|
|
{
|
|
|
|
char *buf = nullptr;
|
|
|
|
if (asprintf(&buf, "%s/%08u.BIN", _log_directory, (unsigned)log_num) == -1) {
|
|
|
|
return nullptr;
|
|
|
|
}
|
|
|
|
return buf;
|
|
|
|
}
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
/*
|
|
|
|
return path name of the lastlog.txt marker file
|
|
|
|
Note: Caller must free.
|
|
|
|
*/
|
2019-01-18 00:23:42 -04:00
|
|
|
char *AP_Logger_File::_lastlog_file_name(void) const
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2016-10-30 02:24:21 -03:00
|
|
|
char *buf = nullptr;
|
2017-02-13 22:25:32 -04:00
|
|
|
if (asprintf(&buf, "%s/LASTLOG.TXT", _log_directory) == -1) {
|
2016-10-30 02:24:21 -03:00
|
|
|
return nullptr;
|
2015-05-04 04:27:15 -03:00
|
|
|
}
|
2013-04-17 08:32:53 -03:00
|
|
|
return buf;
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
// remove all log files
|
2019-01-18 00:23:42 -04:00
|
|
|
void AP_Logger_File::EraseAll()
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2018-10-31 19:53:57 -03:00
|
|
|
if (hal.util->get_soft_armed()) {
|
|
|
|
// do not want to do any filesystem operations while we are e.g. flying
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
if (!_initialised) {
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2021-03-28 22:05:57 -03:00
|
|
|
erase.was_logging = (_write_fd != -1);
|
2013-12-28 23:59:35 -04:00
|
|
|
stop_logging();
|
2018-05-11 09:26:52 -03:00
|
|
|
|
2021-03-28 22:05:57 -03:00
|
|
|
erase.log_num = 1;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
bool AP_Logger_File::WritesOK() const
|
2017-06-08 22:36:18 -03:00
|
|
|
{
|
|
|
|
if (_write_fd == -1) {
|
|
|
|
return false;
|
|
|
|
}
|
2019-10-03 23:10:39 -03:00
|
|
|
if (recent_open_error()) {
|
2017-06-08 22:36:18 -03:00
|
|
|
return false;
|
|
|
|
}
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
|
2017-06-30 08:09:20 -03:00
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
bool AP_Logger_File::StartNewLogOK() const
|
2017-06-30 08:09:20 -03:00
|
|
|
{
|
2019-10-03 23:10:39 -03:00
|
|
|
if (recent_open_error()) {
|
2017-06-30 08:09:20 -03:00
|
|
|
return false;
|
|
|
|
}
|
2021-06-13 20:46:51 -03:00
|
|
|
#if !APM_BUILD_TYPE(APM_BUILD_Replay)
|
|
|
|
if (hal.scheduler->in_main_thread()) {
|
2021-06-08 22:33:25 -03:00
|
|
|
return false;
|
|
|
|
}
|
2021-06-13 20:46:51 -03:00
|
|
|
#endif
|
2019-01-18 00:23:42 -04:00
|
|
|
return AP_Logger_Backend::StartNewLogOK();
|
2017-06-30 08:09:20 -03:00
|
|
|
}
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
/* Write a block of data at current offset */
|
2019-01-18 00:23:42 -04:00
|
|
|
bool AP_Logger_File::_WritePrioritisedBlock(const void *pBuffer, uint16_t size, bool is_critical)
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2020-11-07 23:32:24 -04:00
|
|
|
WITH_SEMAPHORE(semaphore);
|
|
|
|
|
2020-11-05 19:28:26 -04:00
|
|
|
#if APM_BUILD_TYPE(APM_BUILD_Replay)
|
|
|
|
if (AP::FS().write(_write_fd, pBuffer, size) != size) {
|
|
|
|
AP_HAL::panic("Short write");
|
|
|
|
}
|
|
|
|
return true;
|
|
|
|
#endif
|
|
|
|
|
2020-11-07 23:32:24 -04:00
|
|
|
|
2016-07-30 15:13:12 -03:00
|
|
|
uint32_t space = _writebuf.space();
|
2015-08-06 09:18:28 -03:00
|
|
|
|
2015-09-17 07:58:35 -03:00
|
|
|
if (_writing_startup_messages &&
|
2015-11-09 18:14:22 -04:00
|
|
|
_startup_messagewriter->fmt_done()) {
|
2015-09-17 07:58:35 -03:00
|
|
|
// the state machine has called us, and it has finished
|
|
|
|
// writing format messages out. It can always get back to us
|
|
|
|
// with more messages later, so let's leave room for other
|
|
|
|
// things:
|
2018-08-14 22:36:09 -03:00
|
|
|
const uint32_t now = AP_HAL::millis();
|
|
|
|
const bool must_dribble = (now - last_messagewrite_message_sent) > 100;
|
|
|
|
if (!must_dribble &&
|
2020-05-05 14:00:54 -03:00
|
|
|
space < non_messagewriter_message_reserved_space(_writebuf.get_size())) {
|
2015-09-17 07:58:35 -03:00
|
|
|
// this message isn't dropped, it will be sent again...
|
|
|
|
return false;
|
|
|
|
}
|
2018-08-14 22:36:09 -03:00
|
|
|
last_messagewrite_message_sent = now;
|
2015-09-17 07:58:35 -03:00
|
|
|
} else {
|
|
|
|
// we reserve some amount of space for critical messages:
|
2020-05-05 14:00:54 -03:00
|
|
|
if (!is_critical && space < critical_message_reserved_space(_writebuf.get_size())) {
|
2015-09-17 07:58:35 -03:00
|
|
|
_dropped++;
|
|
|
|
return false;
|
|
|
|
}
|
2015-08-06 09:18:28 -03:00
|
|
|
}
|
|
|
|
|
|
|
|
// if no room for entire message - drop it:
|
2013-04-17 08:32:53 -03:00
|
|
|
if (space < size) {
|
2015-08-06 09:18:28 -03:00
|
|
|
_dropped++;
|
|
|
|
return false;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
|
2016-07-29 21:52:21 -03:00
|
|
|
_writebuf.write((uint8_t*)pBuffer, size);
|
2020-05-05 14:00:54 -03:00
|
|
|
df_stats_gather(size, _writebuf.space());
|
2015-08-06 09:18:28 -03:00
|
|
|
return true;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
find the highest log number
|
|
|
|
*/
|
2019-01-18 00:23:42 -04:00
|
|
|
uint16_t AP_Logger_File::find_last_log()
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
|
|
|
unsigned ret = 0;
|
|
|
|
char *fname = _lastlog_file_name();
|
2016-10-30 02:24:21 -03:00
|
|
|
if (fname == nullptr) {
|
2013-04-17 08:32:53 -03:00
|
|
|
return ret;
|
|
|
|
}
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2020-11-12 20:56:29 -04:00
|
|
|
FileData *fd = AP::FS().load_file(fname);
|
2021-04-15 05:15:16 -03:00
|
|
|
free(fname);
|
2023-04-11 07:14:09 -03:00
|
|
|
last_log_is_marked_discard = false;
|
2020-11-12 20:56:29 -04:00
|
|
|
if (fd != nullptr) {
|
2023-04-11 07:14:09 -03:00
|
|
|
char *endptr = nullptr;
|
|
|
|
ret = strtol((const char *)fd->data, &endptr, 10);
|
|
|
|
if (endptr != nullptr) {
|
|
|
|
last_log_is_marked_discard = *endptr == 'D';
|
|
|
|
}
|
2020-11-12 20:56:29 -04:00
|
|
|
delete fd;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
uint32_t AP_Logger_File::_get_log_size(const uint16_t log_num)
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
|
|
|
char *fname = _log_file_name(log_num);
|
2016-10-30 02:24:21 -03:00
|
|
|
if (fname == nullptr) {
|
2013-04-17 08:32:53 -03:00
|
|
|
return 0;
|
|
|
|
}
|
2018-10-11 20:35:04 -03:00
|
|
|
if (_write_fd != -1 && write_fd_semaphore.take_nonblocking()) {
|
2018-06-13 21:32:44 -03:00
|
|
|
if (_write_filename != nullptr && strcmp(_write_filename, fname) == 0) {
|
|
|
|
// it is the file we are currently writing
|
|
|
|
free(fname);
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2018-06-13 21:32:44 -03:00
|
|
|
return _write_offset;
|
|
|
|
}
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2018-06-13 21:32:44 -03:00
|
|
|
}
|
2013-04-17 08:32:53 -03:00
|
|
|
struct stat st;
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2019-08-01 02:14:22 -03:00
|
|
|
if (AP::FS().stat(fname, &st) != 0) {
|
2013-04-17 08:32:53 -03:00
|
|
|
free(fname);
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
free(fname);
|
|
|
|
return st.st_size;
|
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
uint32_t AP_Logger_File::_get_log_time(const uint16_t log_num)
|
2013-12-15 03:57:49 -04:00
|
|
|
{
|
|
|
|
char *fname = _log_file_name(log_num);
|
2016-10-30 02:24:21 -03:00
|
|
|
if (fname == nullptr) {
|
2013-12-15 03:57:49 -04:00
|
|
|
return 0;
|
|
|
|
}
|
2018-10-11 20:35:04 -03:00
|
|
|
if (_write_fd != -1 && write_fd_semaphore.take_nonblocking()) {
|
2018-06-13 21:32:44 -03:00
|
|
|
if (_write_filename != nullptr && strcmp(_write_filename, fname) == 0) {
|
|
|
|
// it is the file we are currently writing
|
|
|
|
free(fname);
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2023-10-05 04:40:34 -03:00
|
|
|
#if AP_RTC_ENABLED
|
2018-06-14 02:30:54 -03:00
|
|
|
uint64_t utc_usec;
|
|
|
|
if (!AP::rtc().get_utc_usec(utc_usec)) {
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
return utc_usec / 1000000U;
|
2023-10-05 04:40:34 -03:00
|
|
|
#else
|
|
|
|
return 0;
|
|
|
|
#endif
|
2018-06-13 21:32:44 -03:00
|
|
|
}
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2018-06-13 21:32:44 -03:00
|
|
|
}
|
2013-12-15 03:57:49 -04:00
|
|
|
struct stat st;
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2019-08-01 02:14:22 -03:00
|
|
|
if (AP::FS().stat(fname, &st) != 0) {
|
2013-12-15 03:57:49 -04:00
|
|
|
free(fname);
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
free(fname);
|
|
|
|
return st.st_mtime;
|
|
|
|
}
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
/*
|
|
|
|
find the number of pages in a log
|
|
|
|
*/
|
2019-01-18 18:45:36 -04:00
|
|
|
void AP_Logger_File::get_log_boundaries(const uint16_t list_entry, uint32_t & start_page, uint32_t & end_page)
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2020-05-05 14:00:54 -03:00
|
|
|
const uint16_t log_num = log_num_from_list_entry(list_entry);
|
2015-10-20 07:32:31 -03:00
|
|
|
if (log_num == 0) {
|
|
|
|
// that failed - probably no logs
|
|
|
|
start_page = 0;
|
|
|
|
end_page = 0;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
start_page = 0;
|
2019-02-11 04:38:01 -04:00
|
|
|
end_page = _get_log_size(log_num) / LOGGER_PAGE_SIZE;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
|
2013-12-15 03:57:49 -04:00
|
|
|
/*
|
2015-11-10 23:51:03 -04:00
|
|
|
retrieve data from a log file
|
2013-12-15 03:57:49 -04:00
|
|
|
*/
|
2019-01-18 00:23:42 -04:00
|
|
|
int16_t AP_Logger_File::get_log_data(const uint16_t list_entry, const uint16_t page, const uint32_t offset, const uint16_t len, uint8_t *data)
|
2013-12-15 03:57:49 -04:00
|
|
|
{
|
2019-10-03 23:10:39 -03:00
|
|
|
if (!_initialised || recent_open_error()) {
|
2013-12-15 03:57:49 -04:00
|
|
|
return -1;
|
|
|
|
}
|
2015-10-20 07:32:31 -03:00
|
|
|
|
2020-05-05 14:00:54 -03:00
|
|
|
const uint16_t log_num = log_num_from_list_entry(list_entry);
|
2015-10-20 07:32:31 -03:00
|
|
|
if (log_num == 0) {
|
|
|
|
// that failed - probably no logs
|
|
|
|
return -1;
|
|
|
|
}
|
|
|
|
|
2013-12-15 03:57:49 -04:00
|
|
|
if (_read_fd != -1 && log_num != _read_fd_log_num) {
|
2019-08-01 02:14:22 -03:00
|
|
|
AP::FS().close(_read_fd);
|
2013-12-15 03:57:49 -04:00
|
|
|
_read_fd = -1;
|
|
|
|
}
|
|
|
|
if (_read_fd == -1) {
|
|
|
|
char *fname = _log_file_name(log_num);
|
2016-10-30 02:24:21 -03:00
|
|
|
if (fname == nullptr) {
|
2013-12-15 03:57:49 -04:00
|
|
|
return -1;
|
|
|
|
}
|
2013-12-27 23:24:28 -04:00
|
|
|
stop_logging();
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2019-08-01 02:14:22 -03:00
|
|
|
_read_fd = AP::FS().open(fname, O_RDONLY);
|
2013-12-15 03:57:49 -04:00
|
|
|
if (_read_fd == -1) {
|
2019-10-03 23:10:39 -03:00
|
|
|
_open_error_ms = AP_HAL::millis();
|
2014-12-20 22:31:27 -04:00
|
|
|
int saved_errno = errno;
|
|
|
|
::printf("Log read open fail for %s - %s\n",
|
|
|
|
fname, strerror(saved_errno));
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("Log read open fail for %s - %s\n",
|
2014-12-20 22:31:27 -04:00
|
|
|
fname, strerror(saved_errno));
|
|
|
|
free(fname);
|
2013-12-15 03:57:49 -04:00
|
|
|
return -1;
|
|
|
|
}
|
2014-12-20 22:31:27 -04:00
|
|
|
free(fname);
|
2013-12-15 03:57:49 -04:00
|
|
|
_read_offset = 0;
|
|
|
|
_read_fd_log_num = log_num;
|
|
|
|
}
|
2019-02-11 04:38:01 -04:00
|
|
|
uint32_t ofs = page * (uint32_t)LOGGER_PAGE_SIZE + offset;
|
2014-02-14 03:21:57 -04:00
|
|
|
|
2013-12-15 03:57:49 -04:00
|
|
|
if (ofs != _read_offset) {
|
2019-08-01 02:14:22 -03:00
|
|
|
if (AP::FS().lseek(_read_fd, ofs, SEEK_SET) == (off_t)-1) {
|
|
|
|
AP::FS().close(_read_fd);
|
2015-12-08 08:43:02 -04:00
|
|
|
_read_fd = -1;
|
|
|
|
return -1;
|
|
|
|
}
|
2014-02-14 03:21:57 -04:00
|
|
|
_read_offset = ofs;
|
2013-12-15 03:57:49 -04:00
|
|
|
}
|
2019-08-01 02:14:22 -03:00
|
|
|
int16_t ret = (int16_t)AP::FS().read(_read_fd, data, len);
|
2013-12-15 03:57:49 -04:00
|
|
|
if (ret > 0) {
|
|
|
|
_read_offset += ret;
|
|
|
|
}
|
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
find size and date of a log
|
|
|
|
*/
|
2019-01-18 00:23:42 -04:00
|
|
|
void AP_Logger_File::get_log_info(const uint16_t list_entry, uint32_t &size, uint32_t &time_utc)
|
2013-12-15 03:57:49 -04:00
|
|
|
{
|
2020-05-05 14:00:54 -03:00
|
|
|
uint16_t log_num = log_num_from_list_entry(list_entry);
|
2015-10-20 07:32:31 -03:00
|
|
|
if (log_num == 0) {
|
|
|
|
// that failed - probably no logs
|
|
|
|
size = 0;
|
|
|
|
time_utc = 0;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2013-12-15 03:57:49 -04:00
|
|
|
size = _get_log_size(log_num);
|
|
|
|
time_utc = _get_log_time(log_num);
|
|
|
|
}
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
|
|
|
|
/*
|
|
|
|
get the number of logs - note that the log numbers must be consecutive
|
|
|
|
*/
|
2019-01-18 00:23:42 -04:00
|
|
|
uint16_t AP_Logger_File::get_num_logs()
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2022-04-17 21:25:16 -03:00
|
|
|
auto *d = AP::FS().opendir(_log_directory);
|
|
|
|
if (d == nullptr) {
|
|
|
|
return 0;
|
|
|
|
}
|
2013-04-17 08:32:53 -03:00
|
|
|
uint16_t high = find_last_log();
|
2022-04-17 21:25:16 -03:00
|
|
|
uint16_t ret = high;
|
|
|
|
uint16_t smallest_above_last = 0;
|
|
|
|
|
|
|
|
EXPECT_DELAY_MS(2000);
|
|
|
|
for (struct dirent *de=AP::FS().readdir(d); de; de=AP::FS().readdir(d)) {
|
|
|
|
EXPECT_DELAY_MS(100);
|
|
|
|
uint16_t thisnum;
|
|
|
|
if (!dirent_to_log_num(de, thisnum)) {
|
|
|
|
// not a log filename
|
|
|
|
continue;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
2023-09-20 12:35:17 -03:00
|
|
|
|
2022-05-05 05:29:05 -03:00
|
|
|
if (thisnum > high && (smallest_above_last == 0 || thisnum < smallest_above_last)) {
|
2022-04-17 21:25:16 -03:00
|
|
|
smallest_above_last = thisnum;
|
2015-10-20 07:32:31 -03:00
|
|
|
}
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
2022-04-17 21:25:16 -03:00
|
|
|
AP::FS().closedir(d);
|
|
|
|
if (smallest_above_last != 0) {
|
|
|
|
// we have wrapped, add in the logs with high numbers
|
2023-09-20 12:35:17 -03:00
|
|
|
ret += (_front.get_max_num_logs() - smallest_above_last) + 1;
|
2022-04-17 21:25:16 -03:00
|
|
|
}
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
2013-12-27 23:24:28 -04:00
|
|
|
stop logging
|
2013-04-17 08:32:53 -03:00
|
|
|
*/
|
2019-01-18 00:23:42 -04:00
|
|
|
void AP_Logger_File::stop_logging(void)
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2017-09-12 22:46:34 -03:00
|
|
|
// best-case effort to avoid annoying the IO thread
|
2019-06-06 00:49:11 -03:00
|
|
|
const bool have_sem = write_fd_semaphore.take(hal.util->get_soft_armed()?1:20);
|
2013-04-17 08:32:53 -03:00
|
|
|
if (_write_fd != -1) {
|
|
|
|
int fd = _write_fd;
|
|
|
|
_write_fd = -1;
|
2019-08-01 02:14:22 -03:00
|
|
|
AP::FS().close(fd);
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
2017-09-12 22:46:34 -03:00
|
|
|
if (have_sem) {
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2017-09-12 22:46:34 -03:00
|
|
|
}
|
2013-12-27 23:24:28 -04:00
|
|
|
}
|
|
|
|
|
2021-06-13 20:46:51 -03:00
|
|
|
/*
|
2021-06-14 22:09:24 -03:00
|
|
|
does start_new_log in the logger thread
|
2021-06-13 20:46:51 -03:00
|
|
|
*/
|
2021-06-14 22:09:24 -03:00
|
|
|
void AP_Logger_File::PrepForArming_start_logging()
|
2021-06-13 20:46:51 -03:00
|
|
|
{
|
|
|
|
if (logging_started()) {
|
|
|
|
return;
|
|
|
|
}
|
2021-06-14 22:09:24 -03:00
|
|
|
|
2021-06-13 20:46:51 -03:00
|
|
|
uint32_t start_ms = AP_HAL::millis();
|
2021-06-15 01:25:45 -03:00
|
|
|
const uint32_t open_limit_ms = 1000;
|
2021-06-13 20:46:51 -03:00
|
|
|
|
|
|
|
/*
|
|
|
|
log open happens in the io_timer thread. We allow for a maximum
|
2021-06-15 01:25:45 -03:00
|
|
|
of 1s to complete the open
|
2021-06-13 20:46:51 -03:00
|
|
|
*/
|
|
|
|
start_new_log_pending = true;
|
2021-06-15 01:25:45 -03:00
|
|
|
EXPECT_DELAY_MS(1000);
|
2021-06-13 20:46:51 -03:00
|
|
|
while (AP_HAL::millis() - start_ms < open_limit_ms) {
|
|
|
|
if (logging_started()) {
|
|
|
|
break;
|
|
|
|
}
|
2023-06-23 21:01:52 -03:00
|
|
|
#if !APM_BUILD_TYPE(APM_BUILD_Replay) && AP_AHRS_ENABLED
|
2021-06-15 01:25:45 -03:00
|
|
|
// keep the EKF ticking over
|
|
|
|
AP::ahrs().update();
|
|
|
|
#endif
|
2021-06-13 20:46:51 -03:00
|
|
|
hal.scheduler->delay(1);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2013-12-27 23:24:28 -04:00
|
|
|
/*
|
|
|
|
start writing to a new log file
|
|
|
|
*/
|
2020-01-20 13:27:12 -04:00
|
|
|
void AP_Logger_File::start_new_log(void)
|
2013-12-27 23:24:28 -04:00
|
|
|
{
|
2019-10-03 23:10:39 -03:00
|
|
|
if (recent_open_error()) {
|
2014-12-20 22:31:27 -04:00
|
|
|
// we have previously failed to open a file - don't try again
|
|
|
|
// to prevent us trying to open files while in flight
|
2020-01-20 13:27:12 -04:00
|
|
|
return;
|
2014-12-20 22:31:27 -04:00
|
|
|
}
|
|
|
|
|
2021-03-28 22:05:57 -03:00
|
|
|
if (erase.log_num != 0) {
|
|
|
|
// don't start a new log while erasing, but record that we
|
|
|
|
// want to start logging when erase finished
|
|
|
|
erase.was_logging = true;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2019-10-03 23:10:39 -03:00
|
|
|
const bool open_error_ms_was_zero = (_open_error_ms == 0);
|
|
|
|
|
AP_Logger: prevent potential infinite recursion in log-open codepath
If anything in start_new_log did logging (for example, by sending a
statustext), we end up infinitely recursing.
With the patch:
diff --git a/libraries/AP_Logger/AP_Logger_File.cpp b/libraries/AP_Logger/AP_Logger_File.cpp
index 69b8ef0431..eb422d10f8 100644
--- a/libraries/AP_Logger/AP_Logger_File.cpp
+++ b/libraries/AP_Logger/AP_Logger_File.cpp
@@ -778,6 +778,7 @@ void AP_Logger_File::PrepForArming()
*/
void AP_Logger_File::start_new_log(void)
{
+ gcs().send_text(MAV_SEVERITY_WARNING, "Starting new log");
stop_logging();
start_new_log_reset_variables();
pbarker@bluebottle:~/rc/ardupilot(master)$
We see:
at ../../libraries/AP_Logger/AP_Logger_File.cpp:781
this=0x555555ad9d30, pBuffer=0x7fffff8209d0, size=75, is_critical=true)
at ../../libraries/AP_Logger/AP_Logger_Backend.cpp:372
this=0x555555ad9d30, pBuffer=0x7fffff8209d0, size=75)
at ../../libraries/AP_Logger/AP_Logger_Backend.h:32
this=0x555555ad9d30, message=0x7fffff820b10 "Starting new log")
at ../../libraries/AP_Logger/LogFile.cpp:466
this=0x555555a6d758 <copter+11384>,
message=0x7fffff820b10 "Starting new log")
at ../../libraries/AP_Logger/AP_Logger.cpp:752
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log", arg_list=0x7fffff820be0,
dest_bitmask=1 '\001') at ../../libraries/GCS_MAVLink/GCS_Common.cpp:1847
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log", arg_list=0x7fffff820be0)
at ../../libraries/GCS_MAVLink/GCS.cpp:53
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log")
at ../../libraries/GCS_MAVLink/GCS.cpp:60
at ../../libraries/AP_Logger/AP_Logger_File.cpp:781
this=0x555555ad9d30, pBuffer=0x7fffff820dc0, size=75, is_critical=true)
at ../../libraries/AP_Logger/AP_Logger_Backend.cpp:372
I'm not aware of any instances in the code where this will actually
happen - but it could easily sneak in.
2020-05-10 22:42:19 -03:00
|
|
|
// set _open_error here to avoid infinite recursion. Simply
|
|
|
|
// writing a prioritised block may try to open a log - which means
|
2024-08-07 00:17:21 -03:00
|
|
|
// if anything in the start_new_log path does a GCS_SEND_TEXT()
|
AP_Logger: prevent potential infinite recursion in log-open codepath
If anything in start_new_log did logging (for example, by sending a
statustext), we end up infinitely recursing.
With the patch:
diff --git a/libraries/AP_Logger/AP_Logger_File.cpp b/libraries/AP_Logger/AP_Logger_File.cpp
index 69b8ef0431..eb422d10f8 100644
--- a/libraries/AP_Logger/AP_Logger_File.cpp
+++ b/libraries/AP_Logger/AP_Logger_File.cpp
@@ -778,6 +778,7 @@ void AP_Logger_File::PrepForArming()
*/
void AP_Logger_File::start_new_log(void)
{
+ gcs().send_text(MAV_SEVERITY_WARNING, "Starting new log");
stop_logging();
start_new_log_reset_variables();
pbarker@bluebottle:~/rc/ardupilot(master)$
We see:
at ../../libraries/AP_Logger/AP_Logger_File.cpp:781
this=0x555555ad9d30, pBuffer=0x7fffff8209d0, size=75, is_critical=true)
at ../../libraries/AP_Logger/AP_Logger_Backend.cpp:372
this=0x555555ad9d30, pBuffer=0x7fffff8209d0, size=75)
at ../../libraries/AP_Logger/AP_Logger_Backend.h:32
this=0x555555ad9d30, message=0x7fffff820b10 "Starting new log")
at ../../libraries/AP_Logger/LogFile.cpp:466
this=0x555555a6d758 <copter+11384>,
message=0x7fffff820b10 "Starting new log")
at ../../libraries/AP_Logger/AP_Logger.cpp:752
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log", arg_list=0x7fffff820be0,
dest_bitmask=1 '\001') at ../../libraries/GCS_MAVLink/GCS_Common.cpp:1847
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log", arg_list=0x7fffff820be0)
at ../../libraries/GCS_MAVLink/GCS.cpp:53
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log")
at ../../libraries/GCS_MAVLink/GCS.cpp:60
at ../../libraries/AP_Logger/AP_Logger_File.cpp:781
this=0x555555ad9d30, pBuffer=0x7fffff820dc0, size=75, is_critical=true)
at ../../libraries/AP_Logger/AP_Logger_Backend.cpp:372
I'm not aware of any instances in the code where this will actually
happen - but it could easily sneak in.
2020-05-10 22:42:19 -03:00
|
|
|
// (for example), you will end up recursing if we don't take
|
|
|
|
// precautions. We will reset _open_error if we actually manage
|
|
|
|
// to open the log...
|
2019-10-03 23:10:39 -03:00
|
|
|
_open_error_ms = AP_HAL::millis();
|
AP_Logger: prevent potential infinite recursion in log-open codepath
If anything in start_new_log did logging (for example, by sending a
statustext), we end up infinitely recursing.
With the patch:
diff --git a/libraries/AP_Logger/AP_Logger_File.cpp b/libraries/AP_Logger/AP_Logger_File.cpp
index 69b8ef0431..eb422d10f8 100644
--- a/libraries/AP_Logger/AP_Logger_File.cpp
+++ b/libraries/AP_Logger/AP_Logger_File.cpp
@@ -778,6 +778,7 @@ void AP_Logger_File::PrepForArming()
*/
void AP_Logger_File::start_new_log(void)
{
+ gcs().send_text(MAV_SEVERITY_WARNING, "Starting new log");
stop_logging();
start_new_log_reset_variables();
pbarker@bluebottle:~/rc/ardupilot(master)$
We see:
at ../../libraries/AP_Logger/AP_Logger_File.cpp:781
this=0x555555ad9d30, pBuffer=0x7fffff8209d0, size=75, is_critical=true)
at ../../libraries/AP_Logger/AP_Logger_Backend.cpp:372
this=0x555555ad9d30, pBuffer=0x7fffff8209d0, size=75)
at ../../libraries/AP_Logger/AP_Logger_Backend.h:32
this=0x555555ad9d30, message=0x7fffff820b10 "Starting new log")
at ../../libraries/AP_Logger/LogFile.cpp:466
this=0x555555a6d758 <copter+11384>,
message=0x7fffff820b10 "Starting new log")
at ../../libraries/AP_Logger/AP_Logger.cpp:752
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log", arg_list=0x7fffff820be0,
dest_bitmask=1 '\001') at ../../libraries/GCS_MAVLink/GCS_Common.cpp:1847
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log", arg_list=0x7fffff820be0)
at ../../libraries/GCS_MAVLink/GCS.cpp:53
this=0x555555a6e708 <copter+15400>, severity=MAV_SEVERITY_WARNING,
fmt=0x5555557d64d0 "Starting new log")
at ../../libraries/GCS_MAVLink/GCS.cpp:60
at ../../libraries/AP_Logger/AP_Logger_File.cpp:781
this=0x555555ad9d30, pBuffer=0x7fffff820dc0, size=75, is_critical=true)
at ../../libraries/AP_Logger/AP_Logger_Backend.cpp:372
I'm not aware of any instances in the code where this will actually
happen - but it could easily sneak in.
2020-05-10 22:42:19 -03:00
|
|
|
|
|
|
|
stop_logging();
|
|
|
|
|
|
|
|
start_new_log_reset_variables();
|
|
|
|
|
2013-12-15 03:57:49 -04:00
|
|
|
if (_read_fd != -1) {
|
2019-08-01 02:14:22 -03:00
|
|
|
AP::FS().close(_read_fd);
|
2013-12-15 03:57:49 -04:00
|
|
|
_read_fd = -1;
|
|
|
|
}
|
2013-04-17 08:32:53 -03:00
|
|
|
|
2019-08-03 04:00:17 -03:00
|
|
|
if (disk_space_avail() < _free_space_min_avail && disk_space() > 0) {
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("Out of space for logging\n");
|
2020-01-20 13:27:12 -04:00
|
|
|
return;
|
2016-07-06 05:58:47 -03:00
|
|
|
}
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
uint16_t log_num = find_last_log();
|
|
|
|
// re-use empty logs if possible
|
2013-04-19 21:41:04 -03:00
|
|
|
if (_get_log_size(log_num) > 0 || log_num == 0) {
|
2013-04-17 08:32:53 -03:00
|
|
|
log_num++;
|
|
|
|
}
|
2023-09-20 12:35:17 -03:00
|
|
|
if (log_num > _front.get_max_num_logs()) {
|
2013-04-17 08:32:53 -03:00
|
|
|
log_num = 1;
|
|
|
|
}
|
2018-10-11 20:35:04 -03:00
|
|
|
if (!write_fd_semaphore.take(1)) {
|
2020-01-20 13:27:12 -04:00
|
|
|
return;
|
2015-12-08 08:07:43 -04:00
|
|
|
}
|
2018-06-13 21:32:44 -03:00
|
|
|
if (_write_filename) {
|
|
|
|
free(_write_filename);
|
|
|
|
_write_filename = nullptr;
|
|
|
|
}
|
|
|
|
_write_filename = _log_file_name(log_num);
|
|
|
|
if (_write_filename == nullptr) {
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2020-01-20 13:27:12 -04:00
|
|
|
return;
|
2017-09-12 22:46:34 -03:00
|
|
|
}
|
2019-07-10 23:16:29 -03:00
|
|
|
|
2019-07-15 20:39:49 -03:00
|
|
|
#if CONFIG_HAL_BOARD == HAL_BOARD_CHIBIOS
|
2019-07-10 23:16:29 -03:00
|
|
|
// remember if we had utc time when we opened the file
|
2023-10-05 04:40:34 -03:00
|
|
|
#if AP_RTC_ENABLED
|
2019-07-10 23:16:29 -03:00
|
|
|
uint64_t utc_usec;
|
|
|
|
_need_rtc_update = !AP::rtc().get_utc_usec(utc_usec);
|
2023-10-05 04:40:34 -03:00
|
|
|
#endif
|
2019-07-15 20:39:49 -03:00
|
|
|
#endif
|
2019-07-10 23:16:29 -03:00
|
|
|
|
2020-05-10 23:18:31 -03:00
|
|
|
// create the log directory if need be
|
|
|
|
ensure_log_directory_exists();
|
|
|
|
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2019-08-01 02:14:22 -03:00
|
|
|
_write_fd = AP::FS().open(_write_filename, O_WRONLY|O_CREAT|O_TRUNC);
|
2015-11-10 23:51:03 -04:00
|
|
|
_cached_oldest_log = 0;
|
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
if (_write_fd == -1) {
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2014-12-20 22:31:27 -04:00
|
|
|
int saved_errno = errno;
|
2019-10-03 23:10:39 -03:00
|
|
|
if (open_error_ms_was_zero) {
|
|
|
|
::printf("Log open fail for %s - %s\n",
|
|
|
|
_write_filename, strerror(saved_errno));
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("Log open fail for %s - %s\n",
|
2019-10-03 23:10:39 -03:00
|
|
|
_write_filename, strerror(saved_errno));
|
|
|
|
}
|
2020-01-20 13:27:12 -04:00
|
|
|
return;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
2018-06-13 21:32:44 -03:00
|
|
|
_last_write_ms = AP_HAL::millis();
|
2019-10-03 23:10:39 -03:00
|
|
|
_open_error_ms = 0;
|
2014-01-12 23:25:16 -04:00
|
|
|
_write_offset = 0;
|
2016-07-29 21:52:21 -03:00
|
|
|
_writebuf.clear();
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2013-04-17 08:32:53 -03:00
|
|
|
|
2023-04-11 07:14:09 -03:00
|
|
|
// now update lastlog.txt with the new log number
|
|
|
|
last_log_is_marked_discard = _front._params.log_disarmed == AP_Logger::LogDisarmed::LOG_WHILE_DISARMED_DISCARD;
|
|
|
|
if (!write_lastlog_file(log_num)) {
|
|
|
|
_open_error_ms = AP_HAL::millis();
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
write LASTLOG.TXT, possibly with a discard marker
|
|
|
|
*/
|
|
|
|
bool AP_Logger_File::write_lastlog_file(uint16_t log_num)
|
|
|
|
{
|
2013-04-17 08:32:53 -03:00
|
|
|
// now update lastlog.txt with the new log number
|
2018-06-13 21:32:44 -03:00
|
|
|
char *fname = _lastlog_file_name();
|
2015-12-08 19:53:20 -04:00
|
|
|
|
2019-05-15 01:09:50 -03:00
|
|
|
EXPECT_DELAY_MS(3000);
|
2019-08-01 02:14:22 -03:00
|
|
|
int fd = AP::FS().open(fname, O_WRONLY|O_CREAT);
|
2015-12-08 19:53:20 -04:00
|
|
|
free(fname);
|
|
|
|
if (fd == -1) {
|
2023-04-11 07:14:09 -03:00
|
|
|
return false;
|
2015-12-08 08:18:37 -04:00
|
|
|
}
|
2015-12-08 19:53:20 -04:00
|
|
|
|
|
|
|
char buf[30];
|
2023-04-11 07:14:09 -03:00
|
|
|
snprintf(buf, sizeof(buf), "%u%s\r\n", (unsigned)log_num, last_log_is_marked_discard?"D":"");
|
2016-08-25 00:57:58 -03:00
|
|
|
const ssize_t to_write = strlen(buf);
|
2019-08-01 02:14:22 -03:00
|
|
|
const ssize_t written = AP::FS().write(fd, buf, to_write);
|
|
|
|
AP::FS().close(fd);
|
2023-04-11 07:14:09 -03:00
|
|
|
return written == to_write;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
|
2015-06-18 22:57:01 -03:00
|
|
|
#if CONFIG_HAL_BOARD == HAL_BOARD_SITL || CONFIG_HAL_BOARD == HAL_BOARD_LINUX
|
2019-01-18 00:23:42 -04:00
|
|
|
void AP_Logger_File::flush(void)
|
2022-10-15 15:39:27 -03:00
|
|
|
#if APM_BUILD_TYPE(APM_BUILD_Replay)
|
2015-06-18 22:57:01 -03:00
|
|
|
{
|
2016-11-06 01:26:31 -04:00
|
|
|
uint32_t tnow = AP_HAL::millis();
|
2019-10-03 23:10:39 -03:00
|
|
|
while (_write_fd != -1 && _initialised && !recent_open_error() && _writebuf.available()) {
|
2015-06-18 22:57:01 -03:00
|
|
|
// convince the IO timer that it really is OK to write out
|
|
|
|
// less than _writebuf_chunk bytes:
|
2016-11-06 01:26:31 -04:00
|
|
|
if (tnow > 2001) { // avoid resetting _last_write_time to 0
|
|
|
|
_last_write_time = tnow - 2001;
|
2016-04-26 09:12:19 -03:00
|
|
|
}
|
2020-12-22 13:25:44 -04:00
|
|
|
io_timer();
|
2015-06-18 22:57:01 -03:00
|
|
|
}
|
2018-10-11 20:35:04 -03:00
|
|
|
if (write_fd_semaphore.take(1)) {
|
2017-09-12 22:46:34 -03:00
|
|
|
if (_write_fd != -1) {
|
|
|
|
::fsync(_write_fd);
|
|
|
|
}
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2017-09-12 22:46:34 -03:00
|
|
|
} else {
|
2020-04-29 21:40:46 -03:00
|
|
|
INTERNAL_ERROR(AP_InternalError::error_t::logger_flushing_without_sem);
|
2015-06-18 22:57:01 -03:00
|
|
|
}
|
|
|
|
}
|
2018-05-13 19:45:48 -03:00
|
|
|
#else
|
|
|
|
{
|
|
|
|
// flush is for replay and examples only
|
|
|
|
}
|
|
|
|
#endif // APM_BUILD_TYPE(APM_BUILD_Replay) || APM_BUILD_TYPE(APM_BUILD_UNKNOWN)
|
2015-06-18 22:57:01 -03:00
|
|
|
#endif
|
2013-04-17 08:32:53 -03:00
|
|
|
|
2020-12-22 13:25:44 -04:00
|
|
|
void AP_Logger_File::io_timer(void)
|
2013-04-17 08:32:53 -03:00
|
|
|
{
|
2021-09-25 21:13:14 -03:00
|
|
|
uint32_t tnow = AP_HAL::millis();
|
|
|
|
_io_timer_heartbeat = tnow;
|
|
|
|
|
2021-06-13 20:46:51 -03:00
|
|
|
if (start_new_log_pending) {
|
|
|
|
start_new_log();
|
|
|
|
start_new_log_pending = false;
|
|
|
|
}
|
|
|
|
|
2021-03-28 22:05:57 -03:00
|
|
|
if (erase.log_num != 0) {
|
|
|
|
// continue erase
|
|
|
|
erase_next();
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2019-10-03 23:10:39 -03:00
|
|
|
if (_write_fd == -1 || !_initialised || recent_open_error()) {
|
2013-04-17 08:32:53 -03:00
|
|
|
return;
|
|
|
|
}
|
2014-01-13 21:39:49 -04:00
|
|
|
|
2023-04-11 07:14:09 -03:00
|
|
|
if (last_log_is_marked_discard && hal.util->get_soft_armed()) {
|
|
|
|
// time to make the log permanent
|
|
|
|
const auto log_num = find_last_log();
|
|
|
|
last_log_is_marked_discard = false;
|
|
|
|
write_lastlog_file(log_num);
|
|
|
|
}
|
|
|
|
|
2016-07-29 21:52:21 -03:00
|
|
|
uint32_t nbytes = _writebuf.available();
|
2013-04-17 08:32:53 -03:00
|
|
|
if (nbytes == 0) {
|
|
|
|
return;
|
|
|
|
}
|
2014-01-12 23:25:16 -04:00
|
|
|
if (nbytes < _writebuf_chunk &&
|
2016-11-06 01:26:31 -04:00
|
|
|
tnow - _last_write_time < 2000UL) {
|
2015-07-19 21:41:14 -03:00
|
|
|
// write in _writebuf_chunk-sized chunks, but always write at
|
|
|
|
// least once per 2 seconds if data is available
|
2013-04-17 08:32:53 -03:00
|
|
|
return;
|
|
|
|
}
|
2016-07-06 05:58:47 -03:00
|
|
|
if (tnow - _free_space_last_check_time > _free_space_check_interval) {
|
|
|
|
_free_space_last_check_time = tnow;
|
2017-07-27 23:07:35 -03:00
|
|
|
last_io_operation = "disk_space_avail";
|
2019-08-03 04:00:17 -03:00
|
|
|
if (disk_space_avail() < _free_space_min_avail && disk_space() > 0) {
|
2022-03-21 06:26:16 -03:00
|
|
|
DEV_PRINTF("Out of space for logging\n");
|
2016-07-06 05:58:47 -03:00
|
|
|
stop_logging();
|
2019-10-03 23:10:39 -03:00
|
|
|
_open_error_ms = AP_HAL::millis(); // prevent logging starting again for 5s
|
2017-07-27 23:07:35 -03:00
|
|
|
last_io_operation = "";
|
2016-07-06 05:58:47 -03:00
|
|
|
return;
|
|
|
|
}
|
2017-07-27 23:07:35 -03:00
|
|
|
last_io_operation = "";
|
2016-07-06 05:58:47 -03:00
|
|
|
}
|
2014-01-12 23:25:16 -04:00
|
|
|
|
2013-04-17 08:32:53 -03:00
|
|
|
_last_write_time = tnow;
|
2014-01-12 23:25:16 -04:00
|
|
|
if (nbytes > _writebuf_chunk) {
|
2019-01-19 03:41:56 -04:00
|
|
|
// be kind to the filesystem layer
|
2014-01-12 23:25:16 -04:00
|
|
|
nbytes = _writebuf_chunk;
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
2014-01-12 23:25:16 -04:00
|
|
|
|
2016-07-29 21:52:21 -03:00
|
|
|
uint32_t size;
|
|
|
|
const uint8_t *head = _writebuf.readptr(size);
|
|
|
|
nbytes = MIN(nbytes, size);
|
|
|
|
|
|
|
|
// try to align writes on a 512 byte boundary to avoid filesystem reads
|
2014-01-12 23:25:16 -04:00
|
|
|
if ((nbytes + _write_offset) % 512 != 0) {
|
|
|
|
uint32_t ofs = (nbytes + _write_offset) % 512;
|
|
|
|
if (ofs < nbytes) {
|
|
|
|
nbytes -= ofs;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2017-07-27 23:07:35 -03:00
|
|
|
last_io_operation = "write";
|
2018-10-11 20:35:04 -03:00
|
|
|
if (!write_fd_semaphore.take(1)) {
|
2017-09-12 22:46:34 -03:00
|
|
|
return;
|
|
|
|
}
|
|
|
|
if (_write_fd == -1) {
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2017-09-12 22:46:34 -03:00
|
|
|
return;
|
|
|
|
}
|
2019-08-01 02:14:22 -03:00
|
|
|
ssize_t nwritten = AP::FS().write(_write_fd, head, nbytes);
|
2017-07-27 23:07:35 -03:00
|
|
|
last_io_operation = "";
|
2013-04-17 08:32:53 -03:00
|
|
|
if (nwritten <= 0) {
|
2019-08-03 04:00:17 -03:00
|
|
|
if ((tnow - _last_write_ms)/1000U > unsigned(_front._params.file_timeout)) {
|
|
|
|
// if we can't write for LOG_FILE_TIMEOUT seconds we give up and close
|
2018-06-13 21:32:44 -03:00
|
|
|
// the file. This allows us to cope with temporary write
|
|
|
|
// failures caused by directory listing
|
|
|
|
last_io_operation = "close";
|
2019-08-01 02:14:22 -03:00
|
|
|
AP::FS().close(_write_fd);
|
2018-06-13 21:32:44 -03:00
|
|
|
last_io_operation = "";
|
|
|
|
_write_fd = -1;
|
|
|
|
printf("Failed to write to File: %s\n", strerror(errno));
|
|
|
|
}
|
2019-08-03 04:00:17 -03:00
|
|
|
_last_write_failed = true;
|
2013-04-17 08:32:53 -03:00
|
|
|
} else {
|
2019-08-03 04:00:17 -03:00
|
|
|
_last_write_failed = false;
|
2018-06-13 21:32:44 -03:00
|
|
|
_last_write_ms = tnow;
|
2014-01-12 23:25:16 -04:00
|
|
|
_write_offset += nwritten;
|
2016-07-29 21:52:21 -03:00
|
|
|
_writebuf.advance(nwritten);
|
2014-01-13 21:39:49 -04:00
|
|
|
/*
|
2016-07-29 21:52:21 -03:00
|
|
|
the best strategy for minimizing corruption on microSD cards
|
2014-01-13 21:39:49 -04:00
|
|
|
seems to be to write in 4k chunks and fsync the file on each
|
|
|
|
chunk, ensuring the directory entry is updated after each
|
|
|
|
write.
|
|
|
|
*/
|
2018-05-11 09:26:52 -03:00
|
|
|
#if CONFIG_HAL_BOARD != HAL_BOARD_SITL && CONFIG_HAL_BOARD_SUBTYPE != HAL_BOARD_SUBTYPE_LINUX_NONE
|
2017-07-27 23:07:35 -03:00
|
|
|
last_io_operation = "fsync";
|
2019-08-01 02:14:22 -03:00
|
|
|
AP::FS().fsync(_write_fd);
|
2017-07-27 23:07:35 -03:00
|
|
|
last_io_operation = "";
|
2014-01-13 21:40:41 -04:00
|
|
|
#endif
|
2019-07-10 23:16:29 -03:00
|
|
|
|
2023-10-05 04:40:34 -03:00
|
|
|
#if AP_RTC_ENABLED && CONFIG_HAL_BOARD == HAL_BOARD_CHIBIOS
|
2019-07-10 23:16:29 -03:00
|
|
|
// ChibiOS does not update mtime on writes, so if we opened
|
|
|
|
// without knowing the time we should update it later
|
|
|
|
if (_need_rtc_update) {
|
|
|
|
uint64_t utc_usec;
|
|
|
|
if (AP::rtc().get_utc_usec(utc_usec)) {
|
2019-08-26 02:55:44 -03:00
|
|
|
AP::FS().set_mtime(_write_filename, utc_usec/(1000U*1000U));
|
2019-07-10 23:16:29 -03:00
|
|
|
_need_rtc_update = false;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
#endif
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
2019-07-10 23:16:29 -03:00
|
|
|
|
2018-10-11 20:35:04 -03:00
|
|
|
write_fd_semaphore.give();
|
2013-04-17 08:32:53 -03:00
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
bool AP_Logger_File::io_thread_alive() const
|
2016-11-06 02:09:39 -04:00
|
|
|
{
|
2021-03-23 19:31:10 -03:00
|
|
|
if (!hal.scheduler->is_system_initialized()) {
|
2021-09-25 21:13:14 -03:00
|
|
|
// the system has long pauses during initialisation, assume still OK
|
|
|
|
return true;
|
2021-03-23 19:31:10 -03:00
|
|
|
}
|
|
|
|
// if the io thread hasn't had a heartbeat in a while then it is
|
2021-10-27 05:06:41 -03:00
|
|
|
#if CONFIG_HAL_BOARD == HAL_BOARD_ESP32
|
|
|
|
uint32_t timeout_ms = 10000;
|
|
|
|
#else
|
2021-09-25 21:13:14 -03:00
|
|
|
uint32_t timeout_ms = 5000;
|
2021-10-27 05:06:41 -03:00
|
|
|
#endif
|
2021-05-19 23:34:13 -03:00
|
|
|
#if CONFIG_HAL_BOARD == HAL_BOARD_SITL && !defined(HAL_BUILD_AP_PERIPH)
|
2021-03-23 19:31:10 -03:00
|
|
|
// the IO thread is working with hardware - writing to a physical
|
|
|
|
// disk. Unfortunately these hardware devices do not obey our
|
|
|
|
// SITL speedup options, so we allow for it here.
|
2021-07-30 07:14:44 -03:00
|
|
|
SITL::SIM *sitl = AP::sitl();
|
2021-03-23 19:31:10 -03:00
|
|
|
if (sitl != nullptr) {
|
|
|
|
timeout_ms *= sitl->speedup;
|
|
|
|
}
|
|
|
|
#endif
|
|
|
|
return (AP_HAL::millis() - _io_timer_heartbeat) < timeout_ms;
|
2016-11-06 02:09:39 -04:00
|
|
|
}
|
|
|
|
|
2019-01-18 00:23:42 -04:00
|
|
|
bool AP_Logger_File::logging_failed() const
|
2016-07-07 04:12:27 -03:00
|
|
|
{
|
2017-09-11 08:28:04 -03:00
|
|
|
if (!_initialised) {
|
|
|
|
return true;
|
|
|
|
}
|
2019-10-03 23:10:39 -03:00
|
|
|
if (recent_open_error()) {
|
2016-07-07 04:12:27 -03:00
|
|
|
return true;
|
|
|
|
}
|
2016-11-06 02:09:39 -04:00
|
|
|
if (!io_thread_alive()) {
|
|
|
|
// No heartbeat in a second. IO thread is dead?! Very Not
|
|
|
|
// Good.
|
|
|
|
return true;
|
|
|
|
}
|
2019-08-03 04:00:17 -03:00
|
|
|
if (_last_write_failed) {
|
|
|
|
return true;
|
|
|
|
}
|
2016-11-06 02:09:39 -04:00
|
|
|
|
2016-07-07 04:12:27 -03:00
|
|
|
return false;
|
|
|
|
}
|
|
|
|
|
2021-03-28 22:05:57 -03:00
|
|
|
/*
|
|
|
|
erase another file in async erase operation
|
|
|
|
*/
|
|
|
|
void AP_Logger_File::erase_next(void)
|
|
|
|
{
|
|
|
|
char *fname = _log_file_name(erase.log_num);
|
|
|
|
if (fname == nullptr) {
|
|
|
|
erase.log_num = 0;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
|
|
|
AP::FS().unlink(fname);
|
|
|
|
free(fname);
|
|
|
|
|
|
|
|
erase.log_num++;
|
2023-09-20 12:35:17 -03:00
|
|
|
if (erase.log_num <= _front.get_max_num_logs()) {
|
2021-03-28 22:05:57 -03:00
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
|
|
|
fname = _lastlog_file_name();
|
|
|
|
if (fname != nullptr) {
|
|
|
|
AP::FS().unlink(fname);
|
|
|
|
free(fname);
|
|
|
|
}
|
|
|
|
|
|
|
|
_cached_oldest_log = 0;
|
|
|
|
|
|
|
|
erase.log_num = 0;
|
|
|
|
}
|
|
|
|
|
2021-01-06 22:04:09 -04:00
|
|
|
#endif // HAL_LOGGING_FILESYSTEM_ENABLED
|
2019-08-01 02:14:22 -03:00
|
|
|
|