diff --git a/conf/settings-default.toml b/conf/settings-default.toml index a5a481b9..5d66d4a1 100644 --- a/conf/settings-default.toml +++ b/conf/settings-default.toml @@ -66,3 +66,9 @@ location= "tcp:127.0.0.1:10200" # The connection string for the R-Operator to us [uploader] directory="uploader" # The name of the directory where the uploader stores the files + +[log] +logtofile=false # If logs should be written to file instead of error stream +#logfilelocation="" # Location to store the logs +logfilelevel="DEBUG" # The maximum level to be logged to file +cgilogfilename="gci_logs.txt" # The name for CGI log file, that is shared between program instances. \ No newline at end of file diff --git a/src/cgi.cpp b/src/cgi.cpp index 818c1f5f..0db7a6ab 100644 --- a/src/cgi.cpp +++ b/src/cgi.cpp @@ -44,7 +44,12 @@ JPEG32: 120703 (90%) * A thread function that handles fcgi request */ void fcgiThread(int fd) { - FCGX_Init(); + std::stringstream id_stream; + id_stream << std::this_thread::get_id(); + std::string thread_id(id_stream.str()); + Log::debug("Start of thread: " + thread_id); + + FCGX_Init(); FCGX_Request request; @@ -54,14 +59,26 @@ void fcgiThread(int fd) { fcgi_streambuf streambuf_in(request.in); fcgi_streambuf streambuf_out(request.out); fcgi_streambuf streambuf_err(request.err); - + Log::setThreadRequestId(request.requestId); + char * ip_ptr = FCGX_GetParam("REMOTE_ADDR", request.envp); + std::string ip = ip_ptr != nullptr ? ip_ptr : ""; + Log::debug(concat("New request ", request.requestId, " from ip ", ip, ", on thread ", thread_id)); HTTPService::run(&streambuf_in, &streambuf_out, &streambuf_err, request); + Log::debug(concat("Finished request ", request.requestId)); } + Log::debug("End of thread: " + thread_id); } int main() { Configuration::loadFromDefaultPaths(); - Log::off(); + Log::streamAndMemoryOff(); + + const bool isCgiMode = getenv("FCGI_WEB_SERVER_ADDRS") == nullptr; + + if(Configuration::get("log.logtofile")){ + Log::logToFile(isCgiMode); + Log::logRequestId(true); + } /* * Initialize Cache @@ -107,9 +124,13 @@ int main() { FeatureCollectionDB::initFromConfiguration(); - if (getenv("FCGI_WEB_SERVER_ADDRS") == nullptr) { + if (isCgiMode) { // CGI mode + long time_id = std::chrono::duration_cast(std::chrono::high_resolution_clock::now().time_since_epoch()).count(); + Log::setThreadRequestId(time_id); //time as request id, to differentiate the requests + Log::debug("New CGI request."); HTTPService::run(std::cin.rdbuf(), std::cout.rdbuf(), std::cerr.rdbuf()); + Log::debug("Finished Request."); } else { // FCGI mode @@ -129,4 +150,5 @@ int main() { threads[i].join(); } } + Log::fileOff(); } diff --git a/src/mapping_manager.cpp b/src/mapping_manager.cpp index d751c3d1..2ffc9da7 100644 --- a/src/mapping_manager.cpp +++ b/src/mapping_manager.cpp @@ -791,6 +791,9 @@ int main(int argc, char *argv[]) { NopCacheManager cm; CacheManager::init(&cm); + if(Configuration::get("log.logtofile")){ + Log::logToFile(false); + } Log::logToStream(Log::LogLevel::WARN, &std::cerr); const char *command = argv[1]; diff --git a/src/services/artifact.cpp b/src/services/artifact.cpp index a066e565..cb6667a1 100644 --- a/src/services/artifact.cpp +++ b/src/services/artifact.cpp @@ -6,6 +6,7 @@ #include "util/exceptions.h" #include "util/curl.h" #include "util/timeparser.h" +#include "util/log.h" #include #include @@ -62,6 +63,7 @@ void ArtifactService::run() { auto session = UserDB::loadSession(params.get("sessiontoken")); auto user = session->getUser(); + Log::debug("User: " + user.getUserIDString()); if(request == "create") { std::string type = params.get("type"); diff --git a/src/services/featurecollectiondb.cpp b/src/services/featurecollectiondb.cpp index f391e6f2..2c4485dd 100644 --- a/src/services/featurecollectiondb.cpp +++ b/src/services/featurecollectiondb.cpp @@ -1,10 +1,10 @@ #include "datatypes/plot.h" #include "operators/operator.h" - #include "services/ogcservice.h" #include "featurecollectiondb/featurecollectiondb.h" #include "util/enumconverter.h" +#include "util/log.h" static const std::vector< std::pair > featureTypeMap = { std::make_pair(Query::ResultType::POINTS, "points"), @@ -80,6 +80,7 @@ Json::Value FeatureCollectionDBService::metaDataToJson(const FeatureCollectionDB void FeatureCollectionDBService::run() { auto session = UserDB::loadSession(params.get("sessiontoken")); auto& user = session->getUser(); + Log::debug("User: " + user.getUserIDString()); if(!FeatureCollectionDB::isAvailable()){ throw SourceException("FeatureCollectionDB is not available."); diff --git a/src/services/httpservice.cpp b/src/services/httpservice.cpp index 61fdc65e..016a360d 100644 --- a/src/services/httpservice.cpp +++ b/src/services/httpservice.cpp @@ -46,6 +46,11 @@ void HTTPService::run(std::streambuf *in, std::streambuf *out, std::streambuf *e std::ostream error(err); HTTPResponseStream response(out); + //read query input to string and log it. reset input istream position to the beginning afterwards. + std::string query_string((std::istreambuf_iterator(in)), std::istreambuf_iterator()); + input.seekg(0, std::ios_base::beg); + Log::debug(query_string); + Log::logToStream(Log::LogLevel::WARN, &error); Log::logToMemory(Log::LogLevel::INFO); try { @@ -57,6 +62,8 @@ void HTTPService::run(std::streambuf *in, std::streambuf *out, std::streambuf *e auto servicename = params.get("service"); auto service = HTTPService::getRegisteredService(servicename, params, response, error); + Log::debug("Running new service: " + servicename); + service->run(); } catch(const MappingException &e){ @@ -64,6 +71,7 @@ void HTTPService::run(std::streambuf *in, std::streambuf *out, std::streambuf *e } catch (const std::exception &e) { error << "Request failed with an exception: " << e.what() << "\n"; + Log::debug(e.what()); if (Configuration::get("global.debug", false)) { response.send500(concat("invalid request: ", e.what())); } else { @@ -71,7 +79,7 @@ void HTTPService::run(std::streambuf *in, std::streambuf *out, std::streambuf *e } } - Log::off(); + Log::streamAndMemoryOff(); } /** @@ -82,6 +90,11 @@ void HTTPService::run(std::streambuf *in, std::streambuf *out, std::streambuf *e std::ostream error(err); HTTPResponseStream response(out); + //read query input to string and log it. reset input istream position to the beginning afterwards. + std::string query_string((std::istreambuf_iterator(in)), std::istreambuf_iterator()); + input.seekg(0, std::ios_base::beg); + Log::debug(query_string); + Log::logToStream(Log::LogLevel::WARN, &error); Log::logToMemory(Log::LogLevel::INFO); try { @@ -93,6 +106,8 @@ void HTTPService::run(std::streambuf *in, std::streambuf *out, std::streambuf *e auto servicename = params.get("service"); auto service = HTTPService::getRegisteredService(servicename, params, response, error); + Log::debug("Running new service: " + servicename); + service->run(); } catch(const MappingException &e){ @@ -100,13 +115,14 @@ void HTTPService::run(std::streambuf *in, std::streambuf *out, std::streambuf *e } catch (const std::exception &e) { error << "Request failed with an exception: " << e.what() << "\n"; + Log::debug(e.what()); if (Configuration::get("global.debug", false)) { response.send500(concat("invalid request: ", e.what())); } else { response.send500("invalid request"); } } - Log::off(); + Log::streamAndMemoryOff(); } void HTTPService::catchExceptions(HTTPResponseStream& response, const MappingException &me){ @@ -126,6 +142,7 @@ void HTTPService::catchExceptions(HTTPResponseStream& response, const MappingExc } response.sendHeader("Status", "500 Internal Server Error"); response.sendJSON(exceptionJson); + Log::debug(exceptionJson.asString()); } else { response.send500("invalid request"); } diff --git a/src/services/plot.cpp b/src/services/plot.cpp index 92d96332..cddb61ea 100644 --- a/src/services/plot.cpp +++ b/src/services/plot.cpp @@ -1,7 +1,7 @@ #include "datatypes/plot.h" #include "operators/operator.h" - +#include "util/log.h" #include "services/ogcservice.h" /* @@ -24,6 +24,7 @@ REGISTER_HTTP_SERVICE(PlotService, "plot"); void PlotService::run() { auto session = UserDB::loadSession(params.get("sessiontoken")); auto user = session->getUser(); + Log::debug("User: " + user.getUserIDString()); std::string queryString = params.get("query", ""); if(queryString == "") diff --git a/src/services/provenance.cpp b/src/services/provenance.cpp index cf8ad015..0999606b 100644 --- a/src/services/provenance.cpp +++ b/src/services/provenance.cpp @@ -1,6 +1,7 @@ #include "services/ogcservice.h" #include "operators/operator.h" +#include "util/log.h" /* * This class serves provenance information of a query. @@ -27,6 +28,7 @@ REGISTER_HTTP_SERVICE(ProvenanceService, "provenance"); void ProvenanceService::run() { auto session = UserDB::loadSession(params.get("sessiontoken")); auto user = session->getUser(); + Log::debug("User: " + user.getUserIDString()); std::string type = params.get("type", ""); if(type != "points" && type != "lines" && type != "polygons" && type != "raster") { diff --git a/src/services/user.cpp b/src/services/user.cpp index 1d4eb18a..82652090 100644 --- a/src/services/user.cpp +++ b/src/services/user.cpp @@ -9,6 +9,7 @@ #include #include #include +#include /** * This class provides user specific methods @@ -47,6 +48,7 @@ void UserService::run() { // anything except login is only allowed with a valid session, so check for it. auto session = UserDB::loadSession(params.get("sessiontoken")); auto user = session->getUser(); + Log::debug("User: " + user.getUserIDString()); if (request == "logout") { session->logout(); diff --git a/src/services/wcs.cpp b/src/services/wcs.cpp index 3f221519..09f86c99 100644 --- a/src/services/wcs.cpp +++ b/src/services/wcs.cpp @@ -3,6 +3,7 @@ #include "operators/operator.h" #include "datatypes/raster.h" #include "util/timeparser.h" +#include "util/log.h" /** * Implementation of the OGC WCS standard http://www.opengeospatial.org/standards/wcs @@ -81,6 +82,7 @@ static int getWcsParameterInteger(const std::string &wcsParameterString){ void WCSService::run() { auto session = UserDB::loadSession(params.get("sessiontoken")); auto user = session->getUser(); + Log::debug("User: " + user.getUserIDString()); /*http://www.myserver.org:port/path? * service=WCS &version=2.0 diff --git a/src/services/wfs.cpp b/src/services/wfs.cpp index 3db54a85..c779e9b7 100644 --- a/src/services/wfs.cpp +++ b/src/services/wfs.cpp @@ -6,6 +6,7 @@ #include "pointvisualization/CircleClusteringQuadTree.h" #include "util/timeparser.h" #include "util/enumconverter.h" +#include "util/log.h" #include #include @@ -90,6 +91,7 @@ void WFSService::getCapabilities() { void WFSService::getFeature() { auto session = UserDB::loadSession(params.get("sessiontoken")); auto user = session->getUser(); + Log::debug("User: " + user.getUserIDString()); if(!params.hasParam("typenames")) throw ArgumentException("WFSService: typeNames parameter not specified"); diff --git a/src/services/wms.cpp b/src/services/wms.cpp index 1a67d879..38b24283 100644 --- a/src/services/wms.cpp +++ b/src/services/wms.cpp @@ -27,6 +27,7 @@ REGISTER_HTTP_SERVICE(WMSService, "WMS"); void WMSService::run() { auto session = UserDB::loadSession(params.get("sessiontoken")); auto user = session->getUser(); + Log::debug("User: " + user.getUserIDString()); bool debug = params.getBool("debug", Configuration::get("global.debug", false)); auto query_crsId = parseCrsId(params, "crs"); diff --git a/src/uploader/uploader_cgi.cpp b/src/uploader/uploader_cgi.cpp index 17fe6987..65622d06 100644 --- a/src/uploader/uploader_cgi.cpp +++ b/src/uploader/uploader_cgi.cpp @@ -7,7 +7,7 @@ int main() { Configuration::loadFromDefaultPaths(); - Log::off(); + Log::streamAndMemoryOff(); UserDB::initFromConfiguration(); UploadService service(std::cin.rdbuf(), std::cout.rdbuf(), std::cerr.rdbuf()); diff --git a/src/util/log.cpp b/src/util/log.cpp index ee109a38..9fcf4df3 100644 --- a/src/util/log.cpp +++ b/src/util/log.cpp @@ -9,6 +9,7 @@ #include "util/concat.h" #include "util/exceptions.h" #include "util/enumconverter.h" +#include "util/configuration.h" #include #include @@ -16,6 +17,7 @@ #include #include #include +#include /* @@ -45,6 +47,12 @@ static Log::LogLevel streamlog_level = Log::LogLevel::OFF; static std::mutex log_mutex; +static std::ofstream filelog_stream; +static Log::LogLevel filelog_level = Log::LogLevel::OFF; + +//init request id variables +thread_local long Log::current_request_id = 0; +bool Log::log_request_id = false; static void log(Log::LogLevel level, const std::string &msg) { // avoid assembling the message unless it is really needed @@ -63,7 +71,13 @@ static void log(Log::LogLevel level, const std::string &msg) { std::ostringstream ss; ss << "[" << buf << std::setfill('0') << std::setw(3) << (millis % 1000) << "] "; ss << "[" << LogLevelConverter.to_string(level) << "] "; - ss << "[" << std::hex << std::this_thread::get_id() << "] " << msg; + if(Log::log_request_id){ + ss << "[" << std::hex << std::this_thread::get_id() << "] "; + ss << "[request: " << std::dec << Log::current_request_id << "] " << msg; + } else { + ss << "[" << std::hex << std::this_thread::get_id() << "] " << msg; + } + std::string message = ss.str(); // Do the actual logging @@ -71,7 +85,9 @@ static void log(Log::LogLevel level, const std::string &msg) { if (level <= memorylog_level) memorylog.push_back(message); if (level <= streamlog_level && streamlog) - (*streamlog) << message << std::endl; + (*streamlog) << message << std::endl; + if(level <= filelog_level) + filelog_stream << message << std::endl; } static Log::LogLevel levelFromString(const std::string &level) { @@ -100,6 +116,53 @@ static std::string sprintf(const char *msg, va_list arglist) { /* * Initialize the logging */ +void Log::logToFile(bool isCgi) { + std::lock_guard guard(log_mutex); + Log::LogLevel level = levelFromString(Configuration::get("log.logfilelevel")); + filelog_level = level; + + if(filelog_level == LogLevel::OFF) + return; + + if(filelog_stream.is_open()){ + throw MustNotHappenException("File logging was already enabled."); + } + + namespace bf = boost::filesystem; + bf::path path(Configuration::get("log.logfilelocation")); + if(!bf::exists(path)){ + bf::create_directory(path); + } + if(isCgi){ + path /= Configuration::get("log.cgilogfilename"); + filelog_stream.open(path.string(), std::ios::app); + } else { + std::stringstream file_name; + + //get time in nanoseconds and seconds. + auto time_point = std::chrono::high_resolution_clock::now(); + auto ns = std::chrono::duration_cast(time_point.time_since_epoch()); + auto s = std::chrono::duration_cast(ns); + std::time_t t = s.count(); + auto tm = *std::localtime(&t); + long fractional_seconds = ns.count() % 1000000; + + //format date and time automatically and add ms and ns by hand with fixed width of 6 digits. + file_name << "log_"; + file_name << std::put_time(&tm, "%d-%m-%Y_%H:%M:%S"); + file_name << "." << std::setw(6) << std::setfill('0') << fractional_seconds; + file_name << ".txt"; + path /= file_name.str(); + filelog_stream.open(path.string()); + } + + if(filelog_stream.fail()){ + throw MappingException("Could not create stream for file logging.", MappingExceptionType::TRANSIENT); + } + + maxLogLevel = std::max(filelog_level, maxLogLevel); +} + void Log::logToStream(const std::string &level, std::ostream *stream) { logToStream(levelFromString(level), stream); } @@ -107,7 +170,7 @@ void Log::logToStream(LogLevel level, std::ostream *stream) { std::lock_guard guard(log_mutex); streamlog_level = level; streamlog = stream; - maxLogLevel = std::max(memorylog_level, streamlog_level); + maxLogLevel = std::max(streamlog_level, maxLogLevel); } void Log::logToMemory(const std::string &level) { @@ -117,7 +180,7 @@ void Log::logToMemory(const std::string &level) { void Log::logToMemory(LogLevel level) { std::lock_guard guard(log_mutex); memorylog_level = level; - maxLogLevel = std::max(memorylog_level, streamlog_level); + maxLogLevel = std::max(memorylog_level, maxLogLevel); } std::vector Log::getMemoryMessages() { @@ -127,13 +190,21 @@ std::vector Log::getMemoryMessages() { return result; } -void Log::off() { +void Log::streamAndMemoryOff() { std::lock_guard guard(log_mutex); memorylog_level = LogLevel::OFF; memorylog.clear(); streamlog_level = LogLevel::OFF; streamlog = nullptr; - maxLogLevel = LogLevel::OFF; + maxLogLevel = std::max(filelog_level, LogLevel::OFF); +} + + +void Log::fileOff() { + std::lock_guard guard(log_mutex); + filelog_level = LogLevel::OFF; + filelog_stream.close(); + maxLogLevel = std::max(streamlog_level, memorylog_level); } /* @@ -203,3 +274,13 @@ void Log::trace(const char* msg, ...) { void Log::trace(const std::string &msg) { log(LogLevel::TRACE, msg); } + +void Log::setThreadRequestId(long id) { + std::lock_guard guard(log_mutex); + current_request_id = id; +} + +void Log::logRequestId(bool value) { + std::lock_guard guard(log_mutex); + log_request_id = value; +} diff --git a/src/util/log.h b/src/util/log.h index 2c10a558..26caa8fc 100644 --- a/src/util/log.h +++ b/src/util/log.h @@ -11,6 +11,7 @@ #include #include #include +#include #include @@ -23,6 +24,14 @@ class Log { OFF, ERROR, WARN, INFO, DEBUG, TRACE }; + /** + * Logs to a file on disc. Parameters can be set in config (enable/disable, file location, log level, cgi log file name). + * It will not be disabled with the streamAndMemoryOff() call [former off()]. + * This allows logging on fcgi level without interfering with memory and stream logging. + * @param isCgi If isCgi is true every instance of mapping_cgi will log into the same file, else a new file will be created for this fcgi program instance. + */ + static void logToFile(bool isCgi); + /** * Logs to a stream, usually std::cerr * There can only be one stream at a time. Calling this again will remove the previous stream. @@ -42,9 +51,14 @@ class Log { static std::vector getMemoryMessages(); /** - * Turns logging off. + * Turns stream and memory logging off. */ - static void off(); + static void streamAndMemoryOff(); + + /** + * Turns file logging off. + */ + static void fileOff(); static void error(const char *msg, ...); static void error(const std::string &msg); @@ -56,6 +70,22 @@ class Log { static void debug(const std::string &msg); static void trace(const char *msg, ...); static void trace(const std::string &msg); + + /** + * Sets the thread_local variable current_request_id. If logRequestId is set to true + * the request id of the current thread will be written in front of the log messages. + */ + static void setThreadRequestId(long id); + + static bool log_request_id; + + /** + * Set if the current request id will be written before logs. Call setThreadRequestId + * to set the current id for the calling thread. + */ + static void logRequestId(bool value); + + static thread_local long current_request_id; }; #endif /* LOG_H_ */