diff options
Diffstat (limited to 'vespalog')
-rw-r--r-- | vespalog/CMakeLists.txt | 1 | ||||
-rw-r--r-- | vespalog/src/test/log_message/CMakeLists.txt | 9 | ||||
-rw-r--r-- | vespalog/src/test/log_message/log_message_test.cpp | 254 | ||||
-rw-r--r-- | vespalog/src/vespa/log/CMakeLists.txt | 2 | ||||
-rw-r--r-- | vespalog/src/vespa/log/exceptions.cpp | 20 | ||||
-rw-r--r-- | vespalog/src/vespa/log/exceptions.h | 17 | ||||
-rw-r--r-- | vespalog/src/vespa/log/log_message.cpp | 142 | ||||
-rw-r--r-- | vespalog/src/vespa/log/log_message.h | 37 |
8 files changed, 482 insertions, 0 deletions
diff --git a/vespalog/CMakeLists.txt b/vespalog/CMakeLists.txt index 6aa9aac5133..a4a97105122 100644 --- a/vespalog/CMakeLists.txt +++ b/vespalog/CMakeLists.txt @@ -12,6 +12,7 @@ vespa_define_module( TESTS src/test + src/test/log_message src/test/simple src/test/threads ) diff --git a/vespalog/src/test/log_message/CMakeLists.txt b/vespalog/src/test/log_message/CMakeLists.txt new file mode 100644 index 00000000000..51c888f67f3 --- /dev/null +++ b/vespalog/src/test/log_message/CMakeLists.txt @@ -0,0 +1,9 @@ +# Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +vespa_add_executable(vespalog_log_message_test_app TEST + SOURCES + log_message_test.cpp + DEPENDS + vespalog + gtest +) +vespa_add_test(NAME vespalog_log_message_test_app COMMAND vespalog_log_message_test_app) diff --git a/vespalog/src/test/log_message/log_message_test.cpp b/vespalog/src/test/log_message/log_message_test.cpp new file mode 100644 index 00000000000..aedb96c8469 --- /dev/null +++ b/vespalog/src/test/log_message/log_message_test.cpp @@ -0,0 +1,254 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#include <gtest/gtest.h> +#include <vespa/log/log_message.h> +#include <vespa/log/exceptions.h> + +using LogLevel = ns_log::Logger::LogLevel; + +namespace ns_log { + +namespace { + +std::ostream & +add_time(std::ostream &os, double now) +{ + constexpr int64_t onegig = 1000000000; + int64_t now64 = now * onegig; + int64_t now64i = now64 / onegig; + int64_t now64r = now64 % onegig; + os << now64i << '.' << std::setw(6) << std::setfill('0') << (now64r / 1000) << + std::setw(0) << std::setfill(' '); + return os; +} + +std::string +build_logline(double now, std::string hostname, std::string pidString, std::string service, std::string component, std::string level, std::string payload) +{ + std::ostringstream os; + add_time(os, now) << '\t' << hostname << '\t' << pidString << '\t' << + service << '\t' << component << '\t' << level << '\t' << payload; + return os.str(); +} + +std::string +build_logline(double now, std::string remaining) +{ + std::ostringstream os; + add_time(os, now) << '\t' << remaining; + return os.str(); +} + +} + +class LogMessageTest : public ::testing::Test { +protected: + double _now; +public: + LogMessageTest() + : _now(0.0) + { + _now = time(nullptr); + } + ~LogMessageTest() { } +}; + +TEST_F(LogMessageTest, require_that_plain_entry_is_ok) +{ + std::string log_line = build_logline(_now, "localhost", "10/20", "test", "testrunner", "warning", "hello world"); + LogMessage message; + message.parse_log_line(log_line); + EXPECT_EQ(int64_t(_now * 1000000000), message.time_nanos()); + EXPECT_EQ("localhost", message.hostname()); + EXPECT_EQ(10, message.process_id()); + EXPECT_EQ(20, message.thread_id()); + EXPECT_EQ("test", message.service()); + EXPECT_EQ("testrunner", message.component()); + EXPECT_EQ(LogLevel::warning, message.level()); + EXPECT_EQ("hello world", message.payload()); +} + +TEST_F(LogMessageTest, require_that_tab_at_start_of_line_fails) +{ + std::string log_line = "\t"; + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 1st tab: \t"), e.what()); + } +} + +TEST_F(LogMessageTest, require_that_no_tab_after_time_fails) +{ + std::string log_line = "10"; + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 1st tab: 10"), e.what()); + } +} + +TEST_F(LogMessageTest, require_that_malformed_time_fails) +{ + std::string log_line = "10x\t"; + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad time field: 10x"), e.what()); + } +} + +TEST_F(LogMessageTest, require_that_very_old_time_fails) +{ + std::string log_line = build_logline(_now - 101 * 24 * 3600, ""); + std::string time_field = log_line.substr(0, log_line.size() - 1); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("time > 100 days in the past: ") + time_field, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_very_future_time_fails) +{ + std::string log_line = build_logline(_now + 11 * 24 * 3600, ""); + std::string time_field = log_line.substr(0, log_line.size() - 1); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("time > 10 days in the future: ") + time_field, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_no_tab_after_hostname_fails) +{ + std::string log_line = build_logline(_now, "localhost"); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 2nd tab: ") + log_line, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_no_tab_after_pid_fails) +{ + std::string log_line = build_logline(_now, "localhost\t10/20"); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 3rd tab: ") + log_line, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_malformed_pid_fails) +{ + std::string log_line = build_logline(_now, "localhost\tx\t"); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad pid field: x"), e.what()); + } +} + +TEST_F(LogMessageTest, require_that_no_tab_after_service_fails) +{ + std::string log_line = build_logline(_now, "localhost\t10\t"); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 4th tab: ") + log_line, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_no_tab_after_component_fails) +{ + std::string log_line = build_logline(_now, "localhost\t10\ttest\t"); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 5th tab: ") + log_line, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_empty_component_fails) +{ + std::string log_line = build_logline(_now, "localhost\t10\ttest\t\t"); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 5th tab: ") + log_line, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_no_tab_after_level_fails) +{ + std::string log_line = build_logline(_now, "localhost\t10\ttest\ttestrunner\t"); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 6th tab: ") + log_line, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_empty_level_fails) +{ + std::string log_line = build_logline(_now, "localhost\t10\ttest\ttestrunner\t\t"); + LogMessage message; + try { + message.parse_log_line(log_line); + EXPECT_TRUE(false) << "Exception not thrown"; + } catch (BadLogLineException &e) { + EXPECT_EQ(std::string("Bad 6th tab: ") + log_line, e.what()); + } +} + +TEST_F(LogMessageTest, require_that_empty_payload_is_ok) +{ + std::string log_line = build_logline(_now, "localhost\t10\ttest\ttestrunner\twarning\t"); + LogMessage message; + message.parse_log_line(log_line); + EXPECT_EQ(10, message.process_id()); + EXPECT_EQ(0, message.thread_id()); + EXPECT_EQ(std::string(""), message.payload()); +} + +TEST_F(LogMessageTest, require_that_nonempty_payload_is_ok) +{ + std::string log_line = build_logline(_now, "localhost\t10\ttest\ttestrunner\twarning\thi"); + LogMessage message; + message.parse_log_line(log_line); + EXPECT_EQ(std::string("hi"), message.payload()); +} + +} + +int +main(int argc, char* argv[]) +{ + ::testing::InitGoogleTest(&argc, argv); + return RUN_ALL_TESTS(); +} diff --git a/vespalog/src/vespa/log/CMakeLists.txt b/vespalog/src/vespa/log/CMakeLists.txt index dccd17934d3..585d5927c1c 100644 --- a/vespalog/src/vespa/log/CMakeLists.txt +++ b/vespalog/src/vespa/log/CMakeLists.txt @@ -1,12 +1,14 @@ # Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. vespa_add_library(vespalog SOURCES + exceptions.cpp ${CMAKE_CURRENT_BINARY_DIR}/loglevelnames.cpp log.cpp bufferedlogger.cpp log-target-fd.cpp log-target-file.cpp log-target.cpp + log_message.cpp lock.cpp internal.cpp control-file.cpp diff --git a/vespalog/src/vespa/log/exceptions.cpp b/vespalog/src/vespa/log/exceptions.cpp new file mode 100644 index 00000000000..b72d0c7d3b5 --- /dev/null +++ b/vespalog/src/vespa/log/exceptions.cpp @@ -0,0 +1,20 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#include "exceptions.h" + +namespace ns_log { + +BadLogLineException::BadLogLineException(std::string message) + : _message(std::move(message)) +{ +} + +BadLogLineException::~BadLogLineException() = default; + +const char* +BadLogLineException::what() const noexcept +{ + return _message.c_str(); +} + +} diff --git a/vespalog/src/vespa/log/exceptions.h b/vespalog/src/vespa/log/exceptions.h new file mode 100644 index 00000000000..f00322047f1 --- /dev/null +++ b/vespalog/src/vespa/log/exceptions.h @@ -0,0 +1,17 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#include <exception> +#include <string> + +namespace ns_log { + +class BadLogLineException : public std::exception +{ + std::string _message; +public: + BadLogLineException(std::string message); + ~BadLogLineException() override; + const char *what() const noexcept override; +}; + +} diff --git a/vespalog/src/vespa/log/log_message.cpp b/vespalog/src/vespa/log/log_message.cpp new file mode 100644 index 00000000000..6e3584bafc3 --- /dev/null +++ b/vespalog/src/vespa/log/log_message.cpp @@ -0,0 +1,142 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#include "log_message.h" +#include "exceptions.h" +#include <locale> +#include <sstream> + +namespace ns_log { + +namespace { + +std::locale clocale("C"); + +[[noreturn]] void +bad_tab(const char *tab_name, std::string_view log_line) +{ + std::ostringstream os; + os << "Bad " << tab_name << " tab: " << log_line; + throw BadLogLineException(os.str()); +} + +std::string_view::size_type +find_tab(std::string_view log_line, const char *tab_name, std::string_view::size_type field_pos, bool allowEmpty) +{ + auto tab_pos = log_line.find('\t', field_pos); + if (tab_pos == std::string_view::npos || (tab_pos == field_pos && !allowEmpty)) { + bad_tab(tab_name, log_line); + } + return tab_pos; +} + +int64_t +parse_time_field(std::string time_field) +{ + std::istringstream time_stream(time_field); + time_stream.imbue(clocale); + double logtime = 0; + time_stream >> logtime; + if (!time_stream.eof()) { + std::ostringstream os; + os << "Bad time field: " << time_field; + throw BadLogLineException(os.str()); + } + time_t now = time(nullptr); + if (logtime - 864000 > now) { + std::ostringstream os; + os << "time > 10 days in the future: " << time_field; + throw BadLogLineException(os.str()); + } + if (logtime + 8640000 < now) { + std::ostringstream os; + os << "time > 100 days in the past: " << time_field; + throw BadLogLineException(os.str()); + } + return logtime * 1000000000; +} + +struct PidFieldParser +{ + int32_t _process_id; + int32_t _thread_id; + + PidFieldParser(std::string pid_field); +}; + +PidFieldParser::PidFieldParser(std::string pid_field) + : _process_id(0), + _thread_id(0) +{ + std::istringstream pid_stream(pid_field); + pid_stream.imbue(clocale); + pid_stream >> _process_id; + if (!pid_stream.eof() && pid_stream.good() && pid_stream.peek() == '/') { + pid_stream.get(); + pid_stream >> _thread_id; + } + if (!pid_stream.eof() || pid_stream.fail() || pid_stream.bad()) { + std::ostringstream os; + os << "Bad pid field: " << pid_field; + throw BadLogLineException(os.str()); + } +} + +} + +LogMessage::LogMessage() + : _time_nanos(0), + _hostname(), + _process_id(0), + _thread_id(0), + _service(), + _component(), + _level(Logger::LogLevel::NUM_LOGLEVELS), + _payload() +{ +} + +LogMessage::~LogMessage() = default; + + +/* + * Parse log line to populate log message class. The parsing is based on + * LegacyForwarder in logd. + */ +void +LogMessage::parse_log_line(std::string_view log_line) +{ + // time + auto tab_pos = find_tab(log_line, "1st", 0, false); + _time_nanos = parse_time_field(std::string(log_line.substr(0, tab_pos))); + + // hostname + auto field_pos = tab_pos + 1; + tab_pos = find_tab(log_line, "2nd", field_pos, true); + _hostname = log_line.substr(field_pos, tab_pos - field_pos); + + // pid + field_pos = tab_pos + 1; + tab_pos = find_tab(log_line, "3rd", field_pos, false); + PidFieldParser pid_field_parser(std::string(log_line.substr(field_pos, tab_pos - field_pos))); + _process_id = pid_field_parser._process_id; + _thread_id = pid_field_parser._thread_id; + + // service + field_pos = tab_pos + 1; + tab_pos = find_tab(log_line, "4th", field_pos, true); + _service = log_line.substr(field_pos, tab_pos - field_pos); + + // component + field_pos = tab_pos + 1; + tab_pos = find_tab(log_line, "5th", field_pos, false); + _component = log_line.substr(field_pos, tab_pos -field_pos); + + // level + field_pos = tab_pos + 1; + tab_pos = find_tab(log_line, "6th", field_pos, false); + std::string level_string(log_line.substr(field_pos, tab_pos - field_pos)); + _level = Logger::parseLevel(level_string.c_str()); + _payload = log_line.substr(tab_pos + 1); +} + +} diff --git a/vespalog/src/vespa/log/log_message.h b/vespalog/src/vespa/log/log_message.h new file mode 100644 index 00000000000..1ca052c9e7d --- /dev/null +++ b/vespalog/src/vespa/log/log_message.h @@ -0,0 +1,37 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#pragma once + +#include "log.h" +#include <string_view> + +namespace ns_log { + +/* + * Class containing a log message. + */ +class LogMessage { + int64_t _time_nanos; + std::string _hostname; + int32_t _process_id; + int32_t _thread_id; + std::string _service; + std::string _component; + Logger::LogLevel _level; + std::string _payload; + +public: + LogMessage(); + ~LogMessage(); + void parse_log_line(std::string_view log_line); + int64_t time_nanos() const { return _time_nanos; } + const std::string &hostname() const { return _hostname; } + int32_t process_id() const { return _process_id; } + int32_t thread_id() const { return _thread_id; } + const std::string &service() const { return _service;} + const std::string &component() const { return _component; } + Logger::LogLevel level() const { return _level; } + const std::string &payload() const { return _payload; } +}; + +} |