Line data Source code
1 : /*
2 : AP_Logger logging - file oriented variant
3 :
4 : This uses posix file IO to create log files called logs/NN.bin in the
5 : given directory
6 :
7 : SD Card Rates on PixHawk:
8 : - deletion rate seems to be ~50 files/second.
9 : - stat seems to be ~150/second
10 : - readdir loop of 511 entry directory ~62,000 microseconds
11 : */
12 :
13 : #include "AP_Logger_config.h"
14 :
15 : #if HAL_LOGGING_FILESYSTEM_ENABLED
16 :
17 : #include <AP_HAL/AP_HAL.h>
18 : #include <AP_Filesystem/AP_Filesystem.h>
19 : #if AP_FILESYSTEM_LITTLEFS_ENABLED
20 : #include <AP_Filesystem/AP_Filesystem_FlashMemory_LittleFS.h>
21 : #endif
22 :
23 : #include "AP_Logger.h"
24 : #include "AP_Logger_File.h"
25 :
26 : #include <AP_Common/AP_Common.h>
27 : #include <AP_InternalError/AP_InternalError.h>
28 : #include <AP_RTC/AP_RTC.h>
29 : #include <AP_Vehicle/AP_Vehicle_Type.h>
30 : #include <AP_AHRS/AP_AHRS.h>
31 :
32 : #include <AP_Math/AP_Math.h>
33 : #include <GCS_MAVLink/GCS.h>
34 : #include <stdio.h>
35 :
36 :
37 : extern const AP_HAL::HAL& hal;
38 :
39 : #define LOGGER_PAGE_SIZE 1024UL
40 :
41 : #define MB_to_B 1000000
42 : #define B_to_MB 0.000001
43 :
44 : // time between tries to open log
45 : #define LOGGER_FILE_REOPEN_MS 5000
46 :
47 : /*
48 : constructor
49 : */
50 2088 : AP_Logger_File::AP_Logger_File(AP_Logger &front,
51 2088 : LoggerMessageWriter_DFLogStart *writer) :
52 : AP_Logger_Backend(front, writer),
53 2088 : _log_directory(HAL_BOARD_LOG_DIRECTORY)
54 : {
55 2088 : df_stats_clear();
56 2088 : }
57 :
58 :
59 2063 : void AP_Logger_File::ensure_log_directory_exists()
60 : {
61 : int ret;
62 : struct stat st;
63 :
64 2063 : EXPECT_DELAY_MS(3000);
65 2063 : ret = AP::FS().stat(_log_directory, &st);
66 2063 : if (ret == -1) {
67 1 : ret = AP::FS().mkdir(_log_directory);
68 : }
69 2063 : if (ret == -1 && errno != EEXIST) {
70 0 : GCS_SEND_TEXT(MAV_SEVERITY_WARNING, "Failed to create log directory %s : %s", _log_directory, strerror(errno));
71 : }
72 2063 : }
73 :
74 2088 : void AP_Logger_File::Init()
75 : {
76 : // determine and limit file backend buffersize
77 2088 : uint32_t bufsize = _front._params.file_bufsize;
78 2088 : bufsize *= 1024;
79 :
80 2088 : const uint32_t desired_bufsize = bufsize;
81 :
82 : // If we can't allocate the full size, try to reduce it until we can allocate it
83 2088 : while (!_writebuf.set_size(bufsize) && bufsize >= _writebuf_chunk) {
84 0 : bufsize *= 0.9;
85 : }
86 2088 : if (bufsize >= _writebuf_chunk && bufsize != desired_bufsize) {
87 0 : DEV_PRINTF("AP_Logger: reduced buffer %u/%u\n", (unsigned)bufsize, (unsigned)desired_bufsize);
88 : }
89 :
90 2088 : if (!_writebuf.get_size()) {
91 0 : DEV_PRINTF("Out of memory for logging\n");
92 0 : return;
93 : }
94 :
95 2088 : DEV_PRINTF("AP_Logger_File: buffer size=%u\n", (unsigned)bufsize);
96 :
97 2088 : _initialised = true;
98 :
99 2088 : const char* custom_dir = hal.util->get_custom_log_directory();
100 2088 : if (custom_dir != nullptr){
101 0 : _log_directory = custom_dir;
102 : }
103 :
104 2088 : uint16_t last_log_num = find_last_log();
105 2088 : if (last_log_is_marked_discard) {
106 : // delete the last log leftover from LOG_DISARMED=3
107 0 : char *filename = _log_file_name(last_log_num);
108 0 : if (filename != nullptr) {
109 0 : AP::FS().unlink(filename);
110 0 : free(filename);
111 : }
112 : }
113 :
114 2088 : Prep_MinSpace();
115 : }
116 :
117 0 : bool AP_Logger_File::file_exists(const char *filename) const
118 : {
119 : struct stat st;
120 0 : EXPECT_DELAY_MS(3000);
121 0 : if (AP::FS().stat(filename, &st) == -1) {
122 : // hopefully errno==ENOENT. If some error occurs it is
123 : // probably better to assume this file exists.
124 0 : return false;
125 : }
126 0 : return true;
127 0 : }
128 :
129 0 : bool AP_Logger_File::log_exists(const uint16_t lognum) const
130 : {
131 0 : char *filename = _log_file_name(lognum);
132 0 : if (filename == nullptr) {
133 0 : return false; // ?!
134 : }
135 0 : bool ret = file_exists(filename);
136 0 : free(filename);
137 0 : return ret;
138 : }
139 :
140 149912 : void AP_Logger_File::periodic_1Hz()
141 : {
142 149912 : AP_Logger_Backend::periodic_1Hz();
143 :
144 149912 : if (_initialised &&
145 149912 : _write_fd == -1 && _read_fd == -1 &&
146 8003 : erase.log_num == 0 &&
147 8003 : erase.was_logging) {
148 : // restart logging after an erase if needed
149 0 : erase.was_logging = false;
150 : // setup to open the log in the backend thread
151 0 : start_new_log_pending = true;
152 : }
153 :
154 449736 : if (_initialised &&
155 149912 : !start_new_log_pending &&
156 157915 : _write_fd == -1 && _read_fd == -1 &&
157 307827 : logging_enabled() &&
158 1884 : !recent_open_error()) {
159 : // setup to open the log in the backend thread
160 1884 : start_new_log_pending = true;
161 : }
162 :
163 149912 : if (!io_thread_alive()) {
164 0 : if (io_thread_warning_decimation_counter == 0 && _initialised) {
165 : // we don't print this error unless we did initialise. When _initialised is set to true
166 : // we register the IO timer callback
167 0 : GCS_SEND_TEXT(MAV_SEVERITY_CRITICAL, "AP_Logger: stuck thread (%s)", last_io_operation);
168 : }
169 0 : if (io_thread_warning_decimation_counter++ > 30) {
170 0 : io_thread_warning_decimation_counter = 0;
171 : }
172 : }
173 :
174 168606 : if (rate_limiter == nullptr &&
175 18694 : (_front._params.file_ratemax > 0 ||
176 16866 : _front._params.disarm_ratemax > 0 ||
177 16865 : _front._log_pause)) {
178 : // setup rate limiting if log rate max > 0Hz or log pause of streaming entries is requested
179 1829 : rate_limiter = NEW_NOTHROW AP_Logger_RateLimiter(_front, _front._params.file_ratemax, _front._params.disarm_ratemax);
180 : }
181 149912 : }
182 :
183 41565342 : void AP_Logger_File::periodic_fullrate()
184 : {
185 41565342 : AP_Logger_Backend::push_log_blocks();
186 41565342 : }
187 :
188 85162434 : uint32_t AP_Logger_File::bufferspace_available()
189 : {
190 85162434 : const uint32_t space = _writebuf.space();
191 85162407 : const uint32_t crit = critical_message_reserved_space(_writebuf.get_size());
192 :
193 85162370 : return (space > crit) ? space - crit : 0;
194 : }
195 :
196 573849533 : bool AP_Logger_File::recent_open_error(void) const
197 : {
198 573849533 : if (_open_error_ms == 0) {
199 573850724 : return false;
200 : }
201 794 : return AP_HAL::millis() - _open_error_ms < LOGGER_FILE_REOPEN_MS;
202 : }
203 :
204 : // return true for CardInserted() if we successfully initialized
205 134609 : bool AP_Logger_File::CardInserted(void) const
206 : {
207 134609 : return _initialised && !recent_open_error();
208 : }
209 :
210 : // returns the amount of disk space available in _log_directory (in bytes)
211 : // returns -1 on error
212 135293 : int64_t AP_Logger_File::disk_space_avail()
213 : {
214 135293 : return AP::FS().disk_free(_log_directory);
215 : }
216 :
217 : // returns the total amount of disk space (in use + available) in
218 : // _log_directory (in bytes).
219 : // returns -1 on error
220 1 : int64_t AP_Logger_File::disk_space()
221 : {
222 1 : return AP::FS().disk_space(_log_directory);
223 : }
224 :
225 : /*
226 : convert a dirent to a log number
227 : */
228 1552205 : bool AP_Logger_File::dirent_to_log_num(const dirent *de, uint16_t &log_num) const
229 : {
230 1552205 : uint8_t length = strlen(de->d_name);
231 1552205 : if (length < 5) {
232 40818 : return false;
233 : }
234 1511387 : if (strncmp(&de->d_name[length-4], ".BIN", 4) != 0) {
235 : // doesn't end in .BIN
236 20409 : return false;
237 : }
238 :
239 1490978 : uint16_t thisnum = strtoul(de->d_name, nullptr, 10);
240 1490978 : if (thisnum > _front.get_max_num_logs()) {
241 1000 : return false;
242 : }
243 1489978 : log_num = thisnum;
244 1489978 : return true;
245 : }
246 :
247 :
248 : // find_oldest_log - find oldest log in _log_directory
249 : // returns 0 if no log was found
250 334021 : uint16_t AP_Logger_File::find_oldest_log()
251 : {
252 334021 : if (_cached_oldest_log != 0) {
253 331838 : return _cached_oldest_log;
254 : }
255 :
256 2183 : uint16_t last_log_num = find_last_log();
257 2183 : if (last_log_num == 0) {
258 12 : return 0;
259 : }
260 :
261 2171 : uint16_t current_oldest_log = 0; // 0 is invalid
262 :
263 : // We could count up to find_last_log(), but if people start
264 : // relying on the min_avail_space_percent feature we could end up
265 : // doing a *lot* of asprintf()s and stat()s
266 2171 : EXPECT_DELAY_MS(3000);
267 2171 : auto *d = AP::FS().opendir(_log_directory);
268 2171 : if (d == nullptr) {
269 : // SD card may have died? On linux someone may have rm-rf-d
270 0 : return 0;
271 : }
272 :
273 : // we only remove files which look like xxx.BIN
274 2171 : EXPECT_DELAY_MS(3000);
275 525685 : for (struct dirent *de=AP::FS().readdir(d); de; de=AP::FS().readdir(d)) {
276 523514 : EXPECT_DELAY_MS(3000);
277 : uint16_t thisnum;
278 523514 : if (!dirent_to_log_num(de, thisnum)) {
279 : // not a log filename
280 7013 : continue;
281 : }
282 516501 : if (current_oldest_log == 0) {
283 2495 : current_oldest_log = thisnum;
284 : } else {
285 514006 : if (current_oldest_log <= last_log_num) {
286 314190 : if (thisnum > last_log_num) {
287 224 : current_oldest_log = thisnum;
288 313966 : } else if (thisnum < current_oldest_log) {
289 11038 : current_oldest_log = thisnum;
290 : }
291 : } else { // current_oldest_log > last_log_num
292 199816 : if (thisnum > last_log_num) {
293 130017 : if (thisnum < current_oldest_log) {
294 1740 : current_oldest_log = thisnum;
295 : }
296 : }
297 : }
298 : }
299 523514 : }
300 2171 : AP::FS().closedir(d);
301 2171 : _cached_oldest_log = current_oldest_log;
302 :
303 2171 : return current_oldest_log;
304 2171 : }
305 :
306 2088 : void AP_Logger_File::Prep_MinSpace()
307 : {
308 2088 : if (hal.util->was_watchdog_reset()) {
309 : // don't clear space if watchdog reset, it takes too long
310 1 : return;
311 : }
312 :
313 2087 : if (!CardInserted()) {
314 0 : return;
315 : }
316 :
317 2087 : const uint16_t first_log_to_remove = find_oldest_log();
318 2087 : if (first_log_to_remove == 0) {
319 : // no files to remove
320 12 : return;
321 : }
322 :
323 2075 : const int64_t target_free = (int64_t)_front._params.min_MB_free * MB_to_B;
324 :
325 2075 : uint16_t log_to_remove = first_log_to_remove;
326 :
327 2075 : uint16_t count = 0;
328 : do {
329 2075 : int64_t avail = disk_space_avail();
330 2075 : if (avail == -1) {
331 0 : break;
332 : }
333 2075 : if (avail >= target_free) {
334 2075 : break;
335 : }
336 0 : if (count++ > _front.get_max_num_logs() + 10) {
337 : // *way* too many deletions going on here. Possible internal error.
338 0 : INTERNAL_ERROR(AP_InternalError::error_t::logger_too_many_deletions);
339 0 : break;
340 : }
341 0 : char *filename_to_remove = _log_file_name(log_to_remove);
342 0 : if (filename_to_remove == nullptr) {
343 0 : INTERNAL_ERROR(AP_InternalError::error_t::logger_bad_getfilename);
344 0 : break;
345 : }
346 0 : if (file_exists(filename_to_remove)) {
347 0 : DEV_PRINTF("Removing (%s) for minimum-space requirements (%.0fMB < %.0fMB)\n",
348 : filename_to_remove, (double)avail*B_to_MB, (double)target_free*B_to_MB);
349 0 : EXPECT_DELAY_MS(2000);
350 0 : if (AP::FS().unlink(filename_to_remove) == -1) {
351 0 : _cached_oldest_log = 0;
352 0 : DEV_PRINTF("Failed to remove %s: %s\n", filename_to_remove, strerror(errno));
353 0 : free(filename_to_remove);
354 0 : if (errno == ENOENT) {
355 : // corruption - should always have a continuous
356 : // sequence of files... however, there may be still
357 : // files out there, so keep going.
358 : } else {
359 0 : break;
360 : }
361 : } else {
362 0 : free(filename_to_remove);
363 : }
364 0 : }
365 0 : log_to_remove++;
366 0 : if (log_to_remove > _front.get_max_num_logs()) {
367 0 : log_to_remove = 1;
368 : }
369 0 : } while (log_to_remove != first_log_to_remove);
370 : }
371 :
372 : /*
373 : construct a log file name given a log number.
374 : The number in the log filename will be zero-padded.
375 : Note: Caller must free.
376 : */
377 83865 : char *AP_Logger_File::_log_file_name(const uint16_t log_num) const
378 : {
379 83865 : char *buf = nullptr;
380 83865 : if (asprintf(&buf, "%s/%08u.BIN", _log_directory, (unsigned)log_num) == -1) {
381 0 : return nullptr;
382 : }
383 83866 : return buf;
384 : }
385 :
386 : /*
387 : return path name of the lastlog.txt marker file
388 : Note: Caller must free.
389 : */
390 26635 : char *AP_Logger_File::_lastlog_file_name(void) const
391 : {
392 26635 : char *buf = nullptr;
393 26635 : if (asprintf(&buf, "%s/LASTLOG.TXT", _log_directory) == -1) {
394 0 : return nullptr;
395 : }
396 26635 : return buf;
397 : }
398 :
399 :
400 : // remove all log files
401 0 : void AP_Logger_File::EraseAll()
402 : {
403 0 : if (hal.util->get_soft_armed()) {
404 : // do not want to do any filesystem operations while we are e.g. flying
405 0 : return;
406 : }
407 0 : if (!_initialised) {
408 0 : return;
409 : }
410 :
411 0 : erase.was_logging = (_write_fd != -1);
412 0 : stop_logging();
413 :
414 0 : erase.log_num = 1;
415 : }
416 :
417 261508208 : bool AP_Logger_File::WritesOK() const
418 : {
419 261508208 : if (_write_fd == -1) {
420 403367 : return false;
421 : }
422 261104841 : if (recent_open_error()) {
423 1 : return false;
424 : }
425 261104938 : return true;
426 : }
427 :
428 :
429 261508426 : bool AP_Logger_File::StartNewLogOK() const
430 : {
431 261508426 : if (recent_open_error()) {
432 6358 : return false;
433 : }
434 : #if !APM_BUILD_TYPE(APM_BUILD_Replay) && !APM_BUILD_TYPE(APM_BUILD_UNKNOWN)
435 261502025 : if (hal.scheduler->in_main_thread()) {
436 260515258 : return false;
437 : }
438 : #endif
439 986795 : return AP_Logger_Backend::StartNewLogOK();
440 : }
441 :
442 : /* Write a block of data at current offset */
443 98712627 : bool AP_Logger_File::_WritePrioritisedBlock(const void *pBuffer, uint16_t size, bool is_critical)
444 : {
445 98712627 : WITH_SEMAPHORE(semaphore);
446 :
447 : #if APM_BUILD_TYPE(APM_BUILD_Replay)
448 : if (AP::FS().write(_write_fd, pBuffer, size) != size) {
449 : AP_HAL::panic("Short write");
450 : }
451 : return true;
452 : #endif
453 :
454 :
455 98712863 : uint32_t space = _writebuf.space();
456 :
457 102493697 : if (_writing_startup_messages &&
458 3780834 : _startup_messagewriter->fmt_done()) {
459 : // the state machine has called us, and it has finished
460 : // writing format messages out. It can always get back to us
461 : // with more messages later, so let's leave room for other
462 : // things:
463 3413963 : const uint32_t now = AP_HAL::millis();
464 3413963 : const bool must_dribble = (now - last_messagewrite_message_sent) > 100;
465 6824439 : if (!must_dribble &&
466 3410476 : space < non_messagewriter_message_reserved_space(_writebuf.get_size())) {
467 : // this message isn't dropped, it will be sent again...
468 6 : return false;
469 : }
470 3413957 : last_messagewrite_message_sent = now;
471 : } else {
472 : // we reserve some amount of space for critical messages:
473 95298900 : if (!is_critical && space < critical_message_reserved_space(_writebuf.get_size())) {
474 151 : _dropped++;
475 151 : return false;
476 : }
477 : }
478 :
479 : // if no room for entire message - drop it:
480 98712706 : if (space < size) {
481 378 : _dropped++;
482 378 : return false;
483 : }
484 :
485 98712328 : _writebuf.write((uint8_t*)pBuffer, size);
486 98712328 : df_stats_gather(size, _writebuf.space());
487 98712328 : return true;
488 98712863 : }
489 :
490 : /*
491 : find the highest log number
492 : */
493 24572 : uint16_t AP_Logger_File::find_last_log()
494 : {
495 24572 : unsigned ret = 0;
496 24572 : char *fname = _lastlog_file_name();
497 24572 : if (fname == nullptr) {
498 0 : return ret;
499 : }
500 24572 : EXPECT_DELAY_MS(3000);
501 24572 : FileData *fd = AP::FS().load_file(fname);
502 24572 : free(fname);
503 24572 : last_log_is_marked_discard = false;
504 24572 : if (fd != nullptr) {
505 24538 : char *endptr = nullptr;
506 24538 : ret = strtol((const char *)fd->data, &endptr, 10);
507 24538 : if (endptr != nullptr) {
508 24538 : last_log_is_marked_discard = *endptr == 'D';
509 : }
510 24538 : delete fd;
511 : }
512 24572 : return ret;
513 24572 : }
514 :
515 41933 : uint32_t AP_Logger_File::_get_log_size(const uint16_t log_num)
516 : {
517 41933 : char *fname = _log_file_name(log_num);
518 41933 : if (fname == nullptr) {
519 0 : return 0;
520 : }
521 41933 : if (_write_fd != -1 && write_fd_semaphore.take_nonblocking()) {
522 1886 : if (_write_filename != nullptr && strcmp(_write_filename, fname) == 0) {
523 : // it is the file we are currently writing
524 20 : free(fname);
525 20 : write_fd_semaphore.give();
526 20 : return _write_offset;
527 : }
528 1866 : write_fd_semaphore.give();
529 : }
530 : struct stat st;
531 41913 : EXPECT_DELAY_MS(3000);
532 41913 : if (AP::FS().stat(fname, &st) != 0) {
533 10 : free(fname);
534 10 : return 0;
535 : }
536 41903 : free(fname);
537 41903 : return st.st_size;
538 41913 : }
539 :
540 21660 : uint32_t AP_Logger_File::_get_log_time(const uint16_t log_num)
541 : {
542 21660 : char *fname = _log_file_name(log_num);
543 21660 : if (fname == nullptr) {
544 0 : return 0;
545 : }
546 21660 : if (_write_fd != -1 && write_fd_semaphore.take_nonblocking()) {
547 1809 : if (_write_filename != nullptr && strcmp(_write_filename, fname) == 0) {
548 : // it is the file we are currently writing
549 16 : free(fname);
550 16 : write_fd_semaphore.give();
551 : #if AP_RTC_ENABLED
552 : uint64_t utc_usec;
553 16 : if (!AP::rtc().get_utc_usec(utc_usec)) {
554 1 : return 0;
555 : }
556 15 : return utc_usec / 1000000U;
557 : #else
558 : return 0;
559 : #endif
560 : }
561 1793 : write_fd_semaphore.give();
562 : }
563 : struct stat st;
564 21644 : EXPECT_DELAY_MS(3000);
565 21644 : if (AP::FS().stat(fname, &st) != 0) {
566 0 : free(fname);
567 0 : return 0;
568 : }
569 21644 : free(fname);
570 21644 : return st.st_mtime;
571 21644 : }
572 :
573 : /*
574 : find the number of pages in a log
575 : */
576 18210 : void AP_Logger_File::get_log_boundaries(const uint16_t list_entry, uint32_t & start_page, uint32_t & end_page)
577 : {
578 18210 : const uint16_t log_num = log_num_from_list_entry(list_entry);
579 18210 : if (log_num == 0) {
580 : // that failed - probably no logs
581 0 : start_page = 0;
582 0 : end_page = 0;
583 0 : return;
584 : }
585 :
586 18210 : start_page = 0;
587 18210 : end_page = _get_log_size(log_num) / LOGGER_PAGE_SIZE;
588 : }
589 :
590 : /*
591 : retrieve data from a log file
592 : */
593 292064 : 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)
594 : {
595 292064 : if (!_initialised) {
596 0 : return -1;
597 : }
598 :
599 292064 : const uint16_t log_num = log_num_from_list_entry(list_entry);
600 292064 : if (log_num == 0) {
601 : // that failed - probably no logs
602 0 : return -1;
603 : }
604 :
605 292064 : if (_read_fd != -1 && log_num != _read_fd_log_num) {
606 0 : AP::FS().close(_read_fd);
607 0 : _read_fd = -1;
608 : }
609 292064 : if (_read_fd == -1) {
610 18210 : char *fname = _log_file_name(log_num);
611 18210 : if (fname == nullptr) {
612 0 : return -1;
613 : }
614 18210 : stop_logging();
615 18210 : EXPECT_DELAY_MS(3000);
616 18210 : _read_fd = AP::FS().open(fname, O_RDONLY);
617 18210 : if (_read_fd == -1) {
618 0 : const int saved_errno = errno;
619 0 : if (saved_errno != ENOENT) {
620 0 : _open_error_ms = AP_HAL::millis();
621 : }
622 0 : ::printf("Log read open fail for %s - %s\n",
623 : fname, strerror(saved_errno));
624 0 : DEV_PRINTF("Log read open fail for %s - %s\n",
625 : fname, strerror(saved_errno));
626 0 : free(fname);
627 0 : return -1;
628 : }
629 18210 : free(fname);
630 18210 : _read_offset = 0;
631 18210 : _read_fd_log_num = log_num;
632 18210 : }
633 292064 : uint32_t ofs = page * (uint32_t)LOGGER_PAGE_SIZE + offset;
634 :
635 292064 : if (ofs != _read_offset) {
636 18199 : if (AP::FS().lseek(_read_fd, ofs, SEEK_SET) == (off_t)-1) {
637 0 : AP::FS().close(_read_fd);
638 0 : _read_fd = -1;
639 0 : return -1;
640 : }
641 18199 : _read_offset = ofs;
642 : }
643 292064 : int16_t ret = (int16_t)AP::FS().read(_read_fd, data, len);
644 292064 : if (ret > 0) {
645 292061 : _read_offset += ret;
646 : }
647 292064 : return ret;
648 : }
649 :
650 18217 : void AP_Logger_File::end_log_transfer()
651 : {
652 18217 : if (_read_fd != -1) {
653 18210 : AP::FS().close(_read_fd);
654 18210 : _read_fd = -1;
655 : }
656 18217 : }
657 :
658 : /*
659 : find size and date of a log
660 : */
661 21660 : void AP_Logger_File::get_log_info(const uint16_t list_entry, uint32_t &size, uint32_t &time_utc)
662 : {
663 21660 : uint16_t log_num = log_num_from_list_entry(list_entry);
664 21660 : if (log_num == 0) {
665 : // that failed - probably no logs
666 0 : size = 0;
667 0 : time_utc = 0;
668 0 : return;
669 : }
670 :
671 21660 : size = _get_log_size(log_num);
672 21660 : time_utc = _get_log_time(log_num);
673 : }
674 :
675 :
676 : /*
677 : get the number of logs - note that the log numbers must be consecutive
678 : */
679 18238 : uint16_t AP_Logger_File::get_num_logs()
680 : {
681 18238 : auto *d = AP::FS().opendir(_log_directory);
682 18238 : if (d == nullptr) {
683 0 : return 0;
684 : }
685 18238 : uint16_t high = find_last_log();
686 18238 : uint16_t ret = high;
687 18238 : uint16_t smallest_above_last = 0;
688 :
689 18238 : EXPECT_DELAY_MS(2000);
690 1046929 : for (struct dirent *de=AP::FS().readdir(d); de; de=AP::FS().readdir(d)) {
691 1028691 : EXPECT_DELAY_MS(100);
692 : uint16_t thisnum;
693 1028691 : if (!dirent_to_log_num(de, thisnum)) {
694 : // not a log filename
695 55214 : continue;
696 : }
697 :
698 973477 : if (thisnum > high && (smallest_above_last == 0 || thisnum < smallest_above_last)) {
699 30 : smallest_above_last = thisnum;
700 : }
701 1028691 : }
702 18238 : AP::FS().closedir(d);
703 18238 : if (smallest_above_last != 0) {
704 : // we have wrapped, add in the logs with high numbers
705 6 : ret += (_front.get_max_num_logs() - smallest_above_last) + 1;
706 : }
707 :
708 18238 : return ret;
709 18238 : }
710 :
711 : /*
712 : stop logging
713 : */
714 20322 : void AP_Logger_File::stop_logging(void)
715 : {
716 : // best-case effort to avoid annoying the IO thread
717 20322 : const bool have_sem = write_fd_semaphore.take(hal.util->get_soft_armed()?1:20);
718 20322 : if (_write_fd != -1) {
719 137 : int fd = _write_fd;
720 137 : _write_fd = -1;
721 137 : AP::FS().close(fd);
722 : }
723 20322 : if (have_sem) {
724 20322 : write_fd_semaphore.give();
725 : }
726 20322 : }
727 :
728 : /*
729 : does start_new_log in the logger thread
730 : */
731 179 : void AP_Logger_File::PrepForArming_start_logging()
732 : {
733 179 : if (logging_started()) {
734 0 : return;
735 : }
736 :
737 179 : uint32_t start_ms = AP_HAL::millis();
738 179 : const uint32_t open_limit_ms = 1000;
739 :
740 : /*
741 : log open happens in the io_timer thread. We allow for a maximum
742 : of 1s to complete the open
743 : */
744 179 : start_new_log_pending = true;
745 179 : EXPECT_DELAY_MS(1000);
746 642 : while (AP_HAL::millis() - start_ms < open_limit_ms) {
747 642 : if (logging_started()) {
748 179 : break;
749 : }
750 : #if !APM_BUILD_TYPE(APM_BUILD_Replay) && AP_AHRS_ENABLED
751 : // keep the EKF ticking over
752 463 : AP::ahrs().update();
753 : #endif
754 463 : hal.scheduler->delay(1);
755 : }
756 179 : }
757 :
758 : /*
759 : start writing to a new log file
760 : */
761 2063 : void AP_Logger_File::start_new_log(void)
762 : {
763 2063 : if (recent_open_error()) {
764 : // we have previously failed to open a file - don't try again
765 : // to prevent us trying to open files while in flight
766 0 : return;
767 : }
768 :
769 2063 : if (erase.log_num != 0) {
770 : // don't start a new log while erasing, but record that we
771 : // want to start logging when erase finished
772 0 : erase.was_logging = true;
773 0 : return;
774 : }
775 :
776 2063 : const bool open_error_ms_was_zero = (_open_error_ms == 0);
777 :
778 : // set _open_error here to avoid infinite recursion. Simply
779 : // writing a prioritised block may try to open a log - which means
780 : // if anything in the start_new_log path does a GCS_SEND_TEXT()
781 : // (for example), you will end up recursing if we don't take
782 : // precautions. We will reset _open_error if we actually manage
783 : // to open the log...
784 2063 : _open_error_ms = AP_HAL::millis();
785 :
786 2063 : stop_logging();
787 :
788 2063 : start_new_log_reset_variables();
789 :
790 2063 : if (_read_fd != -1) {
791 0 : AP::FS().close(_read_fd);
792 0 : _read_fd = -1;
793 : }
794 :
795 2063 : if (disk_space_avail() < _free_space_min_avail && disk_space() > 0) {
796 0 : DEV_PRINTF("Out of space for logging\n");
797 0 : return;
798 : }
799 :
800 2063 : uint16_t log_num = find_last_log();
801 : // re-use empty logs if possible
802 2063 : if (_get_log_size(log_num) > 0 || log_num == 0) {
803 2001 : log_num++;
804 : }
805 2063 : if (log_num > _front.get_max_num_logs()) {
806 6 : log_num = 1;
807 : }
808 2063 : if (!write_fd_semaphore.take(1)) {
809 0 : return;
810 : }
811 2063 : if (_write_filename) {
812 130 : free(_write_filename);
813 130 : _write_filename = nullptr;
814 : }
815 2063 : _write_filename = _log_file_name(log_num);
816 2063 : if (_write_filename == nullptr) {
817 0 : write_fd_semaphore.give();
818 0 : return;
819 : }
820 :
821 : #if CONFIG_HAL_BOARD == HAL_BOARD_CHIBIOS
822 : // remember if we had utc time when we opened the file
823 : #if AP_RTC_ENABLED
824 : uint64_t utc_usec;
825 : _need_rtc_update = !AP::rtc().get_utc_usec(utc_usec);
826 : #endif
827 : #endif
828 :
829 : // create the log directory if need be
830 2063 : ensure_log_directory_exists();
831 :
832 2063 : EXPECT_DELAY_MS(3000);
833 2063 : _writebuf.clear();
834 2063 : _write_fd = AP::FS().open(_write_filename, O_WRONLY|O_CREAT|O_TRUNC);
835 2063 : _cached_oldest_log = 0;
836 :
837 2063 : if (_write_fd == -1) {
838 0 : write_fd_semaphore.give();
839 0 : int saved_errno = errno;
840 0 : if (open_error_ms_was_zero) {
841 0 : ::printf("Log open fail for %s - %s\n",
842 : _write_filename, strerror(saved_errno));
843 0 : DEV_PRINTF("Log open fail for %s - %s\n",
844 : _write_filename, strerror(saved_errno));
845 : }
846 0 : return;
847 : }
848 2063 : _last_write_ms = AP_HAL::millis();
849 2063 : _open_error_ms = 0;
850 2063 : _write_offset = 0;
851 2063 : write_fd_semaphore.give();
852 :
853 : // now update lastlog.txt with the new log number
854 2063 : last_log_is_marked_discard = _front._params.log_disarmed == AP_Logger::LogDisarmed::LOG_WHILE_DISARMED_DISCARD;
855 2063 : if (!write_lastlog_file(log_num)) {
856 0 : _open_error_ms = AP_HAL::millis();
857 : }
858 2063 : }
859 :
860 : /*
861 : write LASTLOG.TXT, possibly with a discard marker
862 : */
863 2063 : bool AP_Logger_File::write_lastlog_file(uint16_t log_num)
864 : {
865 : // now update lastlog.txt with the new log number
866 2063 : char *fname = _lastlog_file_name();
867 :
868 2063 : EXPECT_DELAY_MS(3000);
869 2063 : int fd = AP::FS().open(fname, O_WRONLY|O_CREAT);
870 2063 : free(fname);
871 2063 : if (fd == -1) {
872 0 : return false;
873 : }
874 :
875 : char buf[30];
876 2063 : snprintf(buf, sizeof(buf), "%u%s\r\n", (unsigned)log_num, last_log_is_marked_discard?"D":"");
877 2063 : const ssize_t to_write = strlen(buf);
878 2063 : const ssize_t written = AP::FS().write(fd, buf, to_write);
879 2063 : AP::FS().close(fd);
880 2063 : return written == to_write;
881 2063 : }
882 :
883 : #if CONFIG_HAL_BOARD == HAL_BOARD_SITL || CONFIG_HAL_BOARD == HAL_BOARD_LINUX
884 0 : void AP_Logger_File::flush(void)
885 : #if APM_BUILD_TYPE(APM_BUILD_Replay) || APM_BUILD_TYPE(APM_BUILD_UNKNOWN)
886 : {
887 0 : uint32_t tnow = AP_HAL::millis();
888 0 : while (_write_fd != -1 && _initialised && !recent_open_error() && _writebuf.available()) {
889 : // convince the IO timer that it really is OK to write out
890 : // less than _writebuf_chunk bytes:
891 0 : if (tnow > 2001) { // avoid resetting _last_write_time to 0
892 0 : _last_write_time = tnow - 2001;
893 : }
894 0 : io_timer();
895 : }
896 0 : if (write_fd_semaphore.take(1)) {
897 0 : if (_write_fd != -1) {
898 0 : ::fsync(_write_fd);
899 : }
900 0 : write_fd_semaphore.give();
901 : } else {
902 0 : INTERNAL_ERROR(AP_InternalError::error_t::logger_flushing_without_sem);
903 : }
904 0 : }
905 : #else
906 : {
907 : // flush is for replay and examples only
908 0 : }
909 : #endif // APM_BUILD_TYPE(APM_BUILD_Replay) || APM_BUILD_TYPE(APM_BUILD_UNKNOWN)
910 : #endif
911 :
912 52836791 : void AP_Logger_File::io_timer(void)
913 : {
914 52836791 : uint32_t tnow = AP_HAL::millis();
915 52836791 : _io_timer_heartbeat = tnow;
916 :
917 52836791 : if (start_new_log_pending) {
918 2063 : start_new_log();
919 2063 : start_new_log_pending = false;
920 : }
921 :
922 52836791 : if (erase.log_num != 0) {
923 : // continue erase
924 0 : erase_next();
925 51810763 : return;
926 : }
927 :
928 52836791 : if (_write_fd == -1 || !_initialised || recent_open_error()) {
929 2956876 : return;
930 : }
931 :
932 49879915 : if (last_log_is_marked_discard && hal.util->get_soft_armed()) {
933 : // time to make the log permanent
934 0 : const auto log_num = find_last_log();
935 0 : last_log_is_marked_discard = false;
936 0 : write_lastlog_file(log_num);
937 : }
938 :
939 49879915 : uint32_t nbytes = _writebuf.available();
940 49879915 : if (nbytes == 0) {
941 46020 : return;
942 : }
943 49833895 : if (nbytes < _writebuf_chunk &&
944 48808498 : tnow - _last_write_time < 2000UL) {
945 : // write in _writebuf_chunk-sized chunks, but always write at
946 : // least once per 2 seconds if data is available
947 48807867 : return;
948 : }
949 :
950 : #if !AP_FILESYSTEM_LITTLEFS_ENABLED // too expensive on littlefs, rely on ENOSPC below
951 1026028 : if (tnow - _free_space_last_check_time > _free_space_check_interval) {
952 131155 : _free_space_last_check_time = tnow;
953 131155 : last_io_operation = "disk_space_avail";
954 131155 : if (disk_space_avail() < _free_space_min_avail && disk_space() > 0) {
955 0 : DEV_PRINTF("Out of space for logging\n");
956 0 : stop_logging();
957 0 : _open_error_ms = AP_HAL::millis(); // prevent logging starting again for 5s
958 0 : last_io_operation = "";
959 0 : return;
960 : }
961 131155 : last_io_operation = "";
962 : }
963 : #endif
964 1026028 : _last_write_time = tnow;
965 1026028 : if (nbytes > _writebuf_chunk) {
966 : // be kind to the filesystem layer
967 1022740 : nbytes = _writebuf_chunk;
968 : }
969 :
970 : uint32_t size;
971 1026028 : const uint8_t *head = _writebuf.readptr(size);
972 1026028 : nbytes = MIN(nbytes, size);
973 :
974 : #if !AP_FILESYSTEM_LITTLEFS_ENABLED
975 : // try to align writes on a 512 byte boundary to avoid filesystem reads
976 1026028 : if ((nbytes + _write_offset) % 512 != 0) {
977 789 : uint32_t ofs = (nbytes + _write_offset) % 512;
978 789 : if (ofs < nbytes) {
979 621 : nbytes -= ofs;
980 : }
981 : }
982 : #endif
983 1026028 : last_io_operation = "write";
984 1026028 : if (!write_fd_semaphore.take(1)) {
985 0 : return;
986 : }
987 1026028 : if (_write_fd == -1) {
988 0 : write_fd_semaphore.give();
989 0 : return;
990 : }
991 :
992 1026028 : uint32_t bytes_until_fsync = AP::FS().bytes_until_fsync(_write_fd);
993 1026028 : if (bytes_until_fsync > 0 && nbytes > bytes_until_fsync) {
994 0 : nbytes = bytes_until_fsync; // write exactly enough to sync
995 : }
996 :
997 1026028 : ssize_t nwritten = AP::FS().write(_write_fd, head, nbytes);
998 1026028 : last_io_operation = "";
999 1026028 : if (nwritten <= 0) {
1000 0 : if (errno == ENOSPC) {
1001 0 : DEV_PRINTF("Out of space for logging\n");
1002 0 : stop_logging();
1003 0 : _open_error_ms = AP_HAL::millis(); // prevent logging starting again for 5s
1004 0 : last_io_operation = "";
1005 0 : } else if ((tnow - _last_write_ms)/1000U > unsigned(_front._params.file_timeout)) {
1006 : // if we can't write for LOG_FILE_TIMEOUT seconds we give up and close
1007 : // the file. This allows us to cope with temporary write
1008 : // failures caused by directory listing
1009 0 : last_io_operation = "close";
1010 0 : AP::FS().close(_write_fd);
1011 0 : last_io_operation = "";
1012 0 : _write_fd = -1;
1013 0 : printf("Failed to write to File: %s\n", strerror(errno));
1014 : }
1015 0 : _last_write_failed = true;
1016 : } else {
1017 1026028 : _last_write_failed = false;
1018 1026028 : _last_write_ms = tnow;
1019 1026028 : _write_offset += nwritten;
1020 1026028 : _writebuf.advance(nwritten);
1021 :
1022 : // we know nwritten > 0 so we won't sync if bytes_until_fsync == 0
1023 1026028 : if ((uint32_t)nwritten == bytes_until_fsync) {
1024 0 : last_io_operation = "fsync";
1025 0 : AP::FS().fsync(_write_fd);
1026 0 : last_io_operation = "";
1027 : }
1028 :
1029 : #if AP_RTC_ENABLED && CONFIG_HAL_BOARD == HAL_BOARD_CHIBIOS
1030 : // ChibiOS does not update mtime on writes, so if we opened
1031 : // without knowing the time we should update it later
1032 : if (_need_rtc_update) {
1033 : uint64_t utc_usec;
1034 : if (AP::rtc().get_utc_usec(utc_usec)) {
1035 : AP::FS().set_mtime(_write_filename, utc_usec/(1000U*1000U));
1036 : _need_rtc_update = false;
1037 : }
1038 : }
1039 : #endif
1040 : }
1041 :
1042 1026028 : write_fd_semaphore.give();
1043 : }
1044 :
1045 1398826 : bool AP_Logger_File::io_thread_alive() const
1046 : {
1047 1398826 : if (!hal.scheduler->is_system_initialized()) {
1048 : // the system has long pauses during initialisation, assume still OK
1049 357 : return true;
1050 : }
1051 : // if the io thread hasn't had a heartbeat in a while then it is
1052 : #if CONFIG_HAL_BOARD == HAL_BOARD_ESP32
1053 : uint32_t timeout_ms = 10000;
1054 : #else
1055 1398469 : uint32_t timeout_ms = 5000;
1056 : #endif
1057 : #if CONFIG_HAL_BOARD == HAL_BOARD_SITL && !defined(HAL_BUILD_AP_PERIPH)
1058 : // the IO thread is working with hardware - writing to a physical
1059 : // disk. Unfortunately these hardware devices do not obey our
1060 : // SITL speedup options, so we allow for it here.
1061 1398469 : SITL::SIM *sitl = AP::sitl();
1062 1398469 : if (sitl != nullptr && sitl->speedup > 0) {
1063 1398469 : timeout_ms *= sitl->speedup;
1064 : }
1065 : #endif
1066 1398469 : return (AP_HAL::millis() - _io_timer_heartbeat) < timeout_ms;
1067 : }
1068 :
1069 1248934 : bool AP_Logger_File::logging_failed() const
1070 : {
1071 1248934 : if (!_initialised) {
1072 0 : return true;
1073 : }
1074 1248934 : if (recent_open_error()) {
1075 20 : return true;
1076 : }
1077 1248914 : if (!io_thread_alive()) {
1078 : // No heartbeat in a second. IO thread is dead?! Very Not
1079 : // Good.
1080 0 : return true;
1081 : }
1082 1248914 : if (_last_write_failed) {
1083 0 : return true;
1084 : }
1085 :
1086 1248914 : return false;
1087 : }
1088 :
1089 : /*
1090 : erase another file in async erase operation
1091 : */
1092 0 : void AP_Logger_File::erase_next(void)
1093 : {
1094 0 : char *fname = _log_file_name(erase.log_num);
1095 0 : if (fname == nullptr) {
1096 0 : erase.log_num = 0;
1097 0 : return;
1098 : }
1099 :
1100 0 : AP::FS().unlink(fname);
1101 0 : free(fname);
1102 :
1103 0 : erase.log_num++;
1104 0 : if (erase.log_num <= _front.get_max_num_logs()) {
1105 0 : return;
1106 : }
1107 :
1108 0 : fname = _lastlog_file_name();
1109 0 : if (fname != nullptr) {
1110 0 : AP::FS().unlink(fname);
1111 0 : free(fname);
1112 : }
1113 :
1114 0 : _cached_oldest_log = 0;
1115 :
1116 0 : erase.log_num = 0;
1117 : }
1118 :
1119 : #endif // HAL_LOGGING_FILESYSTEM_ENABLED
1120 :
|
