blob: d77c9a4bbe12d2356264215bc97fd7340614ed4b [file] [log] [blame]
// 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 <errno.h>
#include <fcntl.h>
#include <fidl/fuchsia.logger/cpp/wire.h>
#include <lib/syslog/global.h>
#include <lib/zx/socket.h>
#include <poll.h>
#include <stdlib.h>
#include <unistd.h>
#include <zircon/errors.h>
#include <climits>
#include <fbl/string_printf.h>
#include <zxtest/zxtest.h>
#include "zircon/system/ulib/syslog/helpers.h"
namespace {
const char* kFileName = syslog::internal::StripPath(__FILE__);
const char* kFilePath = syslog::internal::StripDots(__FILE__);
constexpr std::array<const char*, FX_LOG_MAX_TAGS + 1> kTooManyTags = {"1", "2", "3", "4", "5"};
bool ends_with(const char* str, const fbl::String& suffix) {
size_t str_len = strlen(str);
size_t suffix_len = suffix.size();
if (str_len < suffix_len) {
return false;
}
str += str_len - suffix_len;
return strcmp(str, suffix.c_str()) == 0;
}
void smallest_unused_fd(int* fd_out) {
for (int fd = 0; fd < INT_MAX; ++fd) {
if (fcntl(fd, F_GETFD, nullptr) < 0) {
ASSERT_EQ(errno, EBADF, "%s", strerror(errno));
*fd_out = fd;
return;
}
}
FAIL("did not find unused FD");
}
zx_status_t init_helper(int fd, const char** tags, size_t ntags) {
fx_logger_config_t config = {
.min_severity = FX_LOG_INFO,
.console_fd = fd,
.tags = tags,
.num_tags = ntags,
};
return fx_log_reconfigure(&config);
}
// Ensure accessing the global logger is safe when a global object is being torn down.
class LogDuringTeardownTest {
public:
~LogDuringTeardownTest() {
// This should not crash.
FX_LOG(INFO, NULL, "message");
}
} g_log_during_teardown;
TEST(SyslogTests, test_log_init_with_socket) {
zx::socket socket0, socket1;
EXPECT_OK(zx::socket::create(0, &socket0, &socket1));
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_socket = socket1.release(),
.tags = nullptr,
.num_tags = 0};
EXPECT_OK(fx_log_reconfigure(&config), "");
}
TEST(SyslogTests, test_log_enabled_macro) {
zx::socket socket0, socket1;
EXPECT_OK(zx::socket::create(0, &socket0, &socket1));
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_socket = socket1.release(),
.tags = nullptr,
.num_tags = 0};
EXPECT_OK(fx_log_reconfigure(&config), "");
if (FX_VLOG_IS_ENABLED(4)) {
EXPECT_TRUE(false, "control should not reach this line");
}
if (!FX_LOG_IS_ENABLED(INFO)) {
EXPECT_TRUE(false, "control should not reach this line");
}
if (!FX_LOG_IS_ENABLED(ERROR)) {
EXPECT_TRUE(false, "control should not reach this line");
}
}
TEST(SyslogTests, test_log_simple_write) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
FX_LOG(INFO, NULL, "test message");
char buf[256];
size_t n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
buf[n] = 0;
EXPECT_TRUE(ends_with(buf, "test message\n"), "%s", buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_log_write) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
int line = __LINE__ + 1;
FX_LOGF(INFO, NULL, "%d, %s", 10, "just some number");
char buf[256];
size_t n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
buf[n] = 0;
EXPECT_TRUE(
ends_with(buf, fbl::StringPrintf("INFO: [%s(%d)] 10, just some number\n", kFileName, line)),
"%s", buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_log_preprocessed_message) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
int line = __LINE__ + 1;
FX_LOG(INFO, NULL, "%d, %s");
char buf[256];
size_t n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
buf[n] = 0;
EXPECT_TRUE(ends_with(buf, fbl::StringPrintf("INFO: [%s(%d)] %%d, %%s\n", kFileName, line)), "%s",
buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_log_severity) {
struct pollfd fd;
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
FX_LOG_SET_SEVERITY(WARNING);
FX_LOGF(INFO, NULL, "%d, %s", 10, "just some number");
fd.fd = pipefd[1];
fd.events = POLLIN;
EXPECT_EQ(poll(&fd, 1, 1), 0, "");
close(pipefd[1]);
}
TEST(SyslogTests, test_log_severity_invalid) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
fx_logger_t* logger = fx_log_get_logger();
EXPECT_EQ(FX_LOG_INFO, fx_logger_get_min_severity(logger));
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_logger_set_min_severity(logger, FX_LOG_FATAL + 1));
EXPECT_EQ(FX_LOG_INFO, fx_logger_get_min_severity(logger));
}
TEST(SyslogTests, test_log_write_with_tag) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
int line = __LINE__ + 1;
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, fbl::StringPrintf("[tag] INFO: [%s(%d)] 10, just some string\n",
kFileName, line)),
"%s", buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_log_write_with_global_tag) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
const char* tags[] = {"gtag"};
EXPECT_OK(init_helper(pipefd[0], tags, 1), "");
int line = __LINE__ + 1;
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, fbl::StringPrintf("[gtag, tag] INFO: [%s(%d)] 10, just some string\n",
kFileName, line)),
"%s", buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_get_tags) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
const char* tags[] = {"gtag", "gTag"};
EXPECT_OK(init_helper(pipefd[0], tags, 2), "");
std::vector<std::string> logger_tags;
fx_logger_get_tags(
fx_log_get_logger(),
[](void* context, const char* tag) {
static_cast<std::vector<std::string>*>(context)->push_back(tag);
},
&logger_tags);
EXPECT_EQ(logger_tags.size(), 2);
EXPECT_EQ(logger_tags[0], "gtag");
EXPECT_EQ(logger_tags[1], "gTag");
close(pipefd[1]);
}
TEST(SyslogTests, test_log_write_with_multi_global_tag) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
const char* tags[] = {"gtag", "gtag2"};
EXPECT_OK(init_helper(pipefd[0], tags, 2), "");
int line = __LINE__ + 1;
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, fbl::StringPrintf("[gtag, gtag2, tag] INFO: [%s(%d)] 10, just some string\n",
kFileName, line)),
"%s", buf);
close(pipefd[1]);
}
TEST(SyslogTestsEdgeCases, test_global_tag_limit) {
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, init_helper(-1, nullptr, FX_LOG_MAX_TAGS + 1), "");
}
TEST(SyslogTestsEdgeCases, test_msg_length_limit) {
constexpr size_t kMessageSize = fuchsia_logger::wire::kMaxDatagramLenBytes + 5;
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
char msg[kMessageSize] = {0};
char buf[kMessageSize] = {0};
memset(msg, 'a', sizeof(msg) - 1);
FX_LOGF(INFO, NULL, "%s", msg);
size_t n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
msg[n] = 0;
EXPECT_TRUE(ends_with(buf, "a...\n"), "%s", buf);
msg[0] = '%';
msg[1] = 's';
FX_LOG(INFO, NULL, msg);
n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
msg[n] = 0;
EXPECT_TRUE(ends_with(buf, "a...\n"), "%s", buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_vlog_simple_write) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
FX_LOG_SET_VERBOSITY(5); // INFO - 5
int line = __LINE__ + 1;
FX_VLOG(5, NULL, "test message");
char buf[256];
size_t n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
buf[n] = 0;
EXPECT_TRUE(
ends_with(buf, fbl::StringPrintf("VLOG(5): [%s(%d)] test message\n", kFileName, line)), "%s",
buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_vlog_write) {
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
FX_LOG_SET_VERBOSITY(1); // INFO - 1
int line = __LINE__ + 1;
FX_VLOGF(1, NULL, "%d, %s", 10, "just some number");
char buf[256];
size_t n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
buf[n] = 0;
EXPECT_TRUE(ends_with(buf, fbl::StringPrintf("VLOG(1): [%s(%d)] 10, just some number\n",
kFileName, line)),
"%s", buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_log_reconfiguration) {
// Initialize with no tags.
int pipefd[2];
EXPECT_NE(pipe2(pipefd, O_NONBLOCK), -1, "");
EXPECT_OK(init_helper(pipefd[0], nullptr, 0), "");
int line = __LINE__ + 1;
FX_LOG(INFO, NULL, "Hi");
char buf[256];
size_t n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
buf[n] = 0;
EXPECT_TRUE(ends_with(buf, fbl::StringPrintf("INFO: [%s(%d)] Hi\n", kFileName, line)), "%s", buf);
// Now reconfigure the logger and add tags.
const char* tags[] = {"tag1", "tag2"};
EXPECT_OK(init_helper(-1, tags, 2), "");
line = __LINE__ + 1;
FX_LOG(INFO, NULL, "Hi");
n = read(pipefd[1], buf, sizeof(buf));
EXPECT_GT(n, 0u, "");
buf[n] = 0;
EXPECT_TRUE(
ends_with(buf, fbl::StringPrintf("[tag1, tag2] INFO: [%s(%d)] Hi\n", kFileName, line)), "%s",
buf);
close(pipefd[1]);
}
TEST(SyslogTests, test_log_dont_dup) {
// Remember the current lowest ununsed fd.
int fd_before;
ASSERT_NO_FATAL_FAILURE(smallest_unused_fd(&fd_before));
// Create a logger
fx_logger_t* logger;
zx_status_t status;
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_socket = ZX_HANDLE_INVALID,
.tags = nullptr,
.num_tags = 0};
status = fx_logger_create(&config, &logger);
ASSERT_OK(status);
// No fd must be taken by the logger.
int fd_after;
ASSERT_NO_FATAL_FAILURE(smallest_unused_fd(&fd_after));
EXPECT_EQ(fd_before, fd_after);
// Cleanup
fx_logger_destroy(logger);
}
TEST(SyslogTests, test_fx_logger_create_with_null_config) {
fx_logger_t* logger;
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_logger_create(nullptr, &logger));
}
TEST(SyslogTests, test_fx_logger_create_with_null_output_pointer) {
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_socket = ZX_HANDLE_INVALID,
.tags = nullptr,
.num_tags = 0};
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_logger_create(&config, nullptr));
}
TEST(SyslogTests, test_fx_logger_reconfigure_with_null_config) {
// Create a logger
fx_logger_t* logger;
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_socket = ZX_HANDLE_INVALID,
.tags = nullptr,
.num_tags = 0};
ASSERT_OK(fx_logger_create(&config, &logger));
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_logger_reconfigure(logger, nullptr));
fx_logger_destroy(logger);
}
TEST(SyslogTests, test_log_sink_channel_closed_on_create_fail) {
EXPECT_LT(FX_LOG_MAX_TAGS, kTooManyTags.size());
zx::socket local, remote;
EXPECT_OK(zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
const zx_handle_t passed_handle = remote.release();
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_channel = passed_handle,
.log_sink_socket = ZX_HANDLE_INVALID,
.tags = kTooManyTags.data(),
.num_tags = kTooManyTags.size()};
// This should fail because there are too many tags, and closing the
// handle should fail because it is already closed.
fx_logger_t* logger;
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_logger_create(&config, &logger));
EXPECT_NE(ZX_HANDLE_INVALID, passed_handle);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_handle));
}
TEST(SyslogTests, test_log_sink_socket_closed_on_create_fail) {
EXPECT_LT(FX_LOG_MAX_TAGS, kTooManyTags.size());
zx::socket local, remote;
EXPECT_OK(zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
const zx_handle_t passed_handle = remote.release();
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_channel = ZX_HANDLE_INVALID,
.log_sink_socket = passed_handle,
.tags = kTooManyTags.data(),
.num_tags = kTooManyTags.size()};
// This should fail because there are too many tags, and closing the
// handle should fail because it is already closed.
fx_logger_t* logger;
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_logger_create(&config, &logger));
EXPECT_NE(ZX_HANDLE_INVALID, passed_handle);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_handle));
}
TEST(SyslogTests, test_both_handles_specified_fails_create_and_handles_closed) {
zx::socket local, remote;
EXPECT_OK(zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
const zx_handle_t passed_log_sink_channel = local.release();
const zx_handle_t passed_log_sink_socket = remote.release();
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_channel = passed_log_sink_channel,
.log_sink_socket = passed_log_sink_socket,
.tags = nullptr,
.num_tags = 0};
// This should fail because both handles were specified, and closing the
// handle should fail because it is already closed.
fx_logger_t* logger;
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_logger_create(&config, &logger));
EXPECT_NE(ZX_HANDLE_INVALID, passed_log_sink_channel);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_log_sink_channel));
EXPECT_NE(ZX_HANDLE_INVALID, passed_log_sink_socket);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_log_sink_socket));
}
TEST(SyslogTests, test_log_sink_channel_closed_on_reconfigure_fail) {
EXPECT_LT(FX_LOG_MAX_TAGS, kTooManyTags.size());
zx::socket local, remote;
EXPECT_OK(zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
const zx_handle_t passed_handle = remote.release();
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_channel = passed_handle,
.log_sink_socket = ZX_HANDLE_INVALID,
.tags = kTooManyTags.data(),
.num_tags = kTooManyTags.size()};
// This should fail because there are too many tags, and closing the
// handle should fail because it is already closed.
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_log_reconfigure(&config));
EXPECT_NE(ZX_HANDLE_INVALID, passed_handle);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_handle));
}
TEST(SyslogTests, test_log_sink_socket_closed_on_reconfigure_fail) {
EXPECT_LT(FX_LOG_MAX_TAGS, kTooManyTags.size());
zx::socket local, remote;
EXPECT_OK(zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
const zx_handle_t passed_handle = remote.release();
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_channel = ZX_HANDLE_INVALID,
.log_sink_socket = passed_handle,
.tags = kTooManyTags.data(),
.num_tags = kTooManyTags.size()};
// This should fail because there are too many tags, and closing the
// handle should fail because it is already closed.
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_log_reconfigure(&config));
EXPECT_NE(ZX_HANDLE_INVALID, passed_handle);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_handle));
}
TEST(SyslogTests, test_both_handles_specified_fails_reconfigure_and_handles_closed) {
zx::socket local, remote;
EXPECT_OK(zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
const zx_handle_t passed_log_sink_channel = local.release();
const zx_handle_t passed_log_sink_socket = remote.release();
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_channel = passed_log_sink_channel,
.log_sink_socket = passed_log_sink_socket,
.tags = nullptr,
.num_tags = 0};
// This should fail because both handles were specified, and closing the
// handle should fail because it is already closed.
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_log_reconfigure(&config));
EXPECT_NE(ZX_HANDLE_INVALID, passed_log_sink_channel);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_log_sink_channel));
EXPECT_NE(ZX_HANDLE_INVALID, passed_log_sink_socket);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_log_sink_socket));
}
#ifdef SYSLOG_STATIC
TEST(SyslogTests, test_create_with_log_sink_channel_not_supported) {
zx::socket local, remote;
EXPECT_OK(zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
const zx_handle_t passed_handle = remote.release();
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_channel = passed_handle,
.log_sink_socket = ZX_HANDLE_INVALID,
.tags = nullptr,
.num_tags = 0};
// This should fail because log_sink_channel is not supported, and closing the
// handle should fail because it is already closed.
fx_logger_t* logger;
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_logger_create(&config, &logger));
EXPECT_NE(ZX_HANDLE_INVALID, passed_handle);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_handle));
}
TEST(SyslogTests, test_reconfigure_with_log_sink_channel_not_supported) {
zx::socket local, remote;
EXPECT_OK(zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
const zx_handle_t passed_handle = remote.release();
fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
.console_fd = -1,
.log_sink_channel = passed_handle,
.log_sink_socket = ZX_HANDLE_INVALID,
.tags = nullptr,
.num_tags = 0};
// This should fail because log_sink_channel is not supported, and closing the
// handle should fail because it is already closed.
EXPECT_STATUS(ZX_ERR_INVALID_ARGS, fx_log_reconfigure(&config));
EXPECT_NE(ZX_HANDLE_INVALID, passed_handle);
EXPECT_STATUS(ZX_ERR_BAD_HANDLE, zx_handle_close(passed_handle));
}
#endif
} // namespace