Merge pull request #80 from mlibrary/debug-logging

Add debug logging throughout API requests

apache/client/include/lauth/http_client.hpp

@@ -20,6 +20,9 @@ namespace mlibrary::lauth {
 
     protected:
       const std::string baseUrl;
+      void requestOk(const std::string& path, std::size_t size);
+      void requestNotOk(const std::string& path, int status);
+      void requestFailed(const std::string& path, const std::string& error);
   };
 }
 

apache/client/include/lauth/logging.hpp

@@ -0,0 +1,147 @@
+#ifndef __LAUTH_LOGGING_HPP__
+#define __LAUTH_LOGGING_HPP__
+
+#include <iostream>
+#include <map>
+#include <memory>
+#include <string>
+#include <sstream>
+
+namespace mlibrary::lauth {
+  enum LogLevel {
+    FATAL = 0,
+    ERROR = 1,
+    WARN = 2,
+    INFO = 3,
+    DEBUG = 4,
+    TRACE = 5
+  };
+
+  const std::string LogLevels[] = {"FATAL", "ERROR", "WARN", "INFO", "DEBUG", "TRACE"};
+
+  class LogSink {
+    public:
+      virtual ~LogSink() = default;
+      virtual void write(const std::string& level, const std::string& msg, const char* file, int line) = 0;
+      virtual void fatal(const std::string& msg, const char* file, int line) = 0;
+      virtual void error(const std::string& msg, const char* file, int line) = 0;
+      virtual void warn(const std::string& msg, const char* file, int line) = 0;
+      virtual void info(const std::string& msg, const char* file, int line) = 0;
+      virtual void debug(const std::string& msg, const char* file, int line) = 0;
+      virtual void trace(const std::string& msg, const char* file, int line) = 0;
+  };
+
+  class StdOut : public LogSink {
+    public:
+      virtual ~StdOut() = default;
+
+      void write(const std::string& level, const std::string& msg, const char* file, int line) override {
+        std::cout << "[" << level << "] " << file << "(" << line << "): " << msg << std::endl;
+      }
+
+      void fatal(const std::string& msg, const char* file, int line) override {
+        write(LogLevels[LogLevel::FATAL], msg, file, line);
+      }
+
+      void error(const std::string& msg, const char* file, int line) override {
+        write(LogLevels[LogLevel::ERROR], msg, file, line);
+      }
+
+      void warn(const std::string& msg, const char* file, int line) override {
+        write(LogLevels[LogLevel::WARN], msg, file, line);
+      }
+
+      void info(const std::string& msg, const char* file, int line) override {
+        write(LogLevels[LogLevel::INFO], msg, file, line);
+      }
+
+      void debug(const std::string& msg, const char* file, int line) override {
+        write(LogLevels[LogLevel::DEBUG], msg, file, line);
+      }
+
+      void trace(const std::string& msg, const char* file, int line) override {
+        write(LogLevels[LogLevel::TRACE], msg, file, line);
+      }
+  };
+
+  class NullLog : public LogSink {
+    public:
+      virtual ~NullLog() = default;
+      void write(const std::string&, const std::string&, const char*, int) override {}
+      void fatal(const std::string&, const char*, int) override {}
+      void error(const std::string&, const char*, int) override {}
+      void warn(const std::string&, const char*, int) override {}
+      void info(const std::string&, const char*, int) override {}
+      void debug(const std::string&, const char*, int) override {}
+      void trace(const std::string&, const char*, int) override {}
+  };
+
+  class Logger {
+    public:
+      Logger() : out(std::make_unique<NullLog>()) {};
+      Logger(std::unique_ptr<LogSink>&& out) : out(std::move(out)) {};
+
+      Logger(const Logger&) = delete;
+      Logger& operator=(const Logger&) = delete;
+      Logger(Logger&&) = delete;
+      Logger& operator=(const Logger&&) = delete;
+      virtual ~Logger() = default;
+
+      static void set(std::shared_ptr<Logger> logger) {
+        Logger::logger = logger;
+      }
+
+      static std::shared_ptr<Logger> get() {
+        if (!Logger::logger) {
+          Logger::logger = std::make_shared<Logger>();
+        }
+        return Logger::logger;
+      }
+
+      void fatal(const std::string& msg, const char* file, int line) {
+        out->fatal(msg, file, line);
+      }
+
+      void error(const std::string& msg, const char* file, int line) {
+        out->error(msg, file, line);
+      }
+
+      void warn(const std::string& msg, const char* file, int line) {
+        out->warn(msg, file, line);
+      }
+
+      void info(const std::string& msg, const char* file, int line) {
+        out->info(msg, file, line);
+      }
+
+      void debug(const std::string& msg, const char* file, int line) {
+        out->debug(msg, file, line);
+      }
+
+      void trace(const std::string& msg, const char* file, int line) {
+        out->trace(msg, file, line);
+      }
+
+    protected:
+      inline static std::shared_ptr<Logger> logger;
+      std::unique_ptr<LogSink> out;
+  };
+}
+
+#define LAUTH_DEBUG(msg)                       \
+  mlibrary::lauth::Logger::get()->debug(       \
+    static_cast<std::ostringstream&>(          \
+      std::ostringstream().flush() << msg      \
+    ).str(),                                   \
+    __FILE__, __LINE__                         \
+  )
+
+#define LAUTH_WARN(msg)                        \
+  mlibrary::lauth::Logger::get()->warn(        \
+    static_cast<std::ostringstream&>(          \
+      std::ostringstream().flush() << msg      \
+    ).str(),                                   \
+    __FILE__, __LINE__                         \
+  )
+
+#endif // __LAUTH_LOGGING_HPP__

apache/client/meson.build

@@ -49,7 +49,9 @@ install_headers(
   'include/lauth/http_client.hpp',
   'include/lauth/http_params.hpp',
   'include/lauth/http_headers.hpp',
+  'include/lauth/json.hpp',
   'include/lauth/json_conversions.hpp',
+  'include/lauth/logging.hpp',
   'include/lauth/request.hpp',
   subdir: 'lauth')
 

apache/client/src/lauth/api_client.cpp

@@ -5,6 +5,7 @@
 
 #include "lauth/json.hpp"
 #include "lauth/json_conversions.hpp"
+#include "lauth/logging.hpp"
 
 namespace mlibrary::lauth {
   AuthorizationResult ApiClient::authorize(Request req) {
@@ -20,15 +21,21 @@ namespace mlibrary::lauth {
       {"Authorization", authorization}
     };
 
+    LAUTH_DEBUG("Making API request to /authorized ["
+        << "ip: " << req.ip << ", "
+        << "uri: " << req.uri << ", "
+        << "user: " << req.user << "]");
+
     auto result = client->get("/authorized", params, headers);
 
     try
     {
-      json jsonBody = json::parse(*result);
+      json jsonBody = json::parse(result.value_or(""));
       return jsonBody.template get<AuthorizationResult>();
     }
     catch (const json::exception &e)
     {
+      LAUTH_WARN("Authorization denied because API response failed serialization: " << e.what());
       return AuthorizationResult{
         .determination = "denied"
       };

apache/client/src/lauth/http_client.cpp

@@ -6,19 +6,29 @@
 
 #include "lauth/http_params.hpp"
 #include "lauth/http_headers.hpp"
+#include "lauth/logging.hpp"
 
 namespace mlibrary::lauth {
   std::optional<std::string> HttpClient::get(const std::string& path, const HttpParams& params, const HttpHeaders& headers) {
     httplib::Client client(baseUrl);
+    client.set_connection_timeout(5);
+    client.set_read_timeout(5);
 
     // using Headers = std::multimap<std::string, std::string, detail::ci>;
     httplib::Headers marshal_headers ( headers.begin(), headers.end() );
 
     auto res = client.Get(path, params, marshal_headers);
-    if (res)
+
+    if (res && res->status == 200) {
+      requestOk(path, res->body.size());
       return res->body;
-    else
+    } else if (res) {
+      requestNotOk(path, res->status);
+      return std::nullopt;
+    } else {
+      requestFailed(path, httplib::to_string(res.error()));
       return std::nullopt;
+    }
   }
 
   std::optional<std::string> HttpClient::get(const std::string& path, const HttpParams& params) {
@@ -32,4 +42,16 @@ namespace mlibrary::lauth {
   std::optional<std::string> HttpClient::get(const std::string& path) {
      return get(path, HttpParams{}, HttpHeaders{});
   }
+
+  void HttpClient::requestOk(const std::string& path, std::size_t size) {
+    LAUTH_DEBUG("HTTP request to " << baseUrl << path << " succeeded; response length: " << size);
+  }
+
+  void HttpClient::requestNotOk(const std::string& path, int status) {
+    LAUTH_DEBUG("HTTP request to " << baseUrl << path << " succeeded but was not 200 OK; status: " << status);
+  }
+
+  void HttpClient::requestFailed(const std::string& path, const std::string& error) {
+    LAUTH_WARN("HTTP request to " << baseUrl << path << " failed: " << error);
+  }
 }

apache/module/mod_lauth.cpp

@@ -10,6 +10,7 @@
 #include "mod_auth.h"
 
 #include <lauth/authorizer.hpp>
+#include <lauth/logging.hpp>
 
 #include <string>
 #include <map>
@@ -44,7 +45,53 @@ typedef struct lauth_config_struct {
     const char *token;  /* token for API */
 } lauth_config;
 
-void *create_lauth_server_config(apr_pool_t *p, server_rec *_) {
+namespace mlibrary::lauth {
+  class ApacheLog : public LogSink {
+    public:
+      ApacheLog(server_rec *server) {
+        this->server = server;
+      }
+
+      virtual ~ApacheLog() = default;
+      void write(const std::string& level, const std::string& msg, const char* file, int line) override {
+        const char *message = static_cast<std::ostringstream&>(
+            std::ostringstream().flush() << "[" << level << "] " << msg
+        ).str().c_str();
+
+        ap_log_error(file, line, APLOG_MODULE_INDEX, APLOG_INFO, 0, server, message);
+      }
+
+      void fatal(const std::string& msg, const char* file, int line) override {
+        ap_log_error(file, line, APLOG_MODULE_INDEX, APLOG_EMERG, 0, server, msg.c_str());
+      }
+
+      void error(const std::string& msg, const char* file, int line) override {
+        ap_log_error(file, line, APLOG_MODULE_INDEX, APLOG_ERR, 0, server, msg.c_str());
+      }
+
+      void warn(const std::string& msg, const char* file, int line) override {
+        ap_log_error(file, line, APLOG_MODULE_INDEX, APLOG_WARNING, 0, server, msg.c_str());
+      }
+
+      void info(const std::string& msg, const char* file, int line) override {
+        ap_log_error(file, line, APLOG_MODULE_INDEX, APLOG_INFO, 0, server, msg.c_str());
+      }
+
+      void debug(const std::string& msg, const char* file, int line) override {
+        ap_log_error(file, line, APLOG_MODULE_INDEX, APLOG_DEBUG, 0, server, msg.c_str());
+      }
+
+      void trace(const std::string& msg, const char* file, int line) override {
+        ap_log_error(file, line, APLOG_MODULE_INDEX, APLOG_TRACE1, 0, server, msg.c_str());
+      }
+
+    protected:
+      server_rec *server;
+  };
+}
+
+void *create_lauth_server_config(apr_pool_t *p, server_rec *s) {
+    mlibrary::lauth::Logger::set(std::make_shared<Logger>(std::make_unique<mlibrary::lauth::ApacheLog>(s)));
     lauth_config *config = (lauth_config *) apr_pcalloc(p, sizeof(*config));
     config->url = NULL;
     config->token = NULL;
@@ -73,34 +120,51 @@ const char *set_token(cmd_parms *cmd, void *cfg, const char* arg)
     return NULL;
 }
 
+const char* authPath(request_rec *r) {
+    std::string handler = r->handler ? std::string(r->handler) : "";
+    if (handler.substr(0, handler.find(":")) == "proxy-server") {
+        LAUTH_DEBUG("URI \"" << r->uri << "\" is proxied, using it for authorization.");
+        return r->uri;
+    } else {
+        LAUTH_DEBUG("URI \"" << r->uri << "\" is local, using file path for authorization.");
+        return r->filename;
+    }
+}
+
 static authz_status lauth_check_authorization(request_rec *r,
                                                   const char *require_line,
                                                   const void *parsed_require_line)
 {
-    if (!r->ap_auth_type) return AUTHZ_DENIED_NO_USER;
-
-    Request req;
-    std::string handler = r->handler ? std::string(r->handler) : "";
-    if (handler.substr(0, handler.find(":")) == "proxy-server") {
-      req = Request {
-        .ip = r->useragent_ip ? std::string(r->useragent_ip) : "",
-        .uri = r->uri ? std::string(r->uri) : "",
-        .user = r->user ? std::string(r->user) : ""
-      };
-    } else {
-      req  = Request {
-        .ip = r->useragent_ip ? std::string(r->useragent_ip) : "",
-        .uri = r->filename,
-        .user = r->user ? std::string(r->user) : ""
-      };
+    if (!r->ap_auth_type) {
+      LAUTH_DEBUG("Passing on authorization until authenticated; initial request: " << ap_is_initial_req(r));
+      return AUTHZ_DENIED_NO_USER;
     }
 
+    LAUTH_DEBUG("Checking authorization... "
+        << "initial request: " << ap_is_initial_req(r) << ", "
+        << "auth type: " << r->ap_auth_type << ", "
+        << "uri: " << r->uri << ", "
+        << "filename: " << r->filename);
+
+
+    Request req  = Request {
+      .ip = r->useragent_ip ? std::string(r->useragent_ip) : "",
+      .uri = std::string(authPath(r)),
+      .user = r->user ? std::string(r->user) : ""
+    };
+
     lauth_config *config = (lauth_config *) ap_get_module_config(r->server->module_config, &lauth_module);
+
+    LAUTH_DEBUG("Calling authorizer API at " << config->url);
     std::map<std::string, std::string> result = Authorizer(config->url, config->token).authorize(req);
 
     apr_table_set(r->subprocess_env, "PUBLIC_COLL", result["public_collections"].c_str());
     apr_table_set(r->subprocess_env, "AUTHZD_COLL", result["authorized_collections"].c_str());
 
+    LAUTH_DEBUG("Returned from authorizer API... determination: " << result["determination"]);
+    LAUTH_DEBUG("Setting public collections (PUBLIC_COLL) to: " << result["public_collections"]);
+    LAUTH_DEBUG("Setting authorized collections (AUTHZD_COLL) to: " << result["authorized_collections"]);
+
     return result["determination"] == "allowed" ? AUTHZ_GRANTED : AUTHZ_DENIED;
 }