logger.cpp

Go to the documentation of this file.

/*
 *  SatNOGS-COMMS MCU software
 *
 *  Copyright (C) 2023-2024, Libre Space Foundation <http://libre.space>
 *
 *  This program is free software: you can redistribute it and/or modify
 *  it under the terms of the GNU General Public License as published by
 *  the Free Software Foundation, either version 3 of the License, or
 *  (at your option) any later version.
 *
 *  This program is distributed in the hope that it will be useful,
 *  but WITHOUT ANY WARRANTY; without even the implied warranty of
 *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 *  GNU General Public License for more details.
 *
 *  You should have received a copy of the GNU General Public License
 *  along with this program.  If not, see <http://www.gnu.org/licenses/>.
 *
 *  SPDX-License-Identifier: GNU General Public License v3.0 or later
 */
 
#include "logger.hpp"
#include "bsp/bsp.hpp"
#include "callbacks.hpp"
#include "scoped_lock.hpp"
#include "storage.hpp"
#include "version.hpp"
#include <cstring>
#include <etl/error_handler.h>
#include <etl/string_stream.h>
#include <etl/to_string.h>
#include <satnogs-comms-lib/board.hpp>
#include <zephyr/device.h>
#include <zephyr/devicetree.h>
#include <zephyr/drivers/uart.h>
#include <zephyr/fs/fs.h>
#include <zephyr/retention/retention.h>
#include <zephyr/task_wdt/task_wdt.h>
 
#include "time.hpp"
 
namespace sc  = satnogs::comms;
namespace scl = satnogs::comms::lib;
 
LOG_MODULE_REGISTER(satnogscomms, CONFIG_LOG_DEFAULT_LEVEL);
 
namespace satnogs::comms
{
 
static const struct device *retention_memory_dev =
    DEVICE_DT_GET(DT_CHOSEN(zephyr_retention_memory));
 
etl::string<CONFIG_LOG_MAX_MSG_LEN> retentained_mem_str;
 
#if DT_NODE_EXISTS(DT_ALIAS(uartlog))
K_SEM_DEFINE(tx_done, 1, 1);
static __aligned(32) uint8_t dma_buf[CONFIG_LOG_MAX_MSG_LEN];
 
static void
uart_callback(const struct device *dev, struct uart_event *evt, void *user_data)
{
  ARG_UNUSED(dev);
  switch (evt->type) {
  case UART_TX_DONE:
  case UART_TX_ABORTED:
    k_sem_give(&tx_done);
    break;
  case UART_RX_RDY:
    break;
  case UART_RX_BUF_RELEASED:
    break;
  case UART_RX_BUF_REQUEST:
    break;
  case UART_RX_DISABLED:
    break;
  default:
    break;
  }
}
#endif
 
static etl::string<CONFIG_LOG_MAX_MSG_LEN> log_str;

void
logger::boot()
{
  etl::string<CONFIG_LOG_MAX_MSG_LEN> msg;
  etl::string_stream                  stream(msg);
  stream << "SatNOGS-COMMS FW: " << sc::version::fw_major << "."
         << sc::version::fw_minor << "." << sc::version::fw_patch
         << ", LIB: " << scl::version::lib_major << "."
         << scl::version::lib_minor << "." << scl::version::lib_patch
         << ", HW: " << scl::version::hw_major << "." << scl::version::hw_minor
         << "." << scl::version::hw_patch << " initialized";
  scoped_lock lock(&m_mtx);
  log_unlocked({target::RTT, target::UART, target::RING_BUFFER}, msg.c_str());
}

void
logger::log(const lib::exception &e)
{
  log({target::RTT, target::RING_BUFFER, target::UART, target::STORAGE}, e);
}

void
logger::log(const etl::exception &e)
{
  log({target::RTT, target::RING_BUFFER, target::UART, target::STORAGE}, e);
}

void
logger::log(const std::exception &e)
{
  log({target::RTT, target::RING_BUFFER, target::UART, target::STORAGE}, e);
}

void
logger::log(const char *msg)
{
  log({target::RTT, target::RING_BUFFER, target::UART, target::STORAGE}, msg);
}

void
logger::log(const etl::istring &msg)
{
  log({target::RTT, target::RING_BUFFER, target::UART, target::STORAGE},
      msg.c_str());
}

void
logger::log(std::initializer_list<target> list, const scl::exception &e)
{
  scoped_lock lock(&m_mtx);
  backup_sram_push(e);
  log_unlocked(list, e);
}

void
logger::log(std::initializer_list<target> list, const std::exception &e)
{
  scoped_lock lock(&m_mtx);
  backup_sram_push(e);
  log_unlocked(list, e);
}

void
logger::log(std::initializer_list<target> list, const etl::exception &e)
{
  scoped_lock lock(&m_mtx);
  backup_sram_push(e);
  log_unlocked(list, e);
}

void
logger::log(std::initializer_list<target> list, const char *msg)
{
  scoped_lock lock(&m_mtx);
  log_unlocked(list, msg);
}

void
logger::rtt_push(const satnogs::comms::lib::exception &e)
{
  log_str.clear();
  e.to_string(log_str);
  LOG_ERR("Exception: %s", log_str.c_str());
}

void
logger::rtt_push(const etl::exception &e)
{
  LOG_ERR("Exception: %s", e.what());
}

void
logger::rtt_push(const std::exception &e)
{
  LOG_ERR("Exception: %s", e.what());
}

void
logger::rtt_push(const char *msg)
{
  LOG_INF("%s", msg);
}

void
logger::ring_buffer_push(const lib::exception &e)
{
  auto          &t = time::get_instance();
  uint64_t       t_posix;
  time::time_src t_src = t.get(t_posix);
  log_str.clear();
  log_str.append("EXC: ");
  /* Using the ETL we are safe from a possible buffer overflow */
  e.to_string(log_str);
  if (m_ring_buffer.full() == true) {
    m_ring_buffer.pop();
  }
  m_ring_buffer.push(ring_buf_msg(t_src, t_posix, log_str));
}

void
logger::ring_buffer_push(const std::exception &e)
{
  auto          &t = time::get_instance();
  uint64_t       t_posix;
  time::time_src t_src = t.get(t_posix);
  log_str.clear();
  log_str.append("EXC: ");
  /* Using the ETL we are safe from a possible buffer overflow */
  log_str.append(e.what());
  if (m_ring_buffer.full() == true) {
    m_ring_buffer.pop();
  }
  m_ring_buffer.push(ring_buf_msg(t_src, t_posix, log_str));
}

void
logger::ring_buffer_push(const etl::exception &e)
{
  auto          &t = time::get_instance();
  uint64_t       t_posix;
  time::time_src t_src = t.get(t_posix);
  log_str.clear();
  log_str.append("EXC: ");
  /* Using the ETL we are safe from a possible buffer overflow */
  log_str.append(e.what());
  if (m_ring_buffer.full() == true) {
    m_ring_buffer.pop();
  }
  m_ring_buffer.push(ring_buf_msg(t_src, t_posix, log_str));
}

void
logger::ring_buffer_push(const char *msg)
{
  auto          &t = time::get_instance();
  uint64_t       t_posix;
  time::time_src t_src = t.get(t_posix);
  log_str.clear();
  log_str.append("LOG: ");
  /* Using the ETL we are safe from a possible buffer overflow */
  log_str.append(msg);
  if (m_ring_buffer.full() == true) {
    m_ring_buffer.pop();
  }
  m_ring_buffer.push(ring_buf_msg(t_src, t_posix, log_str));
}

void
logger::uart_push(const lib::exception &e)
{
#if DT_NODE_EXISTS(DT_ALIAS(uartlog))
  log_str.clear();
  log_str.append("EXC: ");
  log_str.append(e.what());
  log_str.append("\r\n");
  const struct device *uart_log = DEVICE_DT_GET(DT_ALIAS(uartlog));
  /*
   * Wait for the previous transfer to finish. If this is not possible just
   * abort
   */
  if (k_sem_take(&tx_done, K_MSEC(400))) {
    uart_tx_abort(uart_log);
    return;
  }
  memcpy(dma_buf, reinterpret_cast<const uint8_t *>(log_str.c_str()),
         log_str.size());
  uart_tx(uart_log, dma_buf, log_str.size(), SYS_FOREVER_US);
#endif
}

void
logger::uart_push(const std::exception &e)
{
#if DT_NODE_EXISTS(DT_ALIAS(uartlog))
  log_str.clear();
  log_str.append("EXC: ");
  log_str.append(e.what());
  const struct device *uart_log = DEVICE_DT_GET(DT_ALIAS(uartlog));
  uart_tx(uart_log, reinterpret_cast<const uint8_t *>(log_str.c_str()),
          log_str.size(), 100000);
#endif
}

void
logger::uart_push(const etl::exception &e)
{
#if DT_NODE_EXISTS(DT_ALIAS(uartlog))
  log_str.clear();
  log_str.append("EXC: ");
  log_str.append(e.what());
  const struct device *uart_log = DEVICE_DT_GET(DT_ALIAS(uartlog));
  uart_tx(uart_log, reinterpret_cast<const uint8_t *>(log_str.c_str()),
          log_str.size(), 100000);
#endif
}

void
logger::uart_push(const char *msg)
{
#if DT_NODE_EXISTS(DT_ALIAS(uartlog))
  log_str.clear();
  log_str.append("LOG: ");
  log_str.append(msg);
  log_str.append("\r\n");
  const struct device *uart_log = DEVICE_DT_GET(DT_ALIAS(uartlog));
 
  /*
   * Wait for the previous transfer to finish. If this is not possible just
   * abort
   */
  if (k_sem_take(&tx_done, K_MSEC(400))) {
    uart_tx_abort(uart_log);
    return;
  }
  memcpy(dma_buf, reinterpret_cast<const uint8_t *>(log_str.c_str()),
         log_str.size());
  uart_tx(uart_log, dma_buf, log_str.size(), SYS_FOREVER_US);
#endif
}
 
void
logger::storage_push(const std::exception &e)
{
  auto &storage = storage::get_instance();
  if (storage.enabled() == false || storage.get_dir() != lib::emmc::dir::MCU) {
    return;
  }
 
  try {
    m_logs_path.clear();
    m_logs_path += mcu_log_dir;
    storage.mkdir(m_logs_path);
 
    auto          &t = time::get_instance();
    uint64_t       t_posix;
    time::time_src t_src = t.get(t_posix);
 
    log_str.clear();
    etl::string_stream stream(log_str);
    stream << "[" << etl::dec << (int)t_src << "," << etl::dec << t_posix
           << "]: "
           << "EXC: " << e.what() << "\r\n";
 
    current_log_file(m_logs_path);
    storage.write(m_logs_path, (const uint8_t *)log_str.c_str(),
                  log_str.size());
  } catch (lib::exception &e) {
    return;
  }
}
 
void
logger::storage_push(const etl::exception &e)
{
  auto &storage = storage::get_instance();
  if (storage.enabled() == false || storage.get_dir() != lib::emmc::dir::MCU) {
    return;
  }
 
  try {
    m_logs_path.clear();
    m_logs_path += mcu_log_dir;
    storage.mkdir(m_logs_path);
 
    auto          &t = time::get_instance();
    uint64_t       t_posix;
    time::time_src t_src = t.get(t_posix);
 
    log_str.clear();
    etl::string_stream stream(log_str);
    stream << "[" << etl::dec << (int)t_src << "," << etl::dec << t_posix
           << "]: "
           << "EXC: " << e.what() << "\r\n";
 
    current_log_file(m_logs_path);
    storage.write(m_logs_path, (const uint8_t *)log_str.c_str(),
                  log_str.size());
  } catch (lib::exception &e) {
    return;
  }
}
 
void
logger::storage_push(const lib::exception &e)
{
  /* if we leave this unchecked the logger will try to write the
   * storage_delete_dir exception to a file in a dir that does not exist -
   * producing a kernel fault
   */
 
  auto &storage = storage::get_instance();
  if (!storage.enabled() || storage.get_dir() == lib::emmc::dir::FPGA) {
    return;
  }
 
  try {
    m_logs_path.clear();
    m_logs_path += mcu_log_dir;
    storage.mkdir(m_logs_path);
 
    auto          &t = time::get_instance();
    uint64_t       t_posix;
    time::time_src t_src = t.get(t_posix);
 
    log_str.clear();
    etl::string_stream stream(log_str);
    stream << "[" << etl::dec << (int)t_src << "," << etl::dec << t_posix
           << "]: EXC ";
    e.to_string(stream);
    stream << "\r\n";
 
    current_log_file(m_logs_path);
    storage.write(m_logs_path, (const uint8_t *)log_str.c_str(),
                  log_str.size());
  } catch (lib::exception &e) {
    return;
  }
}
 
void
logger::storage_push(const char *msg)
{
 
  auto &storage = storage::get_instance();
  if (!storage.enabled() || storage.get_dir() == lib::emmc::dir::FPGA) {
    return;
  }
 
  try {
    m_logs_path.clear();
    m_logs_path += mcu_log_dir;
    storage.mkdir(m_logs_path);
 
    auto          &t = time::get_instance();
    uint64_t       t_posix;
    time::time_src t_src = t.get(t_posix);
 
    log_str.clear();
    etl::string_stream stream(log_str);
    stream << "[" << etl::dec << (int)t_src << "," << etl::dec << t_posix
           << "]: "
           << "LOG: " << msg << "\r\n";
    current_log_file(m_logs_path);
    storage.write(m_logs_path, (const uint8_t *)log_str.c_str(),
                  log_str.size());
  } catch (lib::exception &e) {
    return;
  }
}

void
logger::current_log_file(etl::istring &path)
{
  path.clear();
  etl::string_stream stream(m_logs_path);
 
  auto     &time = time::get_instance();
  struct tm t;
  auto      tsrc = time.get(t);
  switch (tsrc) {
  case sc::time::time_src::UPTIME: {
    auto    &s        = sc::settings::get_instance();
    uint32_t boot_cnt = s.get<sc::settings::param::BOOT_COUNT>();
    uint32_t days     = time.uptime() / (24 * 60 * 60 * 1000);
 
    stream << mcu_log_dir << "/"
           << "boot-" << boot_cnt << "-" << days << ".log";
  } break;
  case sc::time::time_src::GNSS_ASSISTED_RTC:
  case sc::time::time_src::GNSS_ONLY: {
    char strt[16];
    strftime(strt, 15, "%Y-%m-%d", &t);
    stream << mcu_log_dir << "/" << strt << ".log";
    break;
  }
  default:
    throw scl::inval_arg_exception(scl::exception::severity::MINOR, __FILE__,
                                   __LINE__);
  }
}
 
void
logger::delete_storage_logs(struct tm &start, struct tm &end)
{
  auto &storage = storage::get_instance();
  if (!storage.enabled() || storage.get_dir() == lib::emmc::dir::FPGA) {
    return;
  }
 
  scoped_lock lock(&m_mtx);
 
  time_t start_posix = timeutil_timegm(&start);
  time_t end_posix   = timeutil_timegm(&end);
  time_t day_posix   = 24 * 60 * 60;
 
  struct tm tmp;
  for (time_t t = start_posix; t <= end_posix; t += day_posix) {
 
    gmtime_r(&t, &tmp);
    m_logs_path.clear();
    etl::string_stream stream(m_logs_path);
    stream << mcu_log_dir << "/" << tmp.tm_year << "-" << tmp.tm_mon << "-"
           << tmp.tm_mday << ".log";
 
    try {
      storage.rm(m_logs_path);
    } catch (lib::exception &e) {
      /*Do nothing*/
    }
  }
}

int
logger::backup_sram_push(const lib::exception &e)
{
  if (static_cast<uint8_t>(e.get_severity()) <=
      CONFIG_BACKUP_SRAM_EXCEPTION_LOG_LEVEL) {
    log_str.clear();
    e.to_string(log_str);
    retention_clear(retention_memory_dev);
    return retention_write(retention_memory_dev, 0U,
                           reinterpret_cast<const uint8_t *>(log_str.c_str()),
                           CONFIG_LOG_MAX_MSG_LEN);
  }
  return -1;
}

int
logger::backup_sram_push(const std::exception &e)
{
  retention_clear(retention_memory_dev);
  return retention_write(retention_memory_dev, 0U,
                         reinterpret_cast<const uint8_t *>(e.what()),
                         CONFIG_LOG_MAX_MSG_LEN);
}

int
logger::backup_sram_push(const etl::exception &e)
{
  retention_clear(retention_memory_dev);
  return retention_write(retention_memory_dev, 0U,
                         reinterpret_cast<const uint8_t *>(e.what()),
                         CONFIG_LOG_MAX_MSG_LEN);
}
 
size_t
logger::get_ring_buffer_size()
{
  return m_ring_buffer.size();
}
 
void
logger::get_ring_buffer_log(ring_buf_msg &data, size_t index)
{
  data = *(m_ring_buffer.crbegin() + index);
}

etl::string<CONFIG_LOG_MAX_MSG_LEN>
logger::get_latest_exception() const
{
  if (retention_is_valid(retention_memory_dev) != 1) {
    return "Data in BACKUP SRAM is not valid";
  }
  if (retention_read(retention_memory_dev, 0U,
                     reinterpret_cast<uint8_t *>(retentained_mem_str.data()),
                     CONFIG_LOG_MAX_MSG_LEN) != 0) {
    return "Error while reading data from BACKUP SRAM device";
  }
  return retentained_mem_str.data();
}

logger::logger()
{
  k_mutex_init(&m_mtx);
#if DT_NODE_EXISTS(DT_ALIAS(uartlog))
  const struct device *uart_log = DEVICE_DT_GET(DT_ALIAS(uartlog));
  struct uart_config   uart_cfg = {
        .baudrate  = CONFIG_LOG_UART_BAUDRATE,
        .parity    = UART_CFG_PARITY_NONE,
        .stop_bits = UART_CFG_STOP_BITS_1,
        .data_bits = UART_CFG_DATA_BITS_8,
        .flow_ctrl = UART_CFG_FLOW_CTRL_NONE,
  };
  uart_rx_disable(uart_log);
  uart_tx_abort(uart_log);
  uart_configure(uart_log, &uart_cfg);
  uart_callback_set(uart_log, uart_callback, nullptr);
#endif
}
 
} // namespace satnogs::comms