Audit log in failed connection cases

CMakeLists.txt

@@ -116,6 +116,16 @@ else()
   endif()
 endif()
 
+# Used to route gRPC's internal logs into our logger.
+set(_ABSEIL_LOG
+  absl::log
+  absl::log_entry
+  absl::log_globals
+  absl::log_initialize
+  absl::log_sink
+  absl::log_sink_registry
+)
+
 # Python3 Virtual Environment
 if(USE_PYTHON_VIRTUALENV)
   include(CreateVirtualEnvironment)
@@ -657,6 +667,7 @@ endif()
 
 set(server_lib_deps
   ${_ABSEIL_SYNC}
+  ${_ABSEIL_LOG}
   ${_GRPC_GPR}
   ${_GRPC_GRPCPP}
   ${_GRPC}

source/server/client_connection_logger.cpp

@@ -1,6 +1,14 @@
 #include "client_connection_logger.h"
 #include "logging.h"
 
+#include <absl/log/globals.h>
+#include <absl/log/initialize.h>
+#include <absl/log/log_entry.h>
+#include <absl/log/log_sink.h>
+#include <absl/log/log_sink_registry.h>
+
+#include <regex>
+
 #include <grpc/grpc_security_constants.h>
 
 namespace nidevice_grpc {
@@ -19,12 +27,12 @@ std::string describe_authentication(const grpc::AuthContext& auth_context)
   description += transport_type.empty() ? "unknown transport" : std::string(transport_type[0].data(), transport_type[0].size());
 
   if (!common_names.empty())
-    description += ", client cert CN:" + std::string(common_names[0].data(), common_names[0].size());
+    description += ", client cert CN: " + std::string(common_names[0].data(), common_names[0].size());
 
   return description;
 }
 
-}
+} // namespace
 
 bool parse_peer(const std::string& peer, std::string& ip, std::string& port)
 {
@@ -100,4 +108,70 @@ void register_client_connection_logger()
   grpc::Server::SetGlobalCallbacks(new ClientConnectionLogger());
 }
 
+namespace {
+
+// Converts absl's severity levels to our own.
+logging::Level to_logging_level(absl::LogSeverity severity)
+{
+  switch (severity) {
+    case absl::LogSeverity::kWarning:
+      return logging::Level_Warning;
+    case absl::LogSeverity::kError:
+    case absl::LogSeverity::kFatal:
+      return logging::Level_Error;
+    case absl::LogSeverity::kInfo:
+    default:
+      return logging::Level_Info;
+  }
+}
+
+// This sink captures gRPC's own internal logs and calls Send for each of them. We only use it to log handshake failures.
+class AuditLogSinkWrapper {
+  public:
+    AuditLogSinkWrapper() {
+      absl::InitializeLog();
+      absl::AddLogSink(&sink_);
+
+      // gpr_log_verbosity_init() may raise the global floor above INFO and silence audit records.
+      if (absl::MinLogLevel() > absl::LogSeverityAtLeast::kInfo) { 
+        logging::log(logging::Level_Error, "GRPC_VERBOSITY suppresses connection-failure audit logging; forcing INFO."); 
+        absl::SetMinLogLevel(absl::LogSeverityAtLeast::kInfo); 
+      }
+    }
+    ~AuditLogSinkWrapper() {
+      absl::RemoveLogSink(&sink_);
+    }
+
+    // Disable copy/move constructors and assignment operators.
+    AuditLogSinkWrapper(const AuditLogSinkWrapper&) = delete;
+    AuditLogSinkWrapper& operator=(const AuditLogSinkWrapper&) = delete;
+    AuditLogSinkWrapper(AuditLogSinkWrapper&&) = delete;
+    AuditLogSinkWrapper& operator=(AuditLogSinkWrapper&&) = delete;
+
+  private:
+    class AuditLogSink : public absl::LogSink {
+    public:
+      void Send(const absl::LogEntry& entry) override
+      {
+        static const std::regex handshake_fail_pattern(R"(\bhandshake\b.*\bfail)", std::regex::icase);
+        const auto& text = entry.text_message();
+        if (!std::regex_search(text.begin(), text.end(), handshake_fail_pattern))
+          return;
+
+        const auto message = std::string(entry.text_message());
+        logging::log_to_audit_source(to_logging_level(entry.log_severity()), "%s", message.c_str());
+      }
+    };
+
+    AuditLogSink sink_;
+};
+
+} // namespace
+
+void register_grpc_log_sink()
+{
+  // The wrapper handles adding and removing the log sink from absl.
+  static AuditLogSinkWrapper sink;
+}
+
 }  // namespace nidevice_grpc

source/server/client_connection_logger.h

@@ -33,6 +33,9 @@ class ClientConnectionLogger : public grpc::Server::GlobalCallbacks {
 // Registers a process-wide ClientConnectionLogger with gRPC, must be called before any grpc::Server is built.
 void register_client_connection_logger();
 
+// Registers an absl::LogSink that captures all of gRPC's internal log messages; used for logging connection failures
+void register_grpc_log_sink();
+
 }  // namespace nidevice_grpc
 
 #endif  // NIDEVICE_GRPC_CLIENT_CONNECTION_LOGGER_H

source/server/core_server.cpp

@@ -327,6 +327,8 @@ int main(int argc, char** argv)
   nidevice_grpc::set_console_ctrl_handler(&StopServer);
 #endif
 
+  nidevice_grpc::register_grpc_log_sink();
+
   RunServer(config);
   return EXIT_SUCCESS;
 }

source/server/logging.cpp

@@ -53,9 +53,9 @@ namespace {
 std::shared_ptr<spdlog::logger> get_event_log_logger()
 {
   static std::shared_ptr<spdlog::logger> audit_logger = []() {
-    auto sink = std::make_shared<spdlog::sinks::win_eventlog_sink_mt>("ni-grpc-device-server");
+    auto sink = std::make_shared<spdlog::sinks::win_eventlog_sink_mt>("ni-grpc-device");
     auto logger = std::make_shared<spdlog::logger>("Server", sink);
-    logger->set_pattern("[ni-grpc-device-server][%n] %v");
+    logger->set_pattern("[ni-grpc-device][%n] %v");
     return logger;
   }();
   return audit_logger;
@@ -100,7 +100,7 @@ void log_to_audit_source(Level level, const char* fmt, ...)
   }
 #else
   // We're manually prefixing audit logs in the Windows spdlog path, so manually add it here on the Linux path before sending it over to syslog.
-  const std::string message = "[ni-grpc-device-server][Server] " + std::string(fmt);
+  const std::string message = "[ni-grpc-device][Server] " + std::string(fmt);
 
   va_list args;
   va_start(args, fmt);