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.";
 }
 

lib/base/filelogger.hpp

@@ -14,7 +14,7 @@ namespace icinga
  *
  * @ingroup base
  */
-class FileLogger final : public ObjectImpl<FileLogger>
+class FileLogger : public ObjectImpl<FileLogger>
 {
 public:
 	DECLARE_OBJECT(FileLogger);

lib/base/logger.cpp

@@ -53,7 +53,17 @@ INITIALIZE_ONCE([]() {
 void Logger::Start(bool runtimeCreated)
 {
 	ObjectImpl<Logger>::Start(runtimeCreated);
+	Register();
+}
 
+void Logger::Stop(bool runtimeRemoved)
+{
+	Unregister();
+	ObjectImpl<Logger>::Stop(runtimeRemoved);
+}
+
+void Logger::Register()
+{
 	{
 		std::unique_lock<std::mutex> lock(m_Mutex);
 		m_Loggers.insert(this);
@@ -62,7 +72,7 @@ void Logger::Start(bool runtimeCreated)
 	UpdateMinLogSeverity();
 }
 
-void Logger::Stop(bool runtimeRemoved)
+void Logger::Unregister()
 {
 	{
 		std::unique_lock<std::mutex> lock(m_Mutex);
@@ -70,8 +80,6 @@ void Logger::Stop(bool runtimeRemoved)
 	}
 
 	UpdateMinLogSeverity();
-
-	ObjectImpl<Logger>::Stop(runtimeRemoved);
 }
 
 std::set<Logger::Ptr> Logger::GetLoggers()

lib/base/logger.hpp

@@ -93,6 +93,9 @@ protected:
 	void Start(bool runtimeCreated) override;
 	void Stop(bool runtimeRemoved) override;
 
+	virtual void Register();
+	virtual void Unregister();
+
 private:
 	static void UpdateMinLogSeverity();
 

lib/base/streamlogger.hpp

@@ -31,10 +31,10 @@ public:
 protected:
 	void ProcessLogEntry(const LogEntry& entry) final;
 	void Flush() final;
+	std::ostream *m_Stream{nullptr};
 
 private:
 	static std::mutex m_Mutex;
-	std::ostream *m_Stream{nullptr};
 	bool m_OwnsStream{false};
 
 	Timer::Ptr m_FlushLogTimer;

lib/remote/eventshandler.cpp

@@ -5,6 +5,7 @@
 #include "remote/filterutility.hpp"
 #include "config/configcompiler.hpp"
 #include "config/expression.hpp"
+#include "base/accesslogger.hpp"
 #include "base/defer.hpp"
 #include "base/io-engine.hpp"
 #include "base/objectlock.hpp"
@@ -105,6 +106,8 @@ bool EventsHandler::HandleRequest(
 	response.result(http::status::ok);
 	response.set(http::field::content_type, "application/json");
 
+	LogAccess(stream, request, user ? user->GetName() : "", response);
+
 	IoBoundWorkSlot dontLockTheIoThread (yc);
 
 	http::async_write(stream, response, yc);

lib/remote/httpserverconnection.cpp

@@ -6,6 +6,7 @@
 #include "remote/apilistener.hpp"
 #include "remote/apifunction.hpp"
 #include "remote/jsonrpc.hpp"
+#include "base/accesslogger.hpp"
 #include "base/application.hpp"
 #include "base/base64.hpp"
 #include "base/convert.hpp"
@@ -143,10 +144,16 @@ bool EnsureValidHeaders(
 		return false;
 
 	bool httpError = false;
+	bool logAccess = true;
 	String errorMsg;
 
 	boost::system::error_code ec;
 
+	if (!buf.size() && !stream.in_avail()) {
+		boost::system::error_code ec;
+		logAccess = stream.async_fill(yc[ec]);
+	}
+
 	http::async_read_header(stream, buf, parser, yc[ec]);
 
 	if (ec) {
@@ -181,6 +188,10 @@ bool EnsureValidHeaders(
 
 		response.set(http::field::connection, "close");
 
+		if (logAccess) {
+			LogAccess(stream, parser.get(), "", response);
+		}
+
 		http::async_write(stream, response, yc);
 		stream.async_flush(yc);
 
@@ -213,6 +224,7 @@ static inline
 bool HandleAccessControl(
 	AsioTlsStream& stream,
 	boost::beast::http::request<boost::beast::http::string_body>& request,
+	ApiUser::Ptr& authenticatedUser,
 	boost::beast::http::response<boost::beast::http::string_body>& response,
 	boost::asio::yield_context& yc
 )
@@ -244,6 +256,8 @@ bool HandleAccessControl(
 					response.content_length(response.body().size());
 					response.set(http::field::connection, "close");
 
+					LogAccess(stream, request, authenticatedUser ? authenticatedUser->GetName() : "", response);
+
 					http::async_write(stream, response, yc);
 					stream.async_flush(yc);
 
@@ -260,6 +274,7 @@ static inline
 bool EnsureAcceptHeader(
 	AsioTlsStream& stream,
 	boost::beast::http::request<boost::beast::http::string_body>& request,
+	ApiUser::Ptr& authenticatedUser,
 	boost::beast::http::response<boost::beast::http::string_body>& response,
 	boost::asio::yield_context& yc
 )
@@ -273,6 +288,8 @@ bool EnsureAcceptHeader(
 		response.content_length(response.body().size());
 		response.set(http::field::connection, "close");
 
+		LogAccess(stream, request, authenticatedUser ? authenticatedUser->GetName() : "", response);
+
 		http::async_write(stream, response, yc);
 		stream.async_flush(yc);
 
@@ -312,6 +329,8 @@ bool EnsureAuthenticatedUser(
 			response.content_length(response.body().size());
 		}
 
+		LogAccess(stream, request, "", response);
+
 		http::async_write(stream, response, yc);
 		stream.async_flush(yc);
 
@@ -326,6 +345,7 @@ bool EnsureValidBody(
 	AsioTlsStream& stream,
 	boost::beast::flat_buffer& buf,
 	boost::beast::http::parser<true, boost::beast::http::string_body>& parser,
+	boost::beast::http::request<boost::beast::http::string_body>& request,
 	ApiUser::Ptr& authenticatedUser,
 	boost::beast::http::response<boost::beast::http::string_body>& response,
 	bool& shuttingDown,
@@ -402,6 +422,8 @@ bool EnsureValidBody(
 
 		response.set(http::field::connection, "close");
 
+		LogAccess(stream, request, authenticatedUser ? authenticatedUser->GetName() : "", response);
+
 		http::async_write(stream, response, yc);
 		stream.async_flush(yc);
 
@@ -447,6 +469,8 @@ bool ProcessRequest(
 
 		HttpUtility::SendJsonError(response, nullptr, 500, "Unhandled exception" , DiagnosticInformation(ex));
 
+		LogAccess(stream, request, authenticatedUser ? authenticatedUser->GetName() : "", response);
+
 		http::async_write(stream, response, yc);
 		stream.async_flush(yc);
 
@@ -457,6 +481,8 @@ bool ProcessRequest(
 		return false;
 	}
 
+	LogAccess(stream, request, authenticatedUser ? authenticatedUser->GetName() : "", response);
+
 	http::async_write(stream, response, yc);
 	stream.async_flush(yc);
 
@@ -530,11 +556,11 @@ void HttpServerConnection::ProcessMessages(boost::asio::yield_context yc)
 				logMsg << " took total " << ch::duration_cast<ch::milliseconds>(ch::steady_clock::now() - start).count() << "ms.";
 			});
 
-			if (!HandleAccessControl(*m_Stream, request, response, yc)) {
+			if (!HandleAccessControl(*m_Stream, request, authenticatedUser, response, yc)) {
 				break;
 			}
 
-			if (!EnsureAcceptHeader(*m_Stream, request, response, yc)) {
+			if (!EnsureAcceptHeader(*m_Stream, request, authenticatedUser, response, yc)) {
 				break;
 			}
 
@@ -542,7 +568,7 @@ void HttpServerConnection::ProcessMessages(boost::asio::yield_context yc)
 				break;
 			}
 
-			if (!EnsureValidBody(*m_Stream, buf, parser, authenticatedUser, response, m_ShuttingDown, yc)) {
+			if (!EnsureValidBody(*m_Stream, buf, parser, request, authenticatedUser, response, m_ShuttingDown, yc)) {
 				break;
 			}