From def5dbcfa99639957c3769bbb2eca550e287fc8c Mon Sep 17 00:00:00 2001 From: Mateusz Grzegorzek Date: Wed, 3 Mar 2021 13:20:56 +0100 Subject: [PATCH] [EGD-5908] Fix bug in Logger + add log unit test Because `vsnprintf` return value means: " The number of characters that would have been written if n had been sufficiently large, not counting the terminating null character. If an encoding error occurs, a negative number is returned. " `Logger` crashed when log msg was longer than LOGGER_BUFFER_SIZE. Checking `vsnprintf` return value solves this issue. --- enabled_unittests | 4 +++ module-utils/log/Logger.cpp | 34 ++++++++++++------ module-utils/log/Logger.hpp | 3 +- module-utils/log/log.cpp | 10 +++--- module-utils/log/log.hpp | 4 +-- module-utils/test/CMakeLists.txt | 28 ++++++--------- module-utils/test/test_log.cpp | 61 +++++++++++++++++++------------- module-utils/test/test_log2.cpp | 29 --------------- module-utils/test/test_log2.h | 16 --------- test/CMakeLists.txt | 6 ++-- test/mock-logs.cpp | 6 ++-- test/pytest/test_dom_dump.py | 1 - 12 files changed, 91 insertions(+), 111 deletions(-) delete mode 100644 module-utils/test/test_log2.cpp delete mode 100644 module-utils/test/test_log2.h diff --git a/enabled_unittests b/enabled_unittests index 2d497403de8e873d2116ab81f0931877e69f30c5..df9251d4195ab8949deb6ed59d2f5b45b30769da 100644 --- a/enabled_unittests +++ b/enabled_unittests @@ -287,6 +287,10 @@ TESTS_LIST["catch2-utils-duration"]=" Duration - display; " #--------- +TESTS_LIST["catch2-utils-log"]=" + Log tests; +" +#--------- TESTS_LIST["catch2-utils-loggerbuffer"]=" LoggerBuffer tests; " diff --git a/module-utils/log/Logger.cpp b/module-utils/log/Logger.cpp index 1a17798236f9b176b828dc8f5292b12b014668af..c51ffd86afca4f8e9a2023b819a710dd601fb76a 100644 --- a/module-utils/log/Logger.cpp +++ b/module-utils/log/Logger.cpp @@ -68,31 +68,45 @@ namespace Log auto _ = gsl::finally([this] { unlock(); }); loggerBufferCurrentPos = 0; - loggerBufferCurrentPos += vsnprintf(&loggerBuffer[loggerBufferCurrentPos], loggerBufferSizeLeft(), fmt, args); - logToDevice(device, loggerBuffer, loggerBufferCurrentPos); - return loggerBufferCurrentPos; + const auto sizeLeft = loggerBufferSizeLeft(); + const auto result = vsnprintf(&loggerBuffer[loggerBufferCurrentPos], sizeLeft, fmt, args); + if (0 <= result) { + const auto numOfBytesAddedToBuffer = static_cast(result); + loggerBufferCurrentPos += (numOfBytesAddedToBuffer < sizeLeft) ? numOfBytesAddedToBuffer : (sizeLeft - 1); + + logToDevice(device, loggerBuffer, loggerBufferCurrentPos); + return loggerBufferCurrentPos; + } + return -1; } - void Logger::log( - logger_level level, const char *file, int line, const char *function, const char *fmt, va_list args) + auto Logger::log( + logger_level level, const char *file, int line, const char *function, const char *fmt, va_list args) -> int { if (!filterLogs(level)) { - return; + return -1; } if (!lock()) { - return; + return -1; } auto _ = gsl::finally([this] { unlock(); }); loggerBufferCurrentPos = 0; addLogHeader(level, file, line, function); - loggerBufferCurrentPos += vsnprintf(&loggerBuffer[loggerBufferCurrentPos], loggerBufferSizeLeft(), fmt, args); - loggerBufferCurrentPos += snprintf(&loggerBuffer[loggerBufferCurrentPos], loggerBufferSizeLeft(), "\n"); + const auto sizeLeft = loggerBufferSizeLeft(); + const auto result = vsnprintf(&loggerBuffer[loggerBufferCurrentPos], sizeLeft, fmt, args); + if (0 <= result) { + const auto numOfBytesAddedToBuffer = static_cast(result); + loggerBufferCurrentPos += (numOfBytesAddedToBuffer < sizeLeft) ? numOfBytesAddedToBuffer : (sizeLeft - 1); + loggerBufferCurrentPos += snprintf(&loggerBuffer[loggerBufferCurrentPos], loggerBufferSizeLeft(), "\n"); - logToDevice(Device::DEFAULT, loggerBuffer, loggerBufferCurrentPos); + logToDevice(Device::DEFAULT, loggerBuffer, loggerBufferCurrentPos); + return loggerBufferCurrentPos; + } + return -1; } auto Logger::logAssert(const char *fmt, va_list args) -> int diff --git a/module-utils/log/Logger.hpp b/module-utils/log/Logger.hpp index 18be84f6a49368d0146de494e68d526bd456b1dd..a2ee524b5dc8fd5dd8f382860f8c4409ffff9179 100644 --- a/module-utils/log/Logger.hpp +++ b/module-utils/log/Logger.hpp @@ -30,7 +30,8 @@ namespace Log } void init(); auto log(Device device, const char *fmt, va_list args) -> int; - void log(logger_level level, const char *file, int line, const char *function, const char *fmt, va_list args); + 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; static constexpr auto CRIT_STR = "CRIT"; diff --git a/module-utils/log/log.cpp b/module-utils/log/log.cpp index 96f7aff34a9613d565ffddafdb4841d2b656c816..2d99984f5077966bc504b0683cc86d1c8bafb0d7 100644 --- a/module-utils/log/log.cpp +++ b/module-utils/log/log.cpp @@ -7,20 +7,22 @@ using Log::Logger; -void log_Printf(const char *fmt, ...) +int log_Printf(const char *fmt, ...) { va_list args; va_start(args, fmt); - Logger::get().log(Log::Device::DEFAULT, fmt, args); + const int result = Logger::get().log(Log::Device::DEFAULT, fmt, args); va_end(args); + return result; } -void log_Log(logger_level level, const char *file, int line, const char *function, const char *fmt, ...) +int log_Log(logger_level level, const char *file, int line, const char *function, const char *fmt, ...) { va_list args; va_start(args, fmt); - Logger::get().log(level, file, line, function, fmt, args); + const int result = Logger::get().log(level, file, line, function, fmt, args); va_end(args); + return result; } extern "C" diff --git a/module-utils/log/log.hpp b/module-utils/log/log.hpp index 1640088312670b523584898437cdd7a2b97a9330..cd2ceb7dcba7e06342608c5bd1c41bf1985c2091 100644 --- a/module-utils/log/log.hpp +++ b/module-utils/log/log.hpp @@ -60,9 +60,9 @@ extern "C" /** * Forward declarations */ - void log_Log(logger_level level, const char *file, int line, const char *function, const char *fmt, ...) + int log_Log(logger_level level, const char *file, int line, const char *function, const char *fmt, ...) __attribute__((format(printf, 5, 6))); - void log_Printf(const char *fmt, ...) __attribute__((format(printf, 1, 2))); + int log_Printf(const char *fmt, ...) __attribute__((format(printf, 1, 2))); void log_WriteToDevice(const uint8_t *pBuffer, unsigned NumBytes); /** diff --git a/module-utils/test/CMakeLists.txt b/module-utils/test/CMakeLists.txt index 7b2ad68dfdf03a6aa67ea11e4e440109f2569348..6acc3f08b97da37a0538798cc7bb72b5b11bd489 100644 --- a/module-utils/test/CMakeLists.txt +++ b/module-utils/test/CMakeLists.txt @@ -90,6 +90,16 @@ add_catch2_executable( module-utils ) +# Log tests +add_catch2_executable( + NAME + utils-log + SRCS + test_log.cpp + LIBS + module-utils +) + # Logger buffer tests add_catch2_executable( NAME @@ -121,24 +131,6 @@ add_catch2_executable( module-db ) -########################################### -# Log functional tests project -project(test_module-utils_log VERSION 1.0 - DESCRIPTION "Module-utils log functional tests") - -add_executable( ${PROJECT_NAME} EXCLUDE_FROM_ALL - test_log.cpp - test_log2.cpp -) -add_test(NAME ${PROJECT_NAME} - COMMAND ${PROJECT_NAME} - WORKING_DIRECTORY ${CMAKE_BINARY_DIR} - ) -add_dependencies(check ${PROJECT_NAME}) - -target_include_directories(${PROJECT_NAME} PRIVATE "${CMAKE_CURRENT_LIST_DIR}/..") -target_link_libraries(${PROJECT_NAME} PRIVATE module-utils) - ########################################### # UTF8 functional tests projeet project(test_module-utils_utf8 VERSION 1.0 diff --git a/module-utils/test/test_log.cpp b/module-utils/test/test_log.cpp index 88dd443dd63225b37a12058c5f1c527f2514fd8c..05e90470bb2e6632ef2306f87fd0def89ca3e9f3 100644 --- a/module-utils/test/test_log.cpp +++ b/module-utils/test/test_log.cpp @@ -1,35 +1,46 @@ -// 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 -/* - * unittest_log.cpp - * - * Created on: 29 kwi 2019 - * Author: robert - */ +#define CATCH_CONFIG_MAIN // This tells Catch to provide a main() - only do this in one cpp file +#include #include "log/log.hpp" - -#include #include -#include "test_log2.h" - using namespace std; -int main() +TEST_CASE("Log tests") { - - cout << "RUNNING UNIT TEST FOR LOG" << endl; - - LOG_TRACE("This should be blue"); - LOG_DEBUG("This should be navy blue"); - LOG_INFO("This should be green"); - LOG_WARN("This should be yellow"); - LOG_ERROR("This should be red"); - LOG_FATAL("This should be purple"); - - log_test_function(); - - return 0; + int value = -423; + const char *carray = "carray"; + string str = "string"; + double double_value = 6.5323; + unsigned int unsigned_value = 7821; + constexpr auto big_array_size = LOGGER_BUFFER_SIZE + 2; + char big_array[big_array_size]; + memset(big_array, 'X', big_array_size); + big_array[big_array_size - 1] = '\0'; + + int loggerBufferSize = static_cast(LOGGER_BUFFER_SIZE); + int result = LOG_TRACE("value: %d", value); + REQUIRE(0 < result); + REQUIRE(result <= loggerBufferSize); + result = LOG_DEBUG("carray: %s", carray); + REQUIRE(0 < result); + REQUIRE(result <= loggerBufferSize); + result = LOG_INFO("str: %s", str.c_str()); + REQUIRE(0 < result); + REQUIRE(result <= loggerBufferSize); + result = LOG_WARN("double_value: %f", double_value); + REQUIRE(0 < result); + REQUIRE(result <= loggerBufferSize); + result = LOG_ERROR("unsigned_value: %u", unsigned_value); + REQUIRE(0 < result); + REQUIRE(result <= loggerBufferSize); + result = LOG_FATAL("big_array: %s", big_array); + REQUIRE(0 < result); + REQUIRE(result <= loggerBufferSize); + result = LOG_PRINTF("value: %d, carray: %s, double_value: %f", value, carray, double_value); + REQUIRE(0 < result); + REQUIRE(result <= loggerBufferSize); } diff --git a/module-utils/test/test_log2.cpp b/module-utils/test/test_log2.cpp deleted file mode 100644 index 928efeb5c245fc9c13c2d40c86c5b9c842cb17c5..0000000000000000000000000000000000000000 --- a/module-utils/test/test_log2.cpp +++ /dev/null @@ -1,29 +0,0 @@ -// Copyright (c) 2017-2020, Mudita Sp. z.o.o. All rights reserved. -// For licensing, see https://github.com/mudita/MuditaOS/LICENSE.md - -/* - * unittest_log2.cpp - * - * Created on: 29 kwi 2019 - * Author: robert - */ - -#include "log/log.hpp" - -#include -#include - -using namespace std; - -int log_test_function() -{ - - LOG_TRACE("This should be blue"); - LOG_DEBUG("This should be navy blue"); - LOG_INFO("This should be green"); - LOG_WARN("This should be yellow"); - LOG_ERROR("This should be red"); - LOG_FATAL("This should be purple"); - - return 0; -} diff --git a/module-utils/test/test_log2.h b/module-utils/test/test_log2.h deleted file mode 100644 index c3d08b3176d864f61f793c1c25d6895cd476fdd6..0000000000000000000000000000000000000000 --- a/module-utils/test/test_log2.h +++ /dev/null @@ -1,16 +0,0 @@ -// Copyright (c) 2017-2020, Mudita Sp. z.o.o. All rights reserved. -// For licensing, see https://github.com/mudita/MuditaOS/LICENSE.md - -/* - * unittest2_log.h - * - * Created on: 29 kwi 2019 - * Author: robert - */ - -#ifndef TEST_UNITTEST_LOG2_H_ -#define TEST_UNITTEST_LOG2_H_ - -int log_test_function(); - -#endif /* TEST_UNITTEST_LOG2_H_ */ diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index eb962ef254579f3b89fc9524df803b6ed649ed18..2bc67c735145dff2e18d58e142c9cb1d34439bb9 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -84,7 +84,7 @@ function(add_catch2_executable) set(_TESTNAME "catch2-${_TEST_ARGS_NAME}") if(NOT _TEST_ARGS_SRCS) - message(FATAL_ERROR "You must provide test sources for ${_TESTNAME}") + message(FATAL_ERROR "You must provide test sources for ${_TESTNAME}") endif(NOT _TEST_ARGS_SRCS) add_executable(${_TESTNAME} EXCLUDE_FROM_ALL ${_TEST_ARGS_SRCS}) @@ -93,10 +93,10 @@ function(add_catch2_executable) target_link_options(${_TESTNAME} PUBLIC "-fsanitize=address") # disable logs in unit tests - if (NOT ${ENABLE_TEST_LOGS}) + if (NOT ${ENABLE_TEST_LOGS} AND NOT ${_TESTNAME} STREQUAL "catch2-utils-log") target_sources(${_TESTNAME} PRIVATE ${ROOT_TEST_DIR}/mock-logs.cpp) target_sources(${_TESTNAME} PRIVATE ${ROOT_TEST_DIR}/mock-freertos-tls.cpp) - endif (NOT ${ENABLE_TEST_LOGS}) + endif (NOT ${ENABLE_TEST_LOGS} AND NOT ${_TESTNAME} STREQUAL "catch2-utils-log") target_link_libraries(${_TESTNAME} PRIVATE Catch2::Catch2) foreach(lib ${_TEST_ARGS_LIBS}) diff --git a/test/mock-logs.cpp b/test/mock-logs.cpp index e4670bc0cb25d8e236190b45153b558e6be707a8..dcb3395ab71c700bb7b1e9b2555a00a2cd89d2d2 100644 --- a/test/mock-logs.cpp +++ b/test/mock-logs.cpp @@ -3,17 +3,19 @@ #include #include -__attribute__((weak)) void log_Log( +__attribute__((weak)) int log_Log( logger_level level, const char *file, int line, const char *function, const char *fmt, ...) { va_list args; va_start(args, fmt); va_end(args); + return 0; } -__attribute__((weak)) void log_Printf(const char *fmt, ...) +__attribute__((weak)) int log_Printf(const char *fmt, ...) { va_list args; va_start(args, fmt); va_end(args); + return 0; } diff --git a/test/pytest/test_dom_dump.py b/test/pytest/test_dom_dump.py index 25fd576a42fcb0603fc9b1a788cd0ac0156989d4..922ba691b17d766f3d82f34f4a5c984f9c544621 100644 --- a/test/pytest/test_dom_dump.py +++ b/test/pytest/test_dom_dump.py @@ -1,7 +1,6 @@ import pytest from harness import log -@pytest.mark.skip("not working ;/") def test_get_dom(harness): body = {"ui": True, "getWindow": True} result = harness.endpoint_request("developerMode", "get", body)