system/utest/syslog/syslog_socket_tests.cpp

// Copyright 2018 The Fuchsia Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include <fbl/string.h>
#include <fbl/unique_fd.h>
#include <lib/zx/socket.h>
#include <lib/syslog/global.h>
#include <lib/syslog/wire_format.h>
#include <unittest/unittest.h>

#include <errno.h>
#include <fcntl.h>
#include <poll.h>
#include <string.h>
#include <unistd.h>

#include <utility>

__BEGIN_CDECLS

// This does not come from header file as this function should only be used in
// tests and is not for general use.
void fx_log_reset_global(void);

__END_CDECLS

inline zx_status_t init_helper(zx_handle_t handle, const char** tags,
                               size_t ntags) {
    fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
                                 .console_fd = -1,
                                 .log_service_channel = handle,
                                 .tags = tags,
                                 .num_tags = ntags};

    return fx_log_init_with_config(&config);
}

namespace {

class Cleanup {
public:
    Cleanup() { fx_log_reset_global(); }
    ~Cleanup() { fx_log_reset_global(); }
};

} // namespace

bool ends_with(const char* str, const char* suffix) {
    size_t str_len = strlen(str);
    size_t suffix_len = strlen(suffix);
    if (str_len < suffix_len) {
        return false;
    }
    str += str_len - suffix_len;
    return strcmp(str, suffix) == 0;
}

bool output_compare_helper(zx::socket local, fx_log_severity_t severity,
                           const char* msg, const char** tags, int num_tags) {
    fx_log_packet_t packet;
    ASSERT_EQ(ZX_OK, local.read(0, &packet, sizeof(packet), nullptr));
    EXPECT_EQ(severity, packet.metadata.severity);
    int pos = 0;
    for (int i = 0; i < num_tags; i++) {
        const char* tag = tags[i];
        auto tag_len = static_cast<int8_t>(strlen(tag));
        ASSERT_EQ(tag_len, packet.data[pos]);
        pos++;
        ASSERT_BYTES_EQ((uint8_t*)tag, (uint8_t*)packet.data + pos, tag_len, "");
        pos += tag_len;
    }
    ASSERT_EQ(0, packet.data[pos]);
    pos++;
    EXPECT_STR_EQ(msg, packet.data + pos, "");
    return true;
}

bool TestLogSimpleWrite(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
    const char* msg = "test message";
    FX_LOG(INFO, nullptr, msg);
    output_compare_helper(std::move(local), FX_LOG_INFO, msg, nullptr, 0);
    END_TEST;
}

bool TestLogWrite(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
    FX_LOGF(INFO, nullptr, "%d, %s", 10, "just some number");
    output_compare_helper(std::move(local), FX_LOG_INFO, "10, just some number",
                          nullptr, 0);
    END_TEST;
}

bool TestLogPreprocessedMessage(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
    FX_LOG(INFO, nullptr, "%d, %s");
    output_compare_helper(std::move(local), FX_LOG_INFO, "%d, %s",
                          nullptr, 0);
    END_TEST;
}

static zx_status_t GetAvailableBytes(const zx::socket& socket,
                                     size_t* out_available) {
    zx_info_socket_t info = {};
    zx_status_t status = socket.get_info(ZX_INFO_SOCKET, &info, sizeof(info),
                                         nullptr, nullptr);
    if (status != ZX_OK) {
        return status;
    }
    *out_available = info.rx_buf_available;
    return ZX_OK;
}

bool TestLogSeverity(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));

    FX_LOG_SET_SEVERITY(WARNING);
    FX_LOGF(INFO, nullptr, "%d, %s", 10, "just some number");
    size_t outstanding_bytes = 10u; // init to non zero value.
    ASSERT_EQ(ZX_OK, GetAvailableBytes(local, &outstanding_bytes));
    EXPECT_EQ(0u, outstanding_bytes);

    FX_LOGF(WARNING, nullptr, "%d, %s", 10, "just some number");
    output_compare_helper(std::move(local), FX_LOG_WARNING,
                          "10, just some number", nullptr, 0);
    END_TEST;
}

bool TestLogWriteWithTag(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
    FX_LOGF(INFO, "tag", "%d, %s", 10, "just some string");
    const char* tags[] = {"tag"};
    output_compare_helper(std::move(local), FX_LOG_INFO, "10, just some string",
                          tags, 1);
    END_TEST;
}

bool TestLogWriteWithGlobalTag(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    const char* gtags[] = {"gtag"};
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 1));
    FX_LOGF(INFO, "tag", "%d, %s", 10, "just some string");
    const char* tags[] = {"gtag", "tag"};
    output_compare_helper(std::move(local), FX_LOG_INFO, "10, just some string",
                          tags, 2);
    END_TEST;
}

bool TestLogWriteWithMultiGlobalTag(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    const char* gtags[] = {"gtag", "gtag2"};
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 2));
    FX_LOGF(INFO, "tag", "%d, %s", 10, "just some string");
    const char* tags[] = {"gtag", "gtag2", "tag"};
    output_compare_helper(std::move(local), FX_LOG_INFO, "10, just some string",
                          tags, 3);
    END_TEST;
}

bool TestLogFallback(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    const char* gtags[] = {"gtag", "gtag2"};
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 2));

    int pipefd[2];
    EXPECT_EQ(pipe2(pipefd, O_NONBLOCK), 0);
    fbl::unique_fd fd_to_close1(pipefd[0]);
    fbl::unique_fd fd_to_close2(pipefd[1]);
    fx_logger_activate_fallback(fx_log_get_logger(), pipefd[0]);

    FX_LOGF(INFO, "tag", "%d, %s", 10, "just some string");

    char buf[256];
    size_t n = read(pipefd[1], buf, sizeof(buf));
    EXPECT_GT(n, 0u);
    buf[n] = 0;
    EXPECT_TRUE(ends_with(buf, "[gtag, gtag2, tag] INFO: 10, just some string\n"), buf);
    END_TEST;
}

bool TestMsgLengthLimit(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    const char* gtags[] = {"gtag", "gtag2"};
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 2));
    char msg[2048] = {0};
    memset(msg, 'a', sizeof(msg) - 1);
    FX_LOGF(INFO, "tag", "%s", msg);
    fx_log_packet_t packet;
    int msg_size = sizeof(packet.data) - 4 - 12;
    char expected[msg_size];
    memset(expected, 'a', msg_size - 4);
    memset(expected + msg_size - 4, '.', 3);
    expected[msg_size - 1] = 0;
    const char* tags[] = {"gtag", "gtag2", "tag"};
    output_compare_helper(std::move(local), FX_LOG_INFO, expected, tags, 3);
    END_TEST;
}

bool TestMsgLengthLimitForPreprocessedMsg(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    const char* gtags[] = {"gtag", "gtag2"};
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 2));
    char msg[2048] = {0};
    memset(msg, 'a', sizeof(msg) - 1);
    msg[0] = '%';
    msg[1] = 's';
    FX_LOG(INFO, "tag", msg);
    fx_log_packet_t packet;
    int msg_size = sizeof(packet.data) - 4 - 12;
    char expected[msg_size];
    memset(expected, 'a', msg_size - 4);
    expected[0] = '%';
    expected[1] = 's';
    memset(expected + msg_size - 4, '.', 3);
    expected[msg_size - 1] = 0;
    const char* tags[] = {"gtag", "gtag2", "tag"};
    output_compare_helper(std::move(local), FX_LOG_INFO, expected, tags, 3);
    END_TEST;
}

bool TestTagLengthLimit(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    char gtags_buffer[FX_LOG_MAX_TAGS][FX_LOG_MAX_TAG_LEN + 1];
    memset(gtags_buffer, 't', sizeof(gtags_buffer));
    const char* gtags[FX_LOG_MAX_TAGS];
    for (int i = 0; i < FX_LOG_MAX_TAGS; i++) {
        gtags_buffer[i][0] = static_cast<char>(49 + i); // '1' + i
        gtags_buffer[i][FX_LOG_MAX_TAG_LEN] = 0;
        gtags[i] = gtags_buffer[i];
    }
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, FX_LOG_MAX_TAGS));

    char tag[FX_LOG_MAX_TAG_LEN + 1];
    memcpy(tag, gtags[FX_LOG_MAX_TAGS - 1], sizeof(tag));
    tag[0]++;
    char msg[] = "some text";
    FX_LOGF(INFO, tag, "%s", msg);
    const char* tags[FX_LOG_MAX_TAGS + 1];
    for (int i = 0; i < FX_LOG_MAX_TAGS; i++) {
        gtags_buffer[i][FX_LOG_MAX_TAG_LEN - 1] = 0;
        tags[i] = gtags_buffer[i];
    }
    tag[FX_LOG_MAX_TAG_LEN - 1] = 0;
    tags[FX_LOG_MAX_TAGS] = tag;
    output_compare_helper(std::move(local), FX_LOG_INFO, msg, tags,
                          FX_LOG_MAX_TAGS + 1);
    END_TEST;
}

bool TestVlogSimpleWrite(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
    const char* msg = "test message";
    FX_LOG_SET_VERBOSITY(1);
    FX_VLOG(1, nullptr, msg);
    output_compare_helper(std::move(local), -1, msg, nullptr, 0);
    END_TEST;
}

bool TestVlogWrite(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
    FX_LOG_SET_VERBOSITY(1);
    FX_VLOGF(1, nullptr, "%d, %s", 10, "just some number");
    output_compare_helper(std::move(local), -1, "10, just some number",
                          nullptr, 0);
    END_TEST;
}

bool TestVlogWriteWithTag(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
    FX_LOG_SET_VERBOSITY(1);
    FX_VLOGF(1, "tag", "%d, %s", 10, "just some string");
    const char* tags[] = {"tag"};
    output_compare_helper(std::move(local), -1, "10, just some string",
                          tags, 1);
    END_TEST;
}

bool TestLogVerbosity(void) {
    BEGIN_TEST;
    Cleanup cleanup;
    zx::socket local, remote;
    EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
    ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));

    FX_VLOGF(1, nullptr, "%d, %s", 10, "just some number");
    size_t outstanding_bytes = 10u; // init to non zero value.
    ASSERT_EQ(ZX_OK, GetAvailableBytes(local, &outstanding_bytes));
    EXPECT_EQ(0u, outstanding_bytes);

    FX_VLOGF(1, nullptr, "%d, %s", 10, "just some number");
    outstanding_bytes = 10u; // init to non zero value.
    ASSERT_EQ(ZX_OK, GetAvailableBytes(local, &outstanding_bytes));
    EXPECT_EQ(0u, outstanding_bytes);

    FX_LOG_SET_VERBOSITY(2);
    FX_VLOGF(1, nullptr, "%d, %s", 10, "just some number");
    output_compare_helper(std::move(local), -1,
                          "10, just some number", nullptr, 0);
    END_TEST;
}

BEGIN_TEST_CASE(syslog_socket_tests)
RUN_TEST(TestLogSimpleWrite)
RUN_TEST(TestLogWrite)
RUN_TEST(TestLogPreprocessedMessage)
RUN_TEST(TestLogSeverity)
RUN_TEST(TestLogWriteWithTag)
RUN_TEST(TestLogWriteWithGlobalTag)
RUN_TEST(TestLogWriteWithMultiGlobalTag)
RUN_TEST(TestLogFallback)
RUN_TEST(TestVlogSimpleWrite)
RUN_TEST(TestVlogWrite)
RUN_TEST(TestVlogWriteWithTag)
RUN_TEST(TestLogVerbosity)
END_TEST_CASE(syslog_socket_tests)

BEGIN_TEST_CASE(syslog_socket_tests_edge_cases)
RUN_TEST(TestMsgLengthLimit)
RUN_TEST(TestTagLengthLimit)
RUN_TEST(TestMsgLengthLimitForPreprocessedMsg)
END_TEST_CASE(syslog_socket_tests_edge_cases)