diff --git a/.github/workflows/selfdrive_tests.yaml b/.github/workflows/selfdrive_tests.yaml index f04eaad86..46ab32c36 100644 --- a/.github/workflows/selfdrive_tests.yaml +++ b/.github/workflows/selfdrive_tests.yaml @@ -260,6 +260,7 @@ jobs: $UNIT_TEST tools/lib/tests && \ ./selfdrive/boardd/tests/test_boardd_usbprotocol && \ ./selfdrive/common/tests/test_util && \ + ./selfdrive/common/tests/test_swaglog && \ ./selfdrive/loggerd/tests/test_logger &&\ ./selfdrive/proclogd/tests/test_proclog && \ ./selfdrive/ui/replay/tests/test_replay && \ diff --git a/selfdrive/common/SConscript b/selfdrive/common/SConscript index 9b496fef7..21f609865 100644 --- a/selfdrive/common/SConscript +++ b/selfdrive/common/SConscript @@ -33,3 +33,4 @@ Export('_common', '_gpucommon', '_gpu_libs') if GetOption('test'): env.Program('tests/test_util', ['tests/test_util.cc'], LIBS=[_common]) + env.Program('tests/test_swaglog', ['tests/test_swaglog.cc'], LIBS=[_common, 'json11', 'zmq', 'pthread']) diff --git a/selfdrive/common/swaglog.cc b/selfdrive/common/swaglog.cc index 74488e220..d8c7d036d 100644 --- a/selfdrive/common/swaglog.cc +++ b/selfdrive/common/swaglog.cc @@ -82,9 +82,7 @@ static void cloudlog_init() { s.inited = true; } -void log(int levelnum, const char* filename, int lineno, const char* func, const char* msg, const std::string& log_s) { - std::lock_guard lk(s.lock); - cloudlog_init(); +static void log(int levelnum, const char* filename, int lineno, const char* func, const char* msg, const std::string& log_s) { if (levelnum >= s.print_level) { printf("%s: %s\n", filename, msg); } @@ -97,10 +95,13 @@ void cloudlog_e(int levelnum, const char* filename, int lineno, const char* func char* msg_buf = nullptr; va_list args; va_start(args, fmt); - vasprintf(&msg_buf, fmt, args); + int ret = vasprintf(&msg_buf, fmt, args); va_end(args); - if (!msg_buf) return; + if (ret <= 0 || !msg_buf) return; + + std::lock_guard lk(s.lock); + cloudlog_init(); json11::Json log_j = json11::Json::object { {"msg", msg_buf}, diff --git a/selfdrive/common/tests/.gitignore b/selfdrive/common/tests/.gitignore index 2b7a3c6eb..1350b3b82 100644 --- a/selfdrive/common/tests/.gitignore +++ b/selfdrive/common/tests/.gitignore @@ -1 +1,2 @@ test_util +test_swaglog diff --git a/selfdrive/common/tests/test_swaglog.cc b/selfdrive/common/tests/test_swaglog.cc new file mode 100644 index 000000000..e4d333fd4 --- /dev/null +++ b/selfdrive/common/tests/test_swaglog.cc @@ -0,0 +1,86 @@ +#include +#include +#define CATCH_CONFIG_MAIN +#include "catch2/catch.hpp" + +#include "json11.hpp" +#include "selfdrive/common/swaglog.h" +#include "selfdrive/common/util.h" +#include "selfdrive/common/version.h" +#include "selfdrive/hardware/hw.h" + +const char *SWAGLOG_ADDR = "ipc:///tmp/logmessage"; +std::string dongle_id = "test_dongle_id"; + +void log_thread(int msg, int msg_cnt) { + for (int i = 0; i < msg_cnt; ++i) { + LOGD("%d", msg); + usleep(1); + } +} + +void send_stop_msg(void *zctx) { + void *sock = zmq_socket(zctx, ZMQ_PUSH); + zmq_connect(sock, SWAGLOG_ADDR); + zmq_send(sock, "", 0, ZMQ_NOBLOCK); + zmq_close(sock); +} + +void recv_log(void *zctx, int thread_cnt, int thread_msg_cnt) { + void *sock = zmq_socket(zctx, ZMQ_PULL); + zmq_bind(sock, SWAGLOG_ADDR); + std::vector thread_msgs(thread_cnt); + + while (true) { + char buf[4096] = {}; + if (zmq_recv(sock, buf, sizeof(buf), 0) == 0) break; + + REQUIRE(buf[0] == CLOUDLOG_DEBUG); + std::string err; + auto msg = json11::Json::parse(buf + 1, err); + REQUIRE(!msg.is_null()); + + REQUIRE(msg["levelnum"].int_value() == CLOUDLOG_DEBUG); + REQUIRE_THAT(msg["filename"].string_value(), Catch::Contains("test_swaglog.cc")); + REQUIRE(msg["funcname"].string_value() == "log_thread"); + REQUIRE(msg["lineno"].int_value() == 17); + + auto ctx = msg["ctx"]; + REQUIRE(ctx["dongle_id"].string_value() == dongle_id); + REQUIRE(ctx["version"].string_value() == COMMA_VERSION); + REQUIRE(ctx["dirty"].bool_value() == true); + std::string device = "pc"; + if (Hardware::EON()) { + device = "eon"; + } else if (Hardware::TICI()) { + device = "tici"; + } + REQUIRE(ctx["device"].string_value() == device); + + int thread_id = atoi(msg["msg"].string_value().c_str()); + REQUIRE((thread_id >= 0 && thread_id < thread_cnt)); + thread_msgs[thread_id]++; + } + for (int i = 0; i < thread_cnt; ++i) { + REQUIRE(thread_msgs[i] == thread_msg_cnt); + } + zmq_close(sock); +} + +TEST_CASE("swaglog") { + setenv("DONGLE_ID", dongle_id.c_str(), 1); + setenv("dirty", "1", 1); + const int thread_cnt = 5; + const int thread_msg_cnt = 100; + + void *zctx = zmq_ctx_new(); + send_stop_msg(zctx); + std::vector log_threads; + for (int i = 0; i < thread_cnt; ++i) { + log_threads.push_back(std::thread(log_thread, i, thread_msg_cnt)); + } + + for (auto &t : log_threads) t.join(); + recv_log(zctx, thread_cnt, thread_msg_cnt); + zmq_ctx_destroy(zctx); +}