Add LogMessage class to vespalog.

7 files changed, 481 insertions, 0 deletions

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; }
+};
+
+}