Introduce AccessLogger

etc/CMakeLists.txt

@@ -34,6 +34,7 @@ install_if_not_exists(icinga2/conf.d/notifications.conf ${ICINGA2_CONFIGDIR}/con
 install_if_not_exists(icinga2/conf.d/templates.conf ${ICINGA2_CONFIGDIR}/conf.d)
 install_if_not_exists(icinga2/conf.d/timeperiods.conf ${ICINGA2_CONFIGDIR}/conf.d)
 install_if_not_exists(icinga2/conf.d/users.conf ${ICINGA2_CONFIGDIR}/conf.d)
+install_if_not_exists(icinga2/features-available/accesslog.conf ${ICINGA2_CONFIGDIR}/features-available)
 install_if_not_exists(icinga2/features-available/api.conf ${ICINGA2_CONFIGDIR}/features-available)
 install_if_not_exists(icinga2/features-available/debuglog.conf ${ICINGA2_CONFIGDIR}/features-available)
 install_if_not_exists(icinga2/features-available/mainlog.conf ${ICINGA2_CONFIGDIR}/features-available)

etc/icinga2/features-available/accesslog.conf

@@ -0,0 +1,7 @@
+/**
+ * The AccessLogger type writes API access information to a file.
+ */
+
+object AccessLogger "access-log" {
+  path = LogDir + "/access.log"
+}

lib/base/CMakeLists.txt

@@ -1,5 +1,6 @@
 # Icinga 2 | (c) 2012 Icinga GmbH | GPLv2+
 
+mkclass_target(accesslogger.ti accesslogger-ti.cpp accesslogger-ti.hpp)
 mkclass_target(application.ti application-ti.cpp application-ti.hpp)
 mkclass_target(configobject.ti configobject-ti.cpp configobject-ti.hpp)
 mkclass_target(configuration.ti configuration-ti.cpp configuration-ti.hpp)
@@ -14,6 +15,7 @@ mkclass_target(sysloglogger.ti sysloglogger-ti.cpp sysloglogger-ti.hpp)
 
 set(base_SOURCES
   i2-base.hpp
+  accesslogger.cpp accesslogger.hpp accesslogger-ti.hpp
   application.cpp application.hpp application-ti.hpp application-version.cpp application-environment.cpp
   array.cpp array.hpp array-script.cpp
   atomic.hpp

lib/base/accesslogger.cpp

@@ -0,0 +1,262 @@
+/* Icinga 2 | (c) 2020 Icinga GmbH | GPLv2+ */
+
+#include "base/accesslogger.hpp"
+#include "base/accesslogger-ti.cpp"
+#include "base/configtype.hpp"
+#include "base/statsfunction.hpp"
+#include "base/application.hpp"
+#include <boost/algorithm/string.hpp>
+#include <boost/regex.hpp>
+#include <cstring>
+#include <unordered_map>
+#include <stdexcept>
+#include <time.h>
+#include <utility>
+#include <vector>
+
+using namespace icinga;
+namespace http = boost::beast::http;
+
+static std::set<AccessLogger::Ptr> l_AccessLoggers;
+static boost::mutex l_AccessLoggersMutex;
+
+REGISTER_TYPE(AccessLogger);
+
+REGISTER_STATSFUNCTION(AccessLogger, &AccessLogger::StatsFunc);
+
+void AccessLogger::StatsFunc(const Dictionary::Ptr& status, const Array::Ptr&)
+{
+	DictionaryData nodes;
+
+	for (const AccessLogger::Ptr& accesslogger : ConfigType::GetObjectsByType<AccessLogger>()) {
+		nodes.emplace_back(accesslogger->GetName(), 1); //add more stats
+	}
+
+	status->Set("accesslogger", new Dictionary(std::move(nodes)));
+}
+
+LogAccess::~LogAccess()
+{
+	decltype(l_AccessLoggers) loggers;
+
+	{
+		boost::mutex::scoped_lock lock (l_AccessLoggersMutex);
+		loggers = l_AccessLoggers;
+	}
+
+	for (auto& logger : loggers) {
+		ObjectLock oLock (logger);
+		logger->m_Formatter(*this, *logger->m_Stream);
+	}
+}
+
+void AccessLogger::Register()
+{
+	boost::mutex::scoped_lock lock (l_AccessLoggersMutex);
+	l_AccessLoggers.insert(this);
+}
+
+void AccessLogger::Unregister()
+{
+	boost::mutex::scoped_lock lock (l_AccessLoggersMutex);
+	l_AccessLoggers.erase(this);
+}
+
+void AccessLogger::OnAllConfigLoaded()
+{
+	ObjectImpl<AccessLogger>::OnAllConfigLoaded();
+
+	m_Formatter = ParseFormatter(GetFormat());
+}
+
+void AccessLogger::ValidateFormat(const Lazy<String>& lvalue, const ValidationUtils& utils)
+{
+	ObjectImpl<AccessLogger>::ValidateFormat(lvalue, utils);
+
+	try {
+		ParseFormatter(lvalue());
+	} catch (const std::invalid_argument& ex) {
+		BOOST_THROW_EXCEPTION(ValidationError(this, { "format" }, ex.what()));
+	}
+}
+
+template<class Message>
+static inline
+void StreamHttpProtocol(const Message& in, std::ostream& out)
+{
+	auto protocol (in.version());
+	auto minor (protocol % 10u);
+
+	out << (protocol / 10u);
+
+	if (minor || protocol != 20u) {
+		out << '.' << minor;
+	}
+}
+
+template<class Message>
+static inline
+void StreamHttpCLength(const Message& in, std::ostream& out)
+{
+	if (in.count(http::field::content_length)) {
+		out << in[http::field::content_length];
+	} else {
+		out << '-';
+	}
+}
+
+template<class Message, class Header>
+static inline
+void StreamHttpHeader(const Message& in, const Header& header, std::ostream& out)
+{
+	if (in.count(header)) {
+		out << in[header];
+	} else {
+		out << '-';
+	}
+}
+
+static boost::regex l_ALFTime (R"EOF(\Atime.(.*)\z)EOF", boost::regex::mod_s);
+static boost::regex l_ALFHeaders (R"EOF(\A(request|response).headers.(.*)\z)EOF", boost::regex::mod_s);
+
+static std::unordered_map<std::string, AccessLogger::FormatterFunc*> l_ALFormatters ({
+	{ "local.address", [](const LogAccess& in, std::ostream& out) {
+		out << in.Stream.lowest_layer().local_endpoint().address();
+	} },
+	{ "local.port", [](const LogAccess& in, std::ostream& out) {
+		out << in.Stream.lowest_layer().local_endpoint().port();
+	} },
+	{ "remote.address", [](const LogAccess& in, std::ostream& out) {
+		out << in.Stream.lowest_layer().remote_endpoint().address();
+	} },
+	{ "remote.port", [](const LogAccess& in, std::ostream& out) {
+		out << in.Stream.lowest_layer().remote_endpoint().port();
+	} },
+	{ "remote.user", [](const LogAccess& in, std::ostream& out) {
+		if (in.User.IsEmpty()) {
+			out << '-';
+		} else {
+			out << in.User;
+		}
+	} },
+	{ "request.method", [](const LogAccess& in, std::ostream& out) {
+		out << in.Request.method();
+	} },
+	{ "request.uri", [](const LogAccess& in, std::ostream& out) {
+		out << in.Request.target();
+	} },
+	{ "request.protocol", [](const LogAccess& in, std::ostream& out) {
+		StreamHttpProtocol(in.Request, out);
+	} },
+	{ "request.size", [](const LogAccess& in, std::ostream& out) {
+		StreamHttpCLength(in.Request, out);
+	} },
+	{ "response.protocol", [](const LogAccess& in, std::ostream& out) {
+		StreamHttpProtocol(in.Response, out);
+	} },
+	{ "response.status", [](const LogAccess& in, std::ostream& out) {
+		out << (int)in.Response.result();
+	} },
+	{ "response.reason", [](const LogAccess& in, std::ostream& out) {
+		out << in.Response.reason();
+	} },
+	{ "response.size", [](const LogAccess& in, std::ostream& out) {
+		StreamHttpCLength(in.Response, out);
+	} }
+});
+
+AccessLogger::Formatter AccessLogger::ParseFormatter(const String& format)
+{
+	std::vector<std::string> tokens;
+	boost::algorithm::split(tokens, format.GetData(), boost::algorithm::is_any_of("$"));
+
+	if (tokens.size() % 2u == 0u) {
+		throw std::invalid_argument("Closing $ not found in macro format string '" + format + "'.");
+	}
+
+	std::vector<Formatter> formatters;
+	std::string literal;
+	bool isLiteral = true;
+
+	for (auto& token : tokens) {
+		if (isLiteral) {
+			literal += token;
+		} else if (token.empty()) {
+			literal += "$";
+		} else {
+			if (!literal.empty()) {
+				formatters.emplace_back([literal](const LogAccess&, std::ostream& out) {
+					out << literal;
+				});
+
+				literal = "";
+			}
+
+			auto formatter (l_ALFormatters.find(token));
+
+			if (formatter == l_ALFormatters.end()) {
+				boost::smatch what;
+
+				if (boost::regex_search(token, what, l_ALFTime)) {
+					auto spec (what[1].str());
+
+					formatters.emplace_back([spec](const LogAccess&, std::ostream& out) {
+						time_t now;
+						struct tm tmNow;
+
+						(void)time(&now);
+						(void)localtime_r(&now, &tmNow);
+
+						for (std::vector<char>::size_type size = 64;; size *= 2u) {
+							std::vector<char> buf (size);
+
+							if (strftime(buf.data(), size, spec.data(), &tmNow)) {
+								out << buf.data();
+								break;
+							} else if (!strlen(spec.data())) {
+								break;
+							}
+						}
+					});
+				} else if (boost::regex_search(token, what, l_ALFHeaders)) {
+					auto header (what[2].str());
+
+					if (what[1] == "request") {
+						formatters.emplace_back([header](const LogAccess& in, std::ostream& out) {
+							StreamHttpHeader(in.Request, header, out);
+						});
+					} else {
+						formatters.emplace_back([header](const LogAccess& in, std::ostream& out) {
+							StreamHttpHeader(in.Response, header, out);
+						});
+					}
+				} else {
+					throw std::invalid_argument("Bad macro '" + token + "'.");
+				}
+			} else {
+				formatters.emplace_back(formatter->second);
+			}
+		}
+
+		isLiteral = !isLiteral;
+	}
+
+	if (!literal.empty()) {
+		formatters.emplace_back([literal](const LogAccess&, std::ostream& out) {
+			out << literal;
+		});
+	}
+
+	switch (formatters.size()) {
+		case 0u:
+			return [](const LogAccess&, std::ostream&) { };
+		case 1u:
+			return std::move(formatters[0]);
+		default:
+			return [formatters](const LogAccess& in, std::ostream& out) {
+				for (auto& formatter : formatters) {
+					formatter(in, out);
+				}
+			};
+	}
+}

lib/base/accesslogger.hpp

@@ -0,0 +1,73 @@
+/* Icinga 2 | (c) 2020 Icinga GmbH | GPLv2+ */
+
+#ifndef ACCESSLOGGER_H
+#define ACCESSLOGGER_H
+
+#include "base/i2-base.hpp"
+#include "base/accesslogger-ti.hpp"
+#include "base/shared.hpp"
+#include "base/tlsstream.hpp"
+#include <boost/beast/core.hpp>
+#include <boost/beast/http.hpp>
+#include <functional>
+#include <utility>
+
+namespace icinga
+{
+
+class LogAccess
+{
+public:
+	inline LogAccess(
+		const AsioTlsStream& stream,
+		const boost::beast::http::request<boost::beast::http::string_body>& request,
+		String user,
+		const boost::beast::http::response<boost::beast::http::string_body>& response
+	) : Stream(stream), Request(request), User(std::move(user)), Response(response)
+	{}
+
+	LogAccess(const LogAccess&) = delete;
+	LogAccess(LogAccess&&) = delete;
+	LogAccess& operator=(const LogAccess&) = delete;
+	LogAccess& operator=(LogAccess&&) = delete;
+	~LogAccess();
+
+	const AsioTlsStream& Stream;
+	const boost::beast::http::request<boost::beast::http::string_body>& Request;
+	String User;
+	const boost::beast::http::response<boost::beast::http::string_body>& Response;
+};
+
+/**
+ * A file logger that logs API access.
+ *
+ * @ingroup base
+ */
+class AccessLogger final : public ObjectImpl<AccessLogger>
+{
+	friend LogAccess;
+
+public:
+	typedef void FormatterFunc(const LogAccess& in, std::ostream& out);
+	typedef std::function<FormatterFunc> Formatter;
+
+	DECLARE_OBJECT(AccessLogger);
+	DECLARE_OBJECTNAME(AccessLogger);
+
+	static void StatsFunc(const Dictionary::Ptr& status, const Array::Ptr& perfdata);
+
+protected:
+	void OnAllConfigLoaded() override;
+	void ValidateFormat(const Lazy<String>& lvalue, const ValidationUtils& utils) override;
+	void Register() override;
+	void Unregister() override;
+
+private:
+	Formatter ParseFormatter(const String& format);
+
+	Formatter m_Formatter;
+};
+
+}
+
+#endif /* ACCESSLOGGER_H */

lib/base/accesslogger.ti

@@ -0,0 +1,20 @@
+/* Icinga 2 | (c) 2020 Icinga GmbH | GPLv2+ */
+
+#include "base/filelogger.hpp"
+
+library base;
+
+namespace icinga
+{
+
+class AccessLogger : FileLogger
+{
+	activation_priority -99;
+
+	[config] String format {
+		default {{{ return R"EOF($remote.address$ - $remote.user$ [$time.%d/%b/%Y:%T %z$] "$request.method$ $request.uri$ HTTP/$request.protocol$" $response.status$ $response.size$
+)EOF"; }}}
+	};
+};
+
+}

lib/base/filelogger.cpp

@@ -35,7 +35,7 @@ void FileLogger::Start(bool runtimeCreated)
 
 	ObjectImpl<FileLogger>::Start(runtimeCreated);
 
-	Log(LogInformation, "FileLogger")
+	Log(LogInformation, GetReflectionType()->GetName())
 		<< "'" << GetName() << "' started.";
 }