From e7776f6c1790f3064d47c7a3a95e5a71119e9a52 Mon Sep 17 00:00:00 2001 From: Marek Niepieklo Date: Thu, 15 Jul 2021 16:09:06 +0200 Subject: [PATCH] [CP-228] Force flushing of logs before getting log files Moved flushing function to Logger class Decreased flushing time to 2 min Added EM event to request flushing from ServiceDesktop --- .../service-desktop/ServiceDesktop.cpp | 21 ++++++++++ .../filesystem/FilesystemEndpoint.cpp | 19 ++++++++++ .../filesystem/FilesystemEndpoint.hpp | 2 + .../service-desktop/ServiceDesktop.hpp | 4 ++ .../service-evtmgr/EventManager.cpp | 25 +++++++----- .../service-evtmgr/EVMessages.hpp | 14 +++++++ .../service-evtmgr/EventManager.hpp | 5 ++- module-utils/log/Logger.cpp | 38 +++++++++++++++++++ module-utils/log/Logger.hpp | 2 + test/harness | 2 +- 10 files changed, 121 insertions(+), 11 deletions(-) diff --git a/module-services/service-desktop/ServiceDesktop.cpp b/module-services/service-desktop/ServiceDesktop.cpp index d68937eb05014fd99ea774054aa5313e0715ff15..3c6840c8a1499c90c7a66b7bfda8aab6288a175c 100644 --- a/module-services/service-desktop/ServiceDesktop.cpp +++ b/module-services/service-desktop/ServiceDesktop.cpp @@ -18,6 +18,8 @@ #include #include #include +#include +#include #include #include #include @@ -81,6 +83,25 @@ auto ServiceDesktop::getSerialNumber() const -> std::string return settings->getValue(std::string("factory_data/serial"), settings::SettingsScope::Global); } +auto ServiceDesktop::requestLogsFlush() -> void +{ + int response = 0; + auto ret = bus.sendUnicastSync( + std::make_shared(), service::name::evt_manager, DefaultLogFlushTimeoutInMs); + + if (ret.first == sys::ReturnCodes::Success) { + auto responseMsg = std::dynamic_pointer_cast(ret.second); + if ((responseMsg != nullptr) && (responseMsg->retCode == true)) { + response = responseMsg->data; + + LOG_DEBUG("Respone data: %d", response); + } + } + if (ret.first == sys::ReturnCodes::Failure || response < 0) { + throw std::runtime_error("Logs flush failed"); + } +} + sys::ReturnCodes ServiceDesktop::InitHandler() { diff --git a/module-services/service-desktop/endpoints/filesystem/FilesystemEndpoint.cpp b/module-services/service-desktop/endpoints/filesystem/FilesystemEndpoint.cpp index 2ec031fb8583afa3ddf607c4870da88fe0af7941..c06d36cc70eef188d3ff74631e1d2e8a2e93809f 100644 --- a/module-services/service-desktop/endpoints/filesystem/FilesystemEndpoint.cpp +++ b/module-services/service-desktop/endpoints/filesystem/FilesystemEndpoint.cpp @@ -38,10 +38,29 @@ static bool isWritable(const fs::path &file) return static_cast(sf); } +auto FilesystemEndpoint::requestLogsFlush() const -> void +{ + auto owner = dynamic_cast(ownerServicePtr); + if (owner) { + owner->requestLogsFlush(); + } +} + auto FilesystemEndpoint::startGetFile(Context &context) const -> sys::ReturnCodes { std::filesystem::path filePath = context.getBody()[parserFSM::json::fileName].string_value(); + try { + requestLogsFlush(); + } + catch (const std::runtime_error &e) { + LOG_ERROR("Logs flush exception: %s", e.what()); + + context.setResponseStatus(parserFSM::http::Code::InternalServerError); + context.setResponseBody(json11::Json::object({{json::reason, std::string(e.what())}})); + return sys::ReturnCodes::Failure; + } + if (!std::filesystem::exists(filePath)) { LOG_ERROR("file not found"); diff --git a/module-services/service-desktop/endpoints/filesystem/FilesystemEndpoint.hpp b/module-services/service-desktop/endpoints/filesystem/FilesystemEndpoint.hpp index 3b8bd6ce4f5eb5b91bacce99ba7414ef1b061c5a..d4b96d9fe81ecfbe14dde8d8d9d187b1e15d69e6 100644 --- a/module-services/service-desktop/endpoints/filesystem/FilesystemEndpoint.hpp +++ b/module-services/service-desktop/endpoints/filesystem/FilesystemEndpoint.hpp @@ -31,5 +31,7 @@ class FilesystemEndpoint : public parserFSM::Endpoint auto startSendFile(parserFSM::Context &context) const -> sys::ReturnCodes; auto sendFileChunk(parserFSM::Context &context) const -> sys::ReturnCodes; + auto requestLogsFlush() const -> void; + FileOperations &fileOps; }; diff --git a/module-services/service-desktop/service-desktop/ServiceDesktop.hpp b/module-services/service-desktop/service-desktop/ServiceDesktop.hpp index 4708f6bf6f4c88f1c3c29adcd8e0553c2b8e342f..e0280b395888e00066cb76c1b9f7f63ddd21daae 100644 --- a/module-services/service-desktop/service-desktop/ServiceDesktop.hpp +++ b/module-services/service-desktop/service-desktop/ServiceDesktop.hpp @@ -109,12 +109,16 @@ class ServiceDesktop : public sys::Service return usbSecurityModel.get(); } + auto requestLogsFlush() -> void; + private: auto getSerialNumber() const -> std::string; std::unique_ptr usbSecurityModel; std::unique_ptr settings; sys::TimerHandle transferTimer; std::unique_ptr btMsgHandler; + + static constexpr unsigned int DefaultLogFlushTimeoutInMs = 1000U; }; namespace sys diff --git a/module-services/service-evtmgr/EventManager.cpp b/module-services/service-evtmgr/EventManager.cpp index 5c5af1d403f10680a749a487ec9df341304eed7c..1e045a97a0adbca5b5cdafcfb9c8381f33ac9e7e 100644 --- a/module-services/service-evtmgr/EventManager.cpp +++ b/module-services/service-evtmgr/EventManager.cpp @@ -45,11 +45,12 @@ #include #include #include +#include namespace { - constexpr auto loggerDelayMs = 1000 * 60 * 5; - constexpr auto loggerTimerName = "Logger"; + constexpr auto loggerDelayMs = 1000 * 60 * 5; + constexpr auto loggerTimerName = "Logger"; constexpr std::array sliderKeyCodes = { bsp::KeyCodes::SSwitchUp, bsp::KeyCodes::SSwitchMid, bsp::KeyCodes::SSwitchDown}; @@ -281,6 +282,13 @@ sys::ReturnCodes EventManager::InitHandler() processTimezoneRequest(message->getTimezone()); return sys::MessageNone{}; }); + + connect(typeid(sevm::FlushLogsRequest), [&]([[maybe_unused]] sys::Message *msg) { + if (auto ret = dumpLogsToFile(); ret >= 0) { + return std::make_shared(true, ret); + } + return std::make_shared(false); + }); // initialize keyboard worker EventWorker = std::make_unique(this); @@ -376,15 +384,14 @@ void EventManager::handleKeyMoveEvent(RawKey key) } } -void EventManager::dumpLogsToFile() +int 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()); - } + const auto ts = cpp_freertos::Ticks::TicksToMs(cpp_freertos::Ticks::GetTicks()); + + LOG_DEBUG("Log flush timestamp: %d", static_cast(ts)); + + return Log::Logger::get().dumpToFile(std::move(logPath)); } void EventManager::handleMinuteUpdate(time_t timestamp) diff --git a/module-services/service-evtmgr/service-evtmgr/EVMessages.hpp b/module-services/service-evtmgr/service-evtmgr/EVMessages.hpp index d3735b02fbfb65c921af794a3f4e1f1012dfca58..aa1549f7cd54d01f237ddca13a630d222042acbb 100644 --- a/module-services/service-evtmgr/service-evtmgr/EVMessages.hpp +++ b/module-services/service-evtmgr/service-evtmgr/EVMessages.hpp @@ -138,4 +138,18 @@ namespace sevm std::chrono::milliseconds repetitionTime; }; + class FlushLogsRequest : public sys::DataMessage + {}; + + class FlushLogsResponse : public sys::ResponseMessage + { + public: + FlushLogsResponse(bool retCode, int retData = 0) + : sys::ResponseMessage(sys::ReturnCodes::Success, MessageType::MessageTypeUninitialized), retCode(retCode), + data(retData){}; + + const bool retCode{}; + const int data{}; + }; + } /* namespace sevm*/ diff --git a/module-services/service-evtmgr/service-evtmgr/EventManager.hpp b/module-services/service-evtmgr/service-evtmgr/EventManager.hpp index a55f439f8ee9369f53e3548f88b0179f313f81c8..74deb7edf827a3389dd0e5b5cbce08809eb920e2 100644 --- a/module-services/service-evtmgr/service-evtmgr/EventManager.hpp +++ b/module-services/service-evtmgr/service-evtmgr/EventManager.hpp @@ -79,7 +79,10 @@ class EventManager : public sys::Service sys::ReturnCodes SwitchPowerModeHandler(const sys::ServicePowerMode mode) override final; - void dumpLogsToFile(); + /// @return: < 0 - An error occurred during log flush + /// @return: 0 - Log file reached max size + /// @return: 1 - Logs flushed successflully + int dumpLogsToFile(); /** * @brief Sends request to application manager to switch from current application to specific window in application diff --git a/module-utils/log/Logger.cpp b/module-utils/log/Logger.cpp index d07e150ec1ca7f44bc4db0fff8120b661044a98b..34eb3a83ff17fabba0b26f2bfd900d38dc4772f1 100644 --- a/module-utils/log/Logger.cpp +++ b/module-utils/log/Logger.cpp @@ -118,4 +118,42 @@ namespace Log return loggerBufferCurrentPos; } + + /// @param logPath: file path to store the log + /// @return: < 0 - error occured during log flush + /// @return: 0 - log flush did not happen + /// @return: 1 - log flush successflul + auto Logger::dumpToFile(std::filesystem::path logPath) -> int + { + int status = 0; + const bool dumpLog = + !(std::filesystem::exists(logPath) && std::filesystem::file_size(logPath) > MAX_LOG_FILE_SIZE); + if (!dumpLog) { + LOG_DEBUG("Flush skipped"); + return 0; + } + + { + status = 1; + + const auto &logs = getLogs(); + + LockGuard lock(mutex); + std::fstream logFile(logPath, std::fstream::out | std::fstream::app); + + if (!logFile.good()) { + status = -EIO; + } + + logFile.write(logs.data(), logs.size()); + if (logFile.bad()) { + status = -EIO; + } + } + + LOG_DEBUG("Flush ended with status: %d", status); + + return status; + } + }; // namespace Log diff --git a/module-utils/log/Logger.hpp b/module-utils/log/Logger.hpp index 87c78eafa1ab0a26ee86d0c6aeaf40158de3e571..c845a69fe0dc9063a40122396d903b6136844bee 100644 --- a/module-utils/log/Logger.hpp +++ b/module-utils/log/Logger.hpp @@ -11,6 +11,7 @@ #include #include #include +#include namespace Log { @@ -35,6 +36,7 @@ namespace Log auto log(logger_level level, const char *file, int line, const char *function, const char *fmt, va_list args) -> int; auto logAssert(const char *fmt, va_list args) -> int; + auto dumpToFile(std::filesystem::path logPath) -> int; static constexpr auto CRIT_STR = "CRIT"; static constexpr auto IRQ_STR = "IRQ"; diff --git a/test/harness b/test/harness index b1ae209e9c257f8f62b3023ca30a361bd4d01e21..eecee32772ba2f7ad838535bc1fc99e707205d8e 160000 --- a/test/harness +++ b/test/harness @@ -1 +1 @@ -Subproject commit b1ae209e9c257f8f62b3023ca30a361bd4d01e21 +Subproject commit eecee32772ba2f7ad838535bc1fc99e707205d8e