~aleteoryx/muditaos

a60e27fa4bf7cd10d5a36e4ba6afd1d722ab76de — Mateusz Grzegorzek 4 years ago 31b24ed
[EGD-4593] Dump logs to file on timeout

- Dump logs to file every 10 sec.
- max file size is 50 MB
  (after reaching it, no more logs will be logged),
- Add `LockGuard` with locking mechanism
  supporting IRQ and use it in `Logger`.
- Fix minor style issues in `Logger`.
- Add `mount_user_lfs_partition.py` script for mounting LFS on Linux FS
  in order to get `MuditaOS.log` file from `user` partition
M module-os/CMakeLists.txt => module-os/CMakeLists.txt +1 -0
@@ 28,6 28,7 @@ set(SOURCES
        ${CMAKE_CURRENT_SOURCE_DIR}/memory/usermem.c

        ${CMAKE_CURRENT_SOURCE_DIR}/CriticalSectionGuard.cpp
        ${CMAKE_CURRENT_SOURCE_DIR}/LockGuard.cpp
        )

#Substitute FreeRTOS SystemvView sources if enabled

A module-os/LockGuard.cpp => module-os/LockGuard.cpp +27 -0
@@ 0,0 1,27 @@
// Copyright (c) 2017-2021, Mudita Sp. z.o.o. All rights reserved.
// For licensing, see https://github.com/mudita/MuditaOS/LICENSE.md

#include "critical.hpp"
#include "LockGuard.hpp"
#include <macros.h>
#include <stdexcept>

LockGuard::LockGuard(cpp_freertos::MutexStandard& mutex) : mutex(mutex)
{
    if (isIRQ()) {
        savedInterruptStatus = cpp_freertos::CriticalSection::EnterFromISR();
    }
    else if(!mutex.Lock()) {
        throw std::runtime_error("LockGuard failed to lock mutex");
    }
}

LockGuard::~LockGuard()
{
    if (isIRQ()) {
        cpp_freertos::CriticalSection::ExitFromISR(savedInterruptStatus);
    }
    else {
        mutex.Unlock();
    }
}

A module-os/LockGuard.hpp => module-os/LockGuard.hpp +22 -0
@@ 0,0 1,22 @@
// Copyright (c) 2017-2021, Mudita Sp. z.o.o. All rights reserved.
// For licensing, see https://github.com/mudita/MuditaOS/LICENSE.md

#pragma once

#include <mutex.hpp>

class LockGuard
{
public:
    explicit LockGuard(cpp_freertos::MutexStandard& mutex);
    ~LockGuard();
    LockGuard(const LockGuard &) = delete;
    LockGuard(LockGuard &&)      = delete;

    LockGuard &operator=(const LockGuard &) = delete;
    LockGuard &operator=(LockGuard &&) = delete;

private:
    BaseType_t savedInterruptStatus;
    cpp_freertos::MutexStandard &mutex;
};

M module-services/service-evtmgr/EventManager.cpp => module-services/service-evtmgr/EventManager.cpp +25 -1
@@ 25,6 25,7 @@
#include <bsp/battery-charger/battery_charger.hpp>
#include <common_data/RawKey.hpp>
#include <log/log.hpp>
#include <log/Logger.hpp>
#include <module-utils/time/time_conversion.hpp>
#include <service-appmgr/Controller.hpp>
#include <service-audio/AudioMessage.hpp>


@@ 35,6 36,8 @@
#include <service-desktop/DesktopMessages.hpp>
#include <service-cellular/ServiceCellular.hpp>
#include <cassert>
#include <fstream>
#include <filesystem>
#include <list>
#include <tuple>
#include <vector>


@@ 44,8 47,16 @@
#include <SystemManager/messages/PhoneModeRequest.hpp>
#include <vibra/Vibra.hpp>

namespace
{
    constexpr auto loggerDelayMs   = 1000 * 10;
    constexpr auto loggerTimerName = "Logger";
} // namespace

EventManager::EventManager(const std::string &name)
    : sys::Service(name, "", stackDepth), settings(std::make_shared<settings::Settings>(this)),
    : sys::Service(name, "", stackDepth),
      settings(std::make_shared<settings::Settings>(this)), loggerTimer{std::make_unique<sys::Timer>(
                                                                loggerTimerName, this, loggerDelayMs)},
      screenLightControl(std::make_unique<screen_light_control::ScreenLightControl>(settings, this)),
      Vibra(std::make_unique<vibra_handle::Vibra>(this))
{


@@ 53,6 64,8 @@ EventManager::EventManager(const std::string &name)
    alarmTimestamp = 0;
    alarmID        = 0;
    bus.channels.push_back(sys::BusChannel::ServiceDBNotifications);
    loggerTimer->connect([&](sys::Timer &) { dumpLogsToFile(); });
    loggerTimer->start();
}

EventManager::~EventManager()


@@ 351,6 364,17 @@ bool EventManager::messageSetApplication(sys::Service *sender, const std::string
    return sender->bus.sendUnicast(msg, service::name::evt_manager);
}

void EventManager::dumpLogsToFile()
{
    const auto logPath = purefs::dir::getUserDiskPath() / LOG_FILE_NAME;
    const bool dumpLog = !(std::filesystem::exists(logPath) && std::filesystem::file_size(logPath) > MAX_LOG_FILE_SIZE);
    if (dumpLog) {
        const auto &logs = Log::Logger::get().getLogs();
        std::fstream logFile(logPath, std::fstream::out | std::fstream::app);
        logFile.write(logs.data(), logs.size());
    }
}

void EventManager::handleMinuteUpdate(time_t timestamp)
{
    if (!targetApplication.empty()) {

M module-services/service-evtmgr/service-evtmgr/EventManager.hpp => module-services/service-evtmgr/service-evtmgr/EventManager.hpp +4 -1
@@ 9,13 9,13 @@
#include <Service/Common.hpp>
#include <Service/Message.hpp>
#include <Service/Service.hpp>
#include <Service/Timer.hpp>
#include <Service/Worker.hpp>
#include <bsp/common.hpp>
#include <bsp/keyboard/key_codes.hpp>
#include <bsp/keypad_backlight/keypad_backlight.hpp>
#include <screen-light-control/ScreenLightControl.hpp>
#include <vibra/Vibra.hpp>

#include <service-db/DBServiceName.hpp>

#include <cstdint>


@@ 34,6 34,7 @@ class EventManager : public sys::Service
    bool processVibraRequest(bsp::vibrator::Action act, sys::ms RepetitionTime = static_cast<sys::ms>(1000));

    std::shared_ptr<settings::Settings> settings;
    std::unique_ptr<sys::Timer> loggerTimer;

  protected:
    std::unique_ptr<WorkerEvent> EventWorker;


@@ 67,6 68,8 @@ class EventManager : public sys::Service

    sys::ReturnCodes SwitchPowerModeHandler(const sys::ServicePowerMode mode) override final;

    void dumpLogsToFile();

    /**
     * @brief Sends request to application manager to switch from current application to specific window in application
     * with specified name .

M module-utils/board/cross/log_rt1051.cpp => module-utils/board/cross/log_rt1051.cpp +7 -6
@@ 34,7 34,7 @@ namespace Log
                                           loggerBufferSizeLeft(),
                                           "%s%-5s %s[%s] %s%s:%s:%d:%s ",
                                           logColors->levelColors[level].data(),
                                           level_names[level],
                                           levelNames[level],
                                           logColors->serviceNameColor.data(),
                                           getTaskDesc(),
                                           logColors->callerInfoColor.data(),


@@ 46,7 46,7 @@ namespace Log

    bool Logger::filterLogs(logger_level level)
    {
        return GetLogLevel(getTaskDesc()) < level;
        return getLogLevel(getTaskDesc()) < level;
    }

    void Logger::logToDevice(const char *fmt, va_list args)


@@ 60,21 60,22 @@ namespace Log
        loggerBufferCurrentPos += snprintf(&loggerBuffer[loggerBufferCurrentPos],
                                           loggerBufferSizeLeft(),
                                           "%-5s [%-10s] \x1b[31mASSERTION ",
                                           level_names[LOGFATAL],
                                           levelNames[LOGFATAL],
                                           getTaskDesc());

        loggerBufferCurrentPos += vsnprintf(&loggerBuffer[loggerBufferCurrentPos], loggerBufferSizeLeft(), fmt, args);
        logToDevice(Device::DEFAULT, loggerBuffer, loggerBufferCurrentPos);
        circularBuffer.put(std::string(loggerBuffer, loggerBufferCurrentPos));
    }

    void Logger::logToDevice(Device device, std::string_view log, size_t length)
    void Logger::logToDevice(Device device, std::string_view logMsg, size_t length)
    {
        switch (device) {
        case Device::DEFAULT:
            log_WriteToDevice(reinterpret_cast<const uint8_t *>(log.data()), length);
            log_WriteToDevice(reinterpret_cast<const uint8_t *>(logMsg.data()), length);
            break;
        case Device::SEGGER_RTT:
            SEGGER_RTT_Write(0, reinterpret_cast<const void *>(log.data()), length);
            SEGGER_RTT_Write(0, reinterpret_cast<const void *>(logMsg.data()), length);
            break;
        default:
            break;

M module-utils/board/linux/log_linux.cpp => module-utils/board/linux/log_linux.cpp +3 -3
@@ 20,7 20,7 @@ namespace Log
                                           LOGGER_BUFFER_SIZE - loggerBufferCurrentPos,
                                           "%s%-5s %s%s:%s:%d:%s ",
                                           logColors->levelColors[level].data(),
                                           level_names[level],
                                           levelNames[level],
                                           logColors->callerInfoColor.data(),
                                           file,
                                           function,


@@ 38,8 38,8 @@ namespace Log
        assert(false && "Not implemented");
    }

    void Logger::logToDevice(Device, std::string_view log, size_t)
    void Logger::logToDevice(Device, std::string_view logMsg, size_t)
    {
        std::cout << log;
        std::cout << logMsg;
    }
} // namespace Log

M module-utils/log/Logger.cpp => module-utils/log/Logger.cpp +22 -36
@@ 4,6 4,7 @@
#include "critical.hpp"
#include <fstream>
#include <gsl/gsl_util>
#include "LockGuard.hpp"
#include "Logger.hpp"
#include "macros.h"



@@ 18,14 19,14 @@ namespace Log
                                                            {"ServiceDB", logger_level::LOGINFO},
                                                            {CRIT_STR, logger_level::LOGTRACE},
                                                            {IRQ_STR, logger_level::LOGTRACE}};
    const char *Logger::level_names[]                    = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"};
    const char *Logger::levelNames[]                     = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"};

    Logger::Logger() : circularBuffer(circularBufferSize)
    {}

    void Logger::enableColors(bool enable)
    {
        if (!lock()) {
            return;
        }
        auto _ = gsl::finally([this] { unlock(); });
        LockGuard lock(mutex);

        if (enable) {
            logColors = &logColorsOn;


@@ 35,20 36,23 @@ namespace Log
        }
    }

    auto Logger::GetLogLevel(const std::string &name) -> logger_level
    auto Logger::getLogLevel(const std::string &name) -> logger_level
    {
        return filtered[name];
    }

    bool Logger::lock()
    auto Logger::getLogs() -> std::string
    {
        if (isIRQ()) {
            bt = cpp_freertos::CriticalSection::EnterFromISR();
        LockGuard lock(mutex);

        std::string logs;
        while (!circularBuffer.isEmpty()) {
            const auto [result, msg] = circularBuffer.get();
            if (result) {
                logs += msg;
            }
        }
        else {
            return mutex.Lock();
        }
        return true;
        return logs;
    }

    void Logger::init()


@@ 62,10 66,7 @@ namespace Log

    auto Logger::log(Device device, const char *fmt, va_list args) -> int
    {
        if (!lock()) {
            return -1;
        }
        auto _ = gsl::finally([this] { unlock(); });
        LockGuard lock(mutex);

        loggerBufferCurrentPos = 0;



@@ 76,6 77,7 @@ namespace Log
            loggerBufferCurrentPos += (numOfBytesAddedToBuffer < sizeLeft) ? numOfBytesAddedToBuffer : (sizeLeft - 1);

            logToDevice(device, loggerBuffer, loggerBufferCurrentPos);
            circularBuffer.put(std::string(loggerBuffer, loggerBufferCurrentPos));
            return loggerBufferCurrentPos;
        }
        return -1;


@@ 87,11 89,7 @@ namespace Log
        if (!filterLogs(level)) {
            return -1;
        }

        if (!lock()) {
            return -1;
        }
        auto _ = gsl::finally([this] { unlock(); });
        LockGuard lock(mutex);

        loggerBufferCurrentPos = 0;
        addLogHeader(level, file, line, function);


@@ 104,6 102,7 @@ namespace Log
            loggerBufferCurrentPos += snprintf(&loggerBuffer[loggerBufferCurrentPos], loggerBufferSizeLeft(), "\n");

            logToDevice(Device::DEFAULT, loggerBuffer, loggerBufferCurrentPos);
            circularBuffer.put(std::string(loggerBuffer, loggerBufferCurrentPos));
            return loggerBufferCurrentPos;
        }
        return -1;


@@ 111,23 110,10 @@ namespace Log

    auto Logger::logAssert(const char *fmt, va_list args) -> int
    {
        if (!lock()) {
            return -1;
        }
        auto _ = gsl::finally([this] { unlock(); });
        LockGuard lock(mutex);

        logToDevice(fmt, args);

        return loggerBufferCurrentPos;
    }

    void Logger::unlock()
    {
        if (isIRQ()) {
            cpp_freertos::CriticalSection::ExitFromISR(bt);
        }
        else {
            mutex.Unlock();
        }
    }
}; // namespace Log

M module-utils/log/Logger.hpp => module-utils/log/Logger.hpp +9 -7
@@ 6,6 6,7 @@
#include <assert.h>
#include <board.h>
#include "log.hpp"
#include "LoggerBuffer.hpp"
#include "log_colors.hpp"
#include <map>
#include <mutex.hpp>


@@ 28,6 29,7 @@ namespace Log
            static Logger logger;
            return logger;
        }
        auto getLogs() -> std::string;
        void init();
        auto log(Device device, const char *fmt, va_list args) -> int;
        auto log(logger_level level, const char *file, int line, const char *function, const char *fmt, va_list args)


@@ 38,7 40,7 @@ namespace Log
        static constexpr auto IRQ_STR  = "IRQ";

      private:
        Logger() = default;
        Logger();

        void addLogHeader(logger_level level,
                          const char *file     = nullptr,


@@ 50,26 52,26 @@ namespace Log
        /// - TRACE is level 0, for unedfined lookups it will be alvways trace
        /// - it will be one time init for apps which doesn't tell what level they should have
        /// - for others it will be o1 lookup so it's fine
        [[nodiscard]] auto GetLogLevel(const std::string &name) -> logger_level;
        bool lock();
        [[nodiscard]] auto getLogLevel(const std::string &name) -> logger_level;
        void logToDevice(const char *fmt, va_list args);
        void logToDevice(Device device, std::string_view log, size_t length);
        void logToDevice(Device device, std::string_view logMsg, size_t length);
        [[nodiscard]] size_t loggerBufferSizeLeft() const noexcept
        {
            const auto sizeLeft = LOGGER_BUFFER_SIZE - loggerBufferCurrentPos;
            assert(sizeLeft > 0);
            return sizeLeft;
        }
        void unlock();

        BaseType_t bt;
        cpp_freertos::MutexStandard mutex;
        logger_level level{LOGTRACE};
        const LogColors *logColors            = &logColorsOff;
        char loggerBuffer[LOGGER_BUFFER_SIZE] = {0};
        size_t loggerBufferCurrentPos         = 0;

        static const char *level_names[];
        LoggerBuffer circularBuffer;
        static constexpr size_t circularBufferSize = 1000;

        static const char *levelNames[];
        static std::map<std::string, logger_level> filtered;
    };
} // namespace Log

M module-utils/log/LoggerBuffer.cpp => module-utils/log/LoggerBuffer.cpp +1 -1
@@ 10,7 10,7 @@ std::pair<bool, std::string> LoggerBuffer::get()
        return {result, logMsg};
    }
    if (numOfLostBytes > 0) {
        logMsg += "\r\n" + std::to_string(numOfLostBytes) + " " + lostBytesMessage;
        logMsg         = std::to_string(numOfLostBytes) + " " + lostBytesMessage + "\n" + logMsg;
        numOfLostBytes = 0;
    }
    return {true, logMsg};

M module-utils/log/log.hpp => module-utils/log/log.hpp +3 -2
@@ 1,4 1,4 @@
// Copyright (c) 2017-2020, Mudita Sp. z.o.o. All rights reserved.
// Copyright (c) 2017-2021, Mudita Sp. z.o.o. All rights reserved.
// For licensing, see https://github.com/mudita/MuditaOS/LICENSE.md

/*


@@ 84,7 84,8 @@ extern "C"
#pragma GCC diagnostic push
#pragma GCC diagnostic ignored "-Wunused-variable"
static const size_t LOGGER_BUFFER_SIZE  = 8192;
static const double MAX_BUFFER_UTIL_MEM = 0.8 * LOGGER_BUFFER_SIZE;
static const char *LOG_FILE_NAME        = "MuditaOS.log";
static const size_t MAX_LOG_FILE_SIZE   = 1024 * 1024 * 50; // 50 MB
#pragma GCC diagnostic pop

#endif /* LOG_LOG_H_ */

A tools/mount_user_lfs_partition.py => tools/mount_user_lfs_partition.py +71 -0
@@ 0,0 1,71 @@
# Copyright (c) 2017-2021, Mudita Sp. z.o.o. All rights reserved.
# For licensing, see https://github.com/mudita/MuditaOS/LICENSE.md

import argparse
import os

parser = argparse.ArgumentParser(
    usage=
"\ne.g.:\n"
"For Linux: python3 tools/mount_user_lfs.py --mount_dir /mnt/user --lfsfuse build-linux-Debug/lfsfuse --image build-linux-Debug/PurePhone.img --loop 1\n"
"For  Pure: python3 tools/mount_user_lfs.py --mount_dir /mnt/user --lfsfuse build-rt1051-RelWithDebInfo/lfsfuse --part3_path /dev/sda3")

parser.add_argument('--mount_dir', type=str,
                    help="Directory where LFS should be mounted", required=True)
parser.add_argument('--lfsfuse', type=str,
                    help="Path to `lfsfuse`", required=True)
parser.add_argument('--part3_path', type=str, help="Path to third partition (when mounting PURE LFS) e.g. `/dev/sda3`")
parser.add_argument('--image', type=str, help="Path to PurePhone.img (when mounting LINUX IMAGE LFS)")
parser.add_argument('--loop', type=int,
                    help="Loop device number - different than already existed, see `losetup --list` (when mounting LINUX IMAGE LFS)")
args = parser.parse_args()

if args.loop and args.image:
    command = "sudo losetup -P /dev/loop" + str(args.loop) + " " + str(args.image)
    print("Executing command:", command)
    result = os.system(command)

    if result != 0:
        os._exit(result)

    command = "sudo chmod 666 /dev/loop" + str(args.loop)
    print("Executing command:", command)
    result = os.system(command)

    if result != 0:
        os._exit(result)

elif not args.part3_path:
    print("ERROR! part3_path arg not provided!")
    os._exit(-1)


if not os.path.exists(args.mount_dir):
    print("Mount dir not exist! Trying to create it...")
    command = "sudo mkdir " + args.mount_dir
    print("Executing command:", command)
    result = os.system(command)

    if result != 0:
        os._exit(result)

    if not os.path.exists(args.mount_dir):
        print("Failed to create mount dir!")
        os._exit(-1)
    else:
        print("Mount dir created!")

command = "sudo " + args.lfsfuse + " "
if args.loop:
    command += "/dev/loop" + str(args.loop) + "p3 "
else:
    command += args.part3_path + " "

command += args.mount_dir + " --block_size=32768"
print("Executing command:", command)
result = os.system(command)

if result != 0:
    os._exit(result)

print("Procedure completed. Please check " + args.mount_dir)