Logging (#10)

* start logging

* make logging work!

* better logging

* control log level in bazel

* use local time zone

asphr/asphr/BUILD

@@ -13,6 +13,7 @@ cc_library(
     deps = [
         ":assert",
         ":utils",
+        ":log",
         "//third_party/json",
         "@com_google_absl//absl/hash",
         "@com_google_absl//absl/random",
@@ -67,9 +68,60 @@ cc_binary(
     ],
 )
 
+cc_library(
+    name = "log",
+    hdrs = [
+        "log.hpp",
+        "foreach.hpp"
+    ],
+    linkstatic = True,
+    defines = select({
+        "//conditions:default": [],
+        ":log_level_dbg": ["ASPHR_LOGLEVEL_DBG"],
+        ":log_level_info": ["ASPHR_LOGLEVEL_INFO"],
+        ":log_level_warn": ["ASPHR_LOGLEVEL_WARN"],
+        ":log_level_err": ["ASPHR_LOGLEVEL_ERR"],
+        ":log_level_none": ["ASPHR_LOGLEVEL_NONE"],
+    }),
+    deps = [
+        "@com_google_absl//absl/strings",
+        "@com_google_absl//absl/time",
+    ]
+)
+
+cc_binary(
+    name = "log_manual_test",
+    srcs = ["log_manual_test.cc"],
+    linkstatic = True,
+    deps = [
+        ":log",
+    ],
+)
+
 config_setting(
     name = "opt_build",
     values = {
         "compilation_mode": "opt"
     }
+)
+
+config_setting(
+    name = "log_level_dbg",
+    values = {"define": "log_level=dbg"},
+)
+config_setting(
+    name = "log_level_info",
+    values = {"define": "log_level=info"},
+)
+config_setting(
+    name = "log_level_warn",
+    values = {"define": "log_level=warn"},
+)
+config_setting(
+    name = "log_level_err",
+    values = {"define": "log_level=err"},
+)
+config_setting(
+    name = "log_level_none",
+    values = {"define": "log_level=none"},
 )

asphr/asphr/asphr.hpp

@@ -32,6 +32,7 @@
 #include "absl/time/clock.h"
 #include "absl/time/time.h"
 #include "assert.hpp"
+#include "log.hpp"
 #include "third_party/json/nlohmann_json.h"
 #include "utils.hpp"
 
@@ -44,14 +45,14 @@ using std::make_pair;
 using std::make_shared;
 using std::make_tuple;
 using std::make_unique;
+using std::optional;
 using std::pair;
 using std::shared_ptr;
 using std::string;
 using std::to_string;
 using std::tuple;
 using std::unique_ptr;
 using std::vector;
-using std::optional;
 
 namespace asphr {
 using json = nlohmann::json;
@@ -79,21 +80,4 @@ constexpr size_t MESSAGE_SIZE_BITS = MESSAGE_SIZE * 8;
 using pir_value_t = array<byte, MESSAGE_SIZE>;
 // pir_index is the type of the index in the database. this should correspond to
 // the index in the schema/messenger.proto definition
-using pir_index_t = uint32_t;
-
-// initiate the debug mode macros
-#ifdef DEBUG
-#define dbg(x) x
-// x is the value, y is the message
-#define debug(x, y) cout << y << ": " << x << endl
-#define DEBUG_PRINT(x) std::cout << x << std::endl
-#define DEBUG_PRINT_VAR(x) std::cout << #x << ": " << x << std::endl
-#define DEBUG_PRINT_VAR_VAR(x, y) \
-  std::cout << #x << ": " << x << " " << #y << ": " << y << std::endl
-#else
-#define dbg(x)
-#define debug(x)
-#define DEBUG_PRINT(x)
-#define DEBUG_PRINT_VAR(x)
-#define DEBUG_PRINT_VAR_VAR(x, y)
-#endif
+using pir_index_t = uint32_t;

asphr/asphr/foreach.hpp

@@ -0,0 +1,38 @@
+//
+// Copyright 2022 Anysphere, Inc.
+// SPDX-License-Identifier: GPL-3.0-only
+//
+
+/*
+Inspired by https://www.scs.stanford.edu/~dm/blog/va-opt.html.
+
+Usage:
+* ASPHR_FOR_EACH(F, a, b, c, 1, 2, 3) // => F(a), F(b), F(c), F(1), F(2), F(3)
+* ASPHR_FOR_EACH2(F1, F2, a, b, c, 1, 2, 3) // => F1(a), F2(b), F1(c), F2(1),
+F1(2), F2(3)
+*/
+
+#define ASPHR_PARENS ()
+
+#define ASPHR_EXPAND(...) \
+  ASPHR_EXPAND4(ASPHR_EXPAND4(ASPHR_EXPAND4(ASPHR_EXPAND4(__VA_ARGS__))))
+#define ASPHR_EXPAND4(...) \
+  ASPHR_EXPAND3(ASPHR_EXPAND3(ASPHR_EXPAND3(ASPHR_EXPAND3(__VA_ARGS__))))
+#define ASPHR_EXPAND3(...) \
+  ASPHR_EXPAND2(ASPHR_EXPAND2(ASPHR_EXPAND2(ASPHR_EXPAND2(__VA_ARGS__))))
+#define ASPHR_EXPAND2(...) \
+  ASPHR_EXPAND1(ASPHR_EXPAND1(ASPHR_EXPAND1(ASPHR_EXPAND1(__VA_ARGS__))))
+#define ASPHR_EXPAND1(...) __VA_ARGS__
+
+#define ASPHR_FOR_EACH(macro, between, ...) \
+  __VA_OPT__(ASPHR_EXPAND(ASPHR_FOR_EACH_HELPER(macro, __VA_ARGS__)))
+#define ASPHR_FOR_EACH_HELPER(macro, a1, ...) \
+  macro(a1) __VA_OPT__(, ASPHR_FOR_EACH_AGAIN ASPHR_PARENS(macro, __VA_ARGS__))
+#define ASPHR_FOR_EACH_AGAIN() ASPHR_FOR_EACH_HELPER
+
+#define ASPHR_FOR_EACH2(macro1, macro2, ...) \
+  __VA_OPT__(ASPHR_EXPAND(ASPHR_FOR_EACH2_HELPER(macro1, macro2, __VA_ARGS__)))
+#define ASPHR_FOR_EACH2_HELPER(macro1, macro2, a1, a2, ...)               \
+  macro1(a1), macro2(a2) __VA_OPT__(, ASPHR_FOR_EACH2_AGAIN ASPHR_PARENS( \
+                                          macro1, macro2, __VA_ARGS__))
+#define ASPHR_FOR_EACH2_AGAIN() ASPHR_FOR_EACH2_HELPER

asphr/asphr/log.hpp

@@ -0,0 +1,103 @@
+//
+// Copyright 2022 Anysphere, Inc.
+// SPDX-License-Identifier: GPL-3.0-only
+//
+
+#pragma once
+
+#include <iostream>
+
+#include "absl/strings/str_cat.h"
+#include "absl/time/clock.h"
+#include "absl/time/time.h"
+#include "foreach.hpp"
+
+/*
+ASPHR_LOG is the simplest possible logging mechanism.
+
+Features we want:
+* severity levels
+* structured logging
+* works fine with multiple threads
+
+Features we don't want:
+* everything else
+
+Why not use a more standard logging library?
+* glog reads environment variables, adds gflags, and adds a lot of other stuff
+* log4cxx is a close cousin to log4j..... (need i say more?)
+* nanolog requires a separate binary to decode the logfiles
+
+If it is determined that the logging ever causes a performance bottleneck, it
+may be worth looking into the above libraries. Until then, this simple approach
+wins.
+
+We log to stderr only.
+
+Log level is set at compile time:
+- ASPHR_LOGLEVEL_NONE: log nothing
+- ASPHR_LOGLEVEL_ERR: log only errors
+- ASPHR_LOGLEVEL_WARN: log errors and warnings
+- ASPHR_LOGLEVEL_INFO: log errors and warnings and info
+- ASPHR_LOGLEVEL_DBG: log everything
+
+Default is ASPHR_LOGLEVEL_DBG.
+
+*/
+
+// ASPHR_LOG_ERR(msg, key, value, key, value, ...)
+// ASPHR_LOG_WARN(msg, key, value, key, value, ...)
+// ASPHR_LOG_INFO(msg, key, value, key, value, ...)
+// ASPHR_LOG_DBG(msg, key, value, key, value, ...)
+
+#if !defined(ASPHR_LOGLEVEL_NONE) && !defined(ASPHR_LOGLEVEL_ERR) &&  \
+    !defined(ASPHR_LOGLEVEL_WARN) && !defined(ASPHR_LOGLEVEL_INFO) && \
+    !defined(ASPHR_LOGLEVEL_DBG)
+#define ASPHR_LOGLEVEL_DBG
+#endif
+
+#define ASPHR_EXPAND_LABEL(x) absl::StrCat(" ", #x, "=")
+#define ASPHR_EXPAND_VALUE(x) x
+#define ASPHR_DO_LOG_INTERNAL_DO_NOT_USE(msg, level, ...)                  \
+  {                                                                        \
+    absl::Time t1 = absl::Now();                                           \
+    auto s = absl::StrCat(                                                 \
+        "[",                                                               \
+        absl::FormatTime("%Y-%m-%d%ET%H:%M:%E2S%Ez", t1,                   \
+                         absl::LocalTimeZone()),                           \
+        " ", __FILE__, ":", __LINE__, " ", level, "] ", msg,               \
+        __VA_OPT__(ASPHR_FOR_EACH2(ASPHR_EXPAND_LABEL, ASPHR_EXPAND_VALUE, \
+                                   __VA_ARGS__), ) "\n");                  \
+    std::cerr << s;                                                        \
+    std::cerr.flush();                                                     \
+  }
+
+#if defined(ASPHR_LOGLEVEL_ERR) || defined(ASPHR_LOGLEVEL_WARN) || \
+    defined(ASPHR_LOGLEVEL_INFO) || defined(ASPHR_LOGLEVEL_DBG)
+#define ASPHR_LOG_ERR(msg, ...) \
+  ASPHR_DO_LOG_INTERNAL_DO_NOT_USE(msg, "ERR", __VA_ARGS__)
+#else
+#define ASPHR_LOG_ERR(msg, ...) static_cast<void>(0)
+#endif
+
+#if defined(ASPHR_LOGLEVEL_WARN) || defined(ASPHR_LOGLEVEL_INFO) || \
+    defined(ASPHR_LOGLEVEL_DBG)
+#define ASPHR_LOG_WARN(msg, ...) \
+  ASPHR_DO_LOG_INTERNAL_DO_NOT_USE(msg, "WARN", __VA_ARGS__)
+#else
+#define ASPHR_LOG_WARN(msg, ...) static_cast<void>(0)
+#endif
+
+#if defined(ASPHR_LOGLEVEL_INFO) || defined(ASPHR_LOGLEVEL_DBG)
+#define ASPHR_LOG_INFO(msg, ...) \
+  ASPHR_DO_LOG_INTERNAL_DO_NOT_USE(msg, "INFO", __VA_ARGS__)
+#else
+#define ASPHR_LOG_INFO(msg, ...) static_cast<void>(0)
+#endif
+
+#if defined(ASPHR_LOGLEVEL_DBG)
+#define ASPHR_LOG_DBG(msg, ...) \
+  ASPHR_DO_LOG_INTERNAL_DO_NOT_USE(msg, "DBG", __VA_ARGS__)
+#else
+#define ASPHR_LOG_DBG(msg, ...) static_cast<void>(0)
+#endif

asphr/asphr/log_manual_test.cc

@@ -0,0 +1,18 @@
+//
+// Copyright 2022 Anysphere, Inc.
+// SPDX-License-Identifier: GPL-3.0-only
+//
+
+#include <cstdlib>  // std::exit
+#include <format>
+#include <iostream>  // std::cerr
+
+#include "log.hpp"
+
+int main(int argc, char** argv) {
+  ASPHR_LOG_ERR("error.", key, "value");
+  ASPHR_LOG_WARN("warning.", key, "value", key2, 2);
+  ASPHR_LOG_INFO("info.", info1, "value1");
+  ASPHR_LOG_DBG("debug.", c++ version, "c++20", key2, 2, key3, 3);
+  return 0;
+}