Mirror/ardupilot
5
0
Fork 0
mirror of https://github.com/ArduPilot/ardupilot synced 2025-03-01 03:04:04 -04:00
Code Issues Packages Projects Releases Wiki Activity
d0824a8d9b
ardupilot/libraries/AP_Logger/AP_Logger_File.cpp
Thomas Watson ca3c2c7c72 AP_Logger: File: take advantage of new optimal fsync API 
Now FATFS will always sync on 4K boundaries even if it gets misaligned
due to a short or forced write.

LittleFS behavior is verified identical.
2025-02-17 16:33:51 +11:00

1119 lines
31 KiB
C++
Raw Blame History

/*
AP_Logger logging - file oriented variant
This uses posix file IO to create log files called logs/NN.bin in the
given directory
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
*/
#include "AP_Logger_config.h"
#if HAL_LOGGING_FILESYSTEM_ENABLED
#include <AP_HAL/AP_HAL.h>
#include <AP_Filesystem/AP_Filesystem.h>
#if AP_FILESYSTEM_LITTLEFS_ENABLED
#include <AP_Filesystem/AP_Filesystem_FlashMemory_LittleFS.h>
#endif
#include "AP_Logger.h"
#include "AP_Logger_File.h"
#include <AP_Common/AP_Common.h>
#include <AP_InternalError/AP_InternalError.h>
#include <AP_RTC/AP_RTC.h>
#include <AP_Vehicle/AP_Vehicle_Type.h>
#include <AP_AHRS/AP_AHRS.h>
#include <AP_Math/AP_Math.h>
#include <GCS_MAVLink/GCS.h>
#include <stdio.h>
extern const AP_HAL::HAL& hal;
#define LOGGER_PAGE_SIZE 1024UL
#define MB_to_B 1000000
#define B_to_MB 0.000001
// time between tries to open log
#define LOGGER_FILE_REOPEN_MS 5000
/*
constructor
*/
AP_Logger_File::AP_Logger_File(AP_Logger &front,
LoggerMessageWriter_DFLogStart *writer) :
AP_Logger_Backend(front, writer),
_log_directory(HAL_BOARD_LOG_DIRECTORY)
{
df_stats_clear();
}
void AP_Logger_File::ensure_log_directory_exists()
{
int ret;
struct stat st;
EXPECT_DELAY_MS(3000);
ret = AP::FS().stat(_log_directory, &st);
if (ret == -1) {
ret = AP::FS().mkdir(_log_directory);
}
if (ret == -1 && errno != EEXIST) {
GCS_SEND_TEXT(MAV_SEVERITY_WARNING, "Failed to create log directory %s : %s", _log_directory, strerror(errno));
}
}
void AP_Logger_File::Init()
{
// determine and limit file backend buffersize
uint32_t bufsize = _front._params.file_bufsize;
bufsize *= 1024;
const uint32_t desired_bufsize = bufsize;
// 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) {
bufsize *= 0.9;
}
if (bufsize >= _writebuf_chunk && bufsize != desired_bufsize) {
DEV_PRINTF("AP_Logger: reduced buffer %u/%u\n", (unsigned)bufsize, (unsigned)desired_bufsize);
}
if (!_writebuf.get_size()) {
DEV_PRINTF("Out of memory for logging\n");
return;
}
DEV_PRINTF("AP_Logger_File: buffer size=%u\n", (unsigned)bufsize);
_initialised = true;
const char* custom_dir = hal.util->get_custom_log_directory();
if (custom_dir != nullptr){
_log_directory = custom_dir;
}
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);
}
}
Prep_MinSpace();
}
bool AP_Logger_File::file_exists(const char *filename) const
{
struct stat st;
EXPECT_DELAY_MS(3000);
if (AP::FS().stat(filename, &st) == -1) {
// hopefully errno==ENOENT. If some error occurs it is
// probably better to assume this file exists.
return false;
}
return true;
}
bool AP_Logger_File::log_exists(const uint16_t lognum) const
{
char *filename = _log_file_name(lognum);
if (filename == nullptr) {
return false; // ?!
}
bool ret = file_exists(filename);
free(filename);
return ret;
}
void AP_Logger_File::periodic_1Hz()
{
AP_Logger_Backend::periodic_1Hz();
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;
// setup to open the log in the backend thread
start_new_log_pending = true;
}
if (_initialised &&
!start_new_log_pending &&
_write_fd == -1 && _read_fd == -1 &&
logging_enabled() &&
!recent_open_error()) {
// setup to open the log in the backend thread
start_new_log_pending = true;
}
if (!io_thread_alive()) {
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
GCS_SEND_TEXT(MAV_SEVERITY_CRITICAL, "AP_Logger: stuck thread (%s)", last_io_operation);
}
if (io_thread_warning_decimation_counter++ > 30) {
io_thread_warning_decimation_counter = 0;
}
}
if (rate_limiter == nullptr &&
(_front._params.file_ratemax > 0 ||
_front._params.disarm_ratemax > 0 ||
_front._log_pause)) {
// setup rate limiting if log rate max > 0Hz or log pause of streaming entries is requested
rate_limiter = NEW_NOTHROW AP_Logger_RateLimiter(_front, _front._params.file_ratemax, _front._params.disarm_ratemax);
}
}
void AP_Logger_File::periodic_fullrate()
{
AP_Logger_Backend::push_log_blocks();
}
uint32_t AP_Logger_File::bufferspace_available()
{
const uint32_t space = _writebuf.space();
const uint32_t crit = critical_message_reserved_space(_writebuf.get_size());
return (space > crit) ? space - crit : 0;
}
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;
}
// return true for CardInserted() if we successfully initialized
bool AP_Logger_File::CardInserted(void) const
{
return _initialised && !recent_open_error();
}
// returns the amount of disk space available in _log_directory (in bytes)
// returns -1 on error
int64_t AP_Logger_File::disk_space_avail()
{
return AP::FS().disk_free(_log_directory);
}
// returns the total amount of disk space (in use + available) in
// _log_directory (in bytes).
// returns -1 on error
int64_t AP_Logger_File::disk_space()
{
return AP::FS().disk_space(_log_directory);
}
/*
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);
if (thisnum > _front.get_max_num_logs()) {
return false;
}
log_num = thisnum;
return true;
}
// find_oldest_log - find oldest log in _log_directory
// returns 0 if no log was found
uint16_t AP_Logger_File::find_oldest_log()
{
if (_cached_oldest_log != 0) {
return _cached_oldest_log;
}
uint16_t last_log_num = find_last_log();
if (last_log_num == 0) {
return 0;
}
uint16_t current_oldest_log = 0; // 0 is invalid
// 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
EXPECT_DELAY_MS(3000);
auto *d = AP::FS().opendir(_log_directory);
if (d == nullptr) {
// SD card may have died? On linux someone may have rm-rf-d
return 0;
}
// we only remove files which look like xxx.BIN
EXPECT_DELAY_MS(3000);
for (struct dirent *de=AP::FS().readdir(d); de; de=AP::FS().readdir(d)) {
EXPECT_DELAY_MS(3000);
uint16_t thisnum;
if (!dirent_to_log_num(de, thisnum)) {
// not a log filename
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;
}
}
}
}
}
AP::FS().closedir(d);
_cached_oldest_log = current_oldest_log;
return current_oldest_log;
}
void AP_Logger_File::Prep_MinSpace()
{
if (hal.util->was_watchdog_reset()) {
// don't clear space if watchdog reset, it takes too long
return;
}
if (!CardInserted()) {
return;
}
const uint16_t first_log_to_remove = find_oldest_log();
if (first_log_to_remove == 0) {
// no files to remove
return;
}
const int64_t target_free = (int64_t)_front._params.min_MB_free * MB_to_B;
uint16_t log_to_remove = first_log_to_remove;
uint16_t count = 0;
do {
int64_t avail = disk_space_avail();
if (avail == -1) {
break;
}
if (avail >= target_free) {
break;
}
if (count++ > _front.get_max_num_logs() + 10) {
// *way* too many deletions going on here. Possible internal error.
INTERNAL_ERROR(AP_InternalError::error_t::logger_too_many_deletions);
break;
}
char *filename_to_remove = _log_file_name(log_to_remove);
if (filename_to_remove == nullptr) {
INTERNAL_ERROR(AP_InternalError::error_t::logger_bad_getfilename);
break;
}
if (file_exists(filename_to_remove)) {
DEV_PRINTF("Removing (%s) for minimum-space requirements (%.0fMB < %.0fMB)\n",
filename_to_remove, (double)avail*B_to_MB, (double)target_free*B_to_MB);
EXPECT_DELAY_MS(2000);
if (AP::FS().unlink(filename_to_remove) == -1) {
_cached_oldest_log = 0;
DEV_PRINTF("Failed to remove %s: %s\n", filename_to_remove, strerror(errno));
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 {
break;
}
} else {
free(filename_to_remove);
}
}
log_to_remove++;
if (log_to_remove > _front.get_max_num_logs()) {
log_to_remove = 1;
}
} while (log_to_remove != first_log_to_remove);
}
/*
construct a log file name given a log number.
The number in the log filename will be zero-padded.
Note: Caller must free.
*/
char *AP_Logger_File::_log_file_name(const uint16_t log_num) const
{
char *buf = nullptr;
if (asprintf(&buf, "%s/%08u.BIN", _log_directory, (unsigned)log_num) == -1) {
return nullptr;
}
return buf;
}
/*
return path name of the lastlog.txt marker file
Note: Caller must free.
*/
char *AP_Logger_File::_lastlog_file_name(void) const
{
char *buf = nullptr;
if (asprintf(&buf, "%s/LASTLOG.TXT", _log_directory) == -1) {
return nullptr;
}
return buf;
}
// remove all log files
void AP_Logger_File::EraseAll()
{
if (hal.util->get_soft_armed()) {
// do not want to do any filesystem operations while we are e.g. flying
return;
}
if (!_initialised) {
return;
}
erase.was_logging = (_write_fd != -1);
stop_logging();
erase.log_num = 1;
}
bool AP_Logger_File::WritesOK() const
{
if (_write_fd == -1) {
return false;
}
if (recent_open_error()) {
return false;
}
return true;
}
bool AP_Logger_File::StartNewLogOK() const
{
if (recent_open_error()) {
return false;
}
#if !APM_BUILD_TYPE(APM_BUILD_Replay) && !APM_BUILD_TYPE(APM_BUILD_UNKNOWN)
if (hal.scheduler->in_main_thread()) {
return false;
}
#endif
return AP_Logger_Backend::StartNewLogOK();
}
/* Write a block of data at current offset */
bool AP_Logger_File::_WritePrioritisedBlock(const void *pBuffer, uint16_t size, bool is_critical)
{
WITH_SEMAPHORE(semaphore);
#if APM_BUILD_TYPE(APM_BUILD_Replay)
if (AP::FS().write(_write_fd, pBuffer, size) != size) {
AP_HAL::panic("Short write");
}
return true;
#endif
uint32_t space = _writebuf.space();
if (_writing_startup_messages &&
_startup_messagewriter->fmt_done()) {
// 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:
const uint32_t now = AP_HAL::millis();
const bool must_dribble = (now - last_messagewrite_message_sent) > 100;
if (!must_dribble &&
space < non_messagewriter_message_reserved_space(_writebuf.get_size())) {
// this message isn't dropped, it will be sent again...
return false;
}
last_messagewrite_message_sent = now;
} else {
// we reserve some amount of space for critical messages:
if (!is_critical && space < critical_message_reserved_space(_writebuf.get_size())) {
_dropped++;
return false;
}
}
// if no room for entire message - drop it:
if (space < size) {
_dropped++;
return false;
}
_writebuf.write((uint8_t*)pBuffer, size);
df_stats_gather(size, _writebuf.space());
return true;
}
/*
find the highest log number
*/
uint16_t AP_Logger_File::find_last_log()
{
unsigned ret = 0;
char *fname = _lastlog_file_name();
if (fname == nullptr) {
return ret;
}
EXPECT_DELAY_MS(3000);
FileData *fd = AP::FS().load_file(fname);
free(fname);
last_log_is_marked_discard = false;
if (fd != nullptr) {
char *endptr = nullptr;
ret = strtol((const char *)fd->data, &endptr, 10);
if (endptr != nullptr) {
last_log_is_marked_discard = *endptr == 'D';
}
delete fd;
}
return ret;
}
uint32_t AP_Logger_File::_get_log_size(const uint16_t log_num)
{
char *fname = _log_file_name(log_num);
if (fname == nullptr) {
return 0;
}
if (_write_fd != -1 && write_fd_semaphore.take_nonblocking()) {
if (_write_filename != nullptr && strcmp(_write_filename, fname) == 0) {
// it is the file we are currently writing
free(fname);
write_fd_semaphore.give();
return _write_offset;
}
write_fd_semaphore.give();
}
struct stat st;
EXPECT_DELAY_MS(3000);
if (AP::FS().stat(fname, &st) != 0) {
free(fname);
return 0;
}
free(fname);
return st.st_size;
}
uint32_t AP_Logger_File::_get_log_time(const uint16_t log_num)
{
char *fname = _log_file_name(log_num);
if (fname == nullptr) {
return 0;
}
if (_write_fd != -1 && write_fd_semaphore.take_nonblocking()) {
if (_write_filename != nullptr && strcmp(_write_filename, fname) == 0) {
// it is the file we are currently writing
free(fname);
write_fd_semaphore.give();
#if AP_RTC_ENABLED
uint64_t utc_usec;
if (!AP::rtc().get_utc_usec(utc_usec)) {
return 0;
}
return utc_usec / 1000000U;
#else
return 0;
#endif
}
write_fd_semaphore.give();
}
struct stat st;
EXPECT_DELAY_MS(3000);
if (AP::FS().stat(fname, &st) != 0) {
free(fname);
return 0;
}
free(fname);
return st.st_mtime;
}
/*
find the number of pages in a log
*/
void AP_Logger_File::get_log_boundaries(const uint16_t list_entry, uint32_t & start_page, uint32_t & end_page)
{
const uint16_t log_num = log_num_from_list_entry(list_entry);
if (log_num == 0) {
// that failed - probably no logs
start_page = 0;
end_page = 0;
return;
}
start_page = 0;
end_page = _get_log_size(log_num) / LOGGER_PAGE_SIZE;
}
/*
retrieve data from a log file
*/
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)
{
if (!_initialised || recent_open_error()) {
return -1;
}
const uint16_t log_num = log_num_from_list_entry(list_entry);
if (log_num == 0) {
// that failed - probably no logs
return -1;
}
if (_read_fd != -1 && log_num != _read_fd_log_num) {
AP::FS().close(_read_fd);
_read_fd = -1;
}
if (_read_fd == -1) {
char *fname = _log_file_name(log_num);
if (fname == nullptr) {
return -1;
}
stop_logging();
EXPECT_DELAY_MS(3000);
_read_fd = AP::FS().open(fname, O_RDONLY);
if (_read_fd == -1) {
_open_error_ms = AP_HAL::millis();
int saved_errno = errno;
::printf("Log read open fail for %s - %s\n",
fname, strerror(saved_errno));
DEV_PRINTF("Log read open fail for %s - %s\n",
fname, strerror(saved_errno));
free(fname);
return -1;
}
free(fname);
_read_offset = 0;
_read_fd_log_num = log_num;
}
uint32_t ofs = page * (uint32_t)LOGGER_PAGE_SIZE + offset;
if (ofs != _read_offset) {
if (AP::FS().lseek(_read_fd, ofs, SEEK_SET) == (off_t)-1) {
AP::FS().close(_read_fd);
_read_fd = -1;
return -1;
}
_read_offset = ofs;
}
int16_t ret = (int16_t)AP::FS().read(_read_fd, data, len);
if (ret > 0) {
_read_offset += ret;
}
return ret;
}
void AP_Logger_File::end_log_transfer()
{
if (_read_fd != -1) {
AP::FS().close(_read_fd);
_read_fd = -1;
}
}
/*
find size and date of a log
*/
void AP_Logger_File::get_log_info(const uint16_t list_entry, uint32_t &size, uint32_t &time_utc)
{
uint16_t log_num = log_num_from_list_entry(list_entry);
if (log_num == 0) {
// that failed - probably no logs
size = 0;
time_utc = 0;
return;
}
size = _get_log_size(log_num);
time_utc = _get_log_time(log_num);
}
/*
get the number of logs - note that the log numbers must be consecutive
*/
uint16_t AP_Logger_File::get_num_logs()
{
auto *d = AP::FS().opendir(_log_directory);
if (d == nullptr) {
return 0;
}
uint16_t high = find_last_log();
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;
}
if (thisnum > high && (smallest_above_last == 0 || thisnum < smallest_above_last)) {
smallest_above_last = thisnum;
}
}
AP::FS().closedir(d);
if (smallest_above_last != 0) {
// we have wrapped, add in the logs with high numbers
ret += (_front.get_max_num_logs() - smallest_above_last) + 1;
}
return ret;
}
/*
stop logging
*/
void AP_Logger_File::stop_logging(void)
{
// best-case effort to avoid annoying the IO thread
const bool have_sem = write_fd_semaphore.take(hal.util->get_soft_armed()?1:20);
if (_write_fd != -1) {
int fd = _write_fd;
_write_fd = -1;
AP::FS().close(fd);
}
if (have_sem) {
write_fd_semaphore.give();
}
}
/*
does start_new_log in the logger thread
*/
void AP_Logger_File::PrepForArming_start_logging()
{
if (logging_started()) {
return;
}
uint32_t start_ms = AP_HAL::millis();
const uint32_t open_limit_ms = 1000;
/*
log open happens in the io_timer thread. We allow for a maximum
of 1s to complete the open
*/
start_new_log_pending = true;
EXPECT_DELAY_MS(1000);
while (AP_HAL::millis() - start_ms < open_limit_ms) {
if (logging_started()) {
break;
}
#if !APM_BUILD_TYPE(APM_BUILD_Replay) && AP_AHRS_ENABLED
// keep the EKF ticking over
AP::ahrs().update();
#endif
hal.scheduler->delay(1);
}
}
/*
start writing to a new log file
*/
void AP_Logger_File::start_new_log(void)
{
if (recent_open_error()) {
// we have previously failed to open a file - don't try again
// to prevent us trying to open files while in flight
return;
}
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;
}
const bool open_error_ms_was_zero = (_open_error_ms == 0);
// set _open_error here to avoid infinite recursion. Simply
// writing a prioritised block may try to open a log - which means
// if anything in the start_new_log path does a GCS_SEND_TEXT()
// (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...
_open_error_ms = AP_HAL::millis();
stop_logging();
start_new_log_reset_variables();
if (_read_fd != -1) {
AP::FS().close(_read_fd);
_read_fd = -1;
}
if (disk_space_avail() < _free_space_min_avail && disk_space() > 0) {
DEV_PRINTF("Out of space for logging\n");
return;
}
uint16_t log_num = find_last_log();
// re-use empty logs if possible
if (_get_log_size(log_num) > 0 || log_num == 0) {
log_num++;
}
if (log_num > _front.get_max_num_logs()) {
log_num = 1;
}
if (!write_fd_semaphore.take(1)) {
return;
}
if (_write_filename) {
free(_write_filename);
_write_filename = nullptr;
}
_write_filename = _log_file_name(log_num);
if (_write_filename == nullptr) {
write_fd_semaphore.give();
return;
}
#if CONFIG_HAL_BOARD == HAL_BOARD_CHIBIOS
// remember if we had utc time when we opened the file
#if AP_RTC_ENABLED
uint64_t utc_usec;
_need_rtc_update = !AP::rtc().get_utc_usec(utc_usec);
#endif
#endif
// create the log directory if need be
ensure_log_directory_exists();
EXPECT_DELAY_MS(3000);
_write_fd = AP::FS().open(_write_filename, O_WRONLY|O_CREAT|O_TRUNC);
_cached_oldest_log = 0;
if (_write_fd == -1) {
write_fd_semaphore.give();
int saved_errno = errno;
if (open_error_ms_was_zero) {
::printf("Log open fail for %s - %s\n",
_write_filename, strerror(saved_errno));
DEV_PRINTF("Log open fail for %s - %s\n",
_write_filename, strerror(saved_errno));
}
return;
}
_last_write_ms = AP_HAL::millis();
_open_error_ms = 0;
_write_offset = 0;
_writebuf.clear();
write_fd_semaphore.give();
// 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)
{
// now update lastlog.txt with the new log number
char *fname = _lastlog_file_name();
EXPECT_DELAY_MS(3000);
int fd = AP::FS().open(fname, O_WRONLY|O_CREAT);
free(fname);
if (fd == -1) {
return false;
}
char buf[30];
snprintf(buf, sizeof(buf), "%u%s\r\n", (unsigned)log_num, last_log_is_marked_discard?"D":"");
const ssize_t to_write = strlen(buf);
const ssize_t written = AP::FS().write(fd, buf, to_write);
AP::FS().close(fd);
return written == to_write;
}
#if CONFIG_HAL_BOARD == HAL_BOARD_SITL || CONFIG_HAL_BOARD == HAL_BOARD_LINUX
void AP_Logger_File::flush(void)
#if APM_BUILD_TYPE(APM_BUILD_Replay) || APM_BUILD_TYPE(APM_BUILD_UNKNOWN)
{
uint32_t tnow = AP_HAL::millis();
while (_write_fd != -1 && _initialised && !recent_open_error() && _writebuf.available()) {
// convince the IO timer that it really is OK to write out
// less than _writebuf_chunk bytes:
if (tnow > 2001) { // avoid resetting _last_write_time to 0
_last_write_time = tnow - 2001;
}
io_timer();
}
if (write_fd_semaphore.take(1)) {
if (_write_fd != -1) {
::fsync(_write_fd);
}
write_fd_semaphore.give();
} else {
INTERNAL_ERROR(AP_InternalError::error_t::logger_flushing_without_sem);
}
}
#else
{
// flush is for replay and examples only
}
#endif // APM_BUILD_TYPE(APM_BUILD_Replay) || APM_BUILD_TYPE(APM_BUILD_UNKNOWN)
#endif
void AP_Logger_File::io_timer(void)
{
uint32_t tnow = AP_HAL::millis();
_io_timer_heartbeat = tnow;
if (start_new_log_pending) {
start_new_log();
start_new_log_pending = false;
}
if (erase.log_num != 0) {
// continue erase
erase_next();
return;
}
if (_write_fd == -1 || !_initialised || recent_open_error()) {
return;
}
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);
}
uint32_t nbytes = _writebuf.available();
if (nbytes == 0) {
return;
}
if (nbytes < _writebuf_chunk &&
tnow - _last_write_time < 2000UL) {
// write in _writebuf_chunk-sized chunks, but always write at
// least once per 2 seconds if data is available
return;
}
#if !AP_FILESYSTEM_LITTLEFS_ENABLED // too expensive on littlefs, rely on ENOSPC below
if (tnow - _free_space_last_check_time > _free_space_check_interval) {
_free_space_last_check_time = tnow;
last_io_operation = "disk_space_avail";
if (disk_space_avail() < _free_space_min_avail && disk_space() > 0) {
DEV_PRINTF("Out of space for logging\n");
stop_logging();
_open_error_ms = AP_HAL::millis(); // prevent logging starting again for 5s
last_io_operation = "";
return;
}
last_io_operation = "";
}
#endif
_last_write_time = tnow;
if (nbytes > _writebuf_chunk) {
// be kind to the filesystem layer
nbytes = _writebuf_chunk;
}
uint32_t size;
const uint8_t *head = _writebuf.readptr(size);
nbytes = MIN(nbytes, size);
#if !AP_FILESYSTEM_LITTLEFS_ENABLED
// try to align writes on a 512 byte boundary to avoid filesystem reads
if ((nbytes + _write_offset) % 512 != 0) {
uint32_t ofs = (nbytes + _write_offset) % 512;
if (ofs < nbytes) {
nbytes -= ofs;
}
}
#endif
last_io_operation = "write";
if (!write_fd_semaphore.take(1)) {
return;
}
if (_write_fd == -1) {
write_fd_semaphore.give();
return;
}
uint32_t bytes_until_fsync = AP::FS().bytes_until_fsync(_write_fd);
if (bytes_until_fsync > 0 && nbytes > bytes_until_fsync) {
nbytes = bytes_until_fsync; // write exactly enough to sync
}
ssize_t nwritten = AP::FS().write(_write_fd, head, nbytes);
last_io_operation = "";
if (nwritten <= 0) {
if (errno == ENOSPC) {
DEV_PRINTF("Out of space for logging\n");
stop_logging();
_open_error_ms = AP_HAL::millis(); // prevent logging starting again for 5s
last_io_operation = "";
} else 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
// the file. This allows us to cope with temporary write
// failures caused by directory listing
last_io_operation = "close";
AP::FS().close(_write_fd);
last_io_operation = "";
_write_fd = -1;
printf("Failed to write to File: %s\n", strerror(errno));
}
_last_write_failed = true;
} else {
_last_write_failed = false;
_last_write_ms = tnow;
_write_offset += nwritten;
_writebuf.advance(nwritten);
// we know nwritten > 0 so we won't sync if bytes_until_fsync == 0
if ((uint32_t)nwritten == bytes_until_fsync) {
last_io_operation = "fsync";
AP::FS().fsync(_write_fd);
last_io_operation = "";
}
#if AP_RTC_ENABLED && CONFIG_HAL_BOARD == HAL_BOARD_CHIBIOS
// 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)) {
AP::FS().set_mtime(_write_filename, utc_usec/(1000U*1000U));
_need_rtc_update = false;
}
}
#endif
}
write_fd_semaphore.give();
}
bool AP_Logger_File::io_thread_alive() const
{
if (!hal.scheduler->is_system_initialized()) {
// the system has long pauses during initialisation, assume still OK
return true;
}
// if the io thread hasn't had a heartbeat in a while then it is
#if CONFIG_HAL_BOARD == HAL_BOARD_ESP32
uint32_t timeout_ms = 10000;
#else
uint32_t timeout_ms = 5000;
#endif
#if CONFIG_HAL_BOARD == HAL_BOARD_SITL && !defined(HAL_BUILD_AP_PERIPH)
// 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.
SITL::SIM *sitl = AP::sitl();
if (sitl != nullptr) {
timeout_ms *= sitl->speedup;
}
#endif
return (AP_HAL::millis() - _io_timer_heartbeat) < timeout_ms;
}
bool AP_Logger_File::logging_failed() const
{
if (!_initialised) {
return true;
}
if (recent_open_error()) {
return true;
}
if (!io_thread_alive()) {
// No heartbeat in a second. IO thread is dead?! Very Not
// Good.
return true;
}
if (_last_write_failed) {
return true;
}
return false;
}
/*
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++;
if (erase.log_num <= _front.get_max_num_logs()) {
return;
}
fname = _lastlog_file_name();
if (fname != nullptr) {
AP::FS().unlink(fname);
free(fname);
}
_cached_oldest_log = 0;
erase.log_num = 0;
}
#endif // HAL_LOGGING_FILESYSTEM_ENABLED
Reference in New Issue View Git Blame Copy Permalink