From be2e70ed511b2549721ec1b736f666be5858acae Mon Sep 17 00:00:00 2001 From: Noah Botimer Date: Fri, 12 Jul 2024 09:49:19 -0400 Subject: [PATCH] Add debug logging throughout API requests This adds an indirect logging facility to the client and an implementation that is injected from the module. It uses a globally configured logger/singleton. The design is not perfect, but the invocations and outputs are decent. I didn't want to add a logging or formatting library at this time, but it's something to consider; there are a few promising options. The C++20 format header is not available under the current version of GCC, so we use basic stringstreams, rather than dealing with varargs or adding {fmt}. --- apache/client/include/lauth/http_client.hpp | 3 + apache/client/include/lauth/logging.hpp | 147 ++++++++++++++++++++ apache/client/meson.build | 2 + apache/client/src/lauth/api_client.cpp | 9 +- apache/client/src/lauth/http_client.cpp | 26 +++- apache/module/mod_lauth.cpp | 98 ++++++++++--- 6 files changed, 265 insertions(+), 20 deletions(-) create mode 100644 apache/client/include/lauth/logging.hpp diff --git a/apache/client/include/lauth/http_client.hpp b/apache/client/include/lauth/http_client.hpp index 0898ae5..bda5c3b 100644 --- a/apache/client/include/lauth/http_client.hpp +++ b/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); }; } diff --git a/apache/client/include/lauth/logging.hpp b/apache/client/include/lauth/logging.hpp new file mode 100644 index 0000000..610c29c --- /dev/null +++ b/apache/client/include/lauth/logging.hpp @@ -0,0 +1,147 @@ +#ifndef __LAUTH_LOGGING_HPP__ +#define __LAUTH_LOGGING_HPP__ + +#include +#include +#include +#include +#include + +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()) {}; + Logger(std::unique_ptr&& 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; + } + + static std::shared_ptr get() { + if (!Logger::logger) { + Logger::logger = std::make_shared(); + } + 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; + std::unique_ptr out; + }; +} + +#define LAUTH_DEBUG(msg) \ + mlibrary::lauth::Logger::get()->debug( \ + static_cast( \ + std::ostringstream().flush() << msg \ + ).str(), \ + __FILE__, __LINE__ \ + ) + +#define LAUTH_WARN(msg) \ + mlibrary::lauth::Logger::get()->warn( \ + static_cast( \ + std::ostringstream().flush() << msg \ + ).str(), \ + __FILE__, __LINE__ \ + ) + +#endif // __LAUTH_LOGGING_HPP__ diff --git a/apache/client/meson.build b/apache/client/meson.build index 5fbbef1..9c09ea8 100644 --- a/apache/client/meson.build +++ b/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') diff --git a/apache/client/src/lauth/api_client.cpp b/apache/client/src/lauth/api_client.cpp index 7151153..4d5bbb9 100644 --- a/apache/client/src/lauth/api_client.cpp +++ b/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(); } catch (const json::exception &e) { + LAUTH_WARN("Authorization denied because API response failed serialization: " << e.what()); return AuthorizationResult{ .determination = "denied" }; diff --git a/apache/client/src/lauth/http_client.cpp b/apache/client/src/lauth/http_client.cpp index bbd29ed..4e122d0 100644 --- a/apache/client/src/lauth/http_client.cpp +++ b/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 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; 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 HttpClient::get(const std::string& path, const HttpParams& params) { @@ -32,4 +42,16 @@ namespace mlibrary::lauth { std::optional 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); + } } diff --git a/apache/module/mod_lauth.cpp b/apache/module/mod_lauth.cpp index d62792c..2c41632 100644 --- a/apache/module/mod_lauth.cpp +++ b/apache/module/mod_lauth.cpp @@ -10,6 +10,7 @@ #include "mod_auth.h" #include +#include #include #include @@ -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().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(std::make_unique(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 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; }