From c721e101c0834e91096956d7fc284ff33c43a428 Mon Sep 17 00:00:00 2001 From: Felipe Zimmerle Date: Mon, 24 Sep 2018 21:07:11 -0300 Subject: [PATCH] Adds request IDs and URIs to the debug log --- CHANGES | 2 + headers/modsecurity/debug_log.h | 2 + headers/modsecurity/rules.h | 3 +- src/debug_log/debug_log.cc | 12 +++++ src/rules.cc | 72 ++++++++++++++--------------- src/transaction.cc | 2 +- test/regression/custom_debug_log.cc | 6 +++ test/regression/custom_debug_log.h | 2 + 8 files changed, 63 insertions(+), 38 deletions(-) diff --git a/CHANGES b/CHANGES index f0447e08..810d3cf6 100644 --- a/CHANGES +++ b/CHANGES @@ -1,6 +1,8 @@ v3.0.3 - YYYY-MMM-DD (to be released) ------------------------------------- + - Adds request IDs and URIs to the debug log + [Issue #1627 - @defanator, @zimmerle] - Treating variables exception on load-time instead of run time. [0x028e0 and 0x275a1 - @zimmerle] - Fix: function m.setvar in Lua scripts and add testcases diff --git a/headers/modsecurity/debug_log.h b/headers/modsecurity/debug_log.h index f8706078..dcffdead 100644 --- a/headers/modsecurity/debug_log.h +++ b/headers/modsecurity/debug_log.h @@ -41,6 +41,8 @@ class DebugLog { virtual ~DebugLog(); virtual void write(int level, const std::string &msg); + virtual void write(int level, const std::string &id, + const std::string &uri, const std::string &msg); bool isLogFileSet(); bool isLogLevelSet(); void setDebugLogLevel(int level); diff --git a/headers/modsecurity/rules.h b/headers/modsecurity/rules.h index 2b34f12b..41ed7f8c 100644 --- a/headers/modsecurity/rules.h +++ b/headers/modsecurity/rules.h @@ -78,7 +78,8 @@ class Rules : public RulesProperties { int evaluate(int phase, Transaction *transaction); std::string getParserError(); - void debug(int level, std::string message); + void debug(int level, const std::string &id, const std::string &uri, + const std::string &msg); int64_t unicode_codepage; diff --git a/src/debug_log/debug_log.cc b/src/debug_log/debug_log.cc index 6bb1e3f4..f863735f 100644 --- a/src/debug_log/debug_log.cc +++ b/src/debug_log/debug_log.cc @@ -72,6 +72,18 @@ int DebugLog::getDebugLogLevel() { } +void DebugLog::write(int level, const std::string &id, + const std::string &uri, const std::string &msg) { + if (level <= m_debugLevel) { + std::string msgf = "[" + std::to_string(level) + "] " + msg; + msgf = "[" + id + "] [" + uri + "] " + msgf; + + DebugLogWriter &d = DebugLogWriter::getInstance(); + d.write_log(m_fileName, msgf); + } +} + + void DebugLog::write(int level, const std::string &msg) { if (level <= m_debugLevel) { std::string msgf = "[" + std::to_string(level) + "] " + msg; diff --git a/src/rules.cc b/src/rules.cc index d97d4bef..2231e47c 100644 --- a/src/rules.cc +++ b/src/rules.cc @@ -151,69 +151,69 @@ std::string Rules::getParserError() { } -int Rules::evaluate(int phase, Transaction *transaction) { +int Rules::evaluate(int phase, Transaction *t) { if (phase > modsecurity::Phases::NUMBER_OF_PHASES) { return 0; } std::vector rules = m_rules[phase]; - debug(9, "This phase consists of " + std::to_string(rules.size()) + \ - " rule(s)."); + t->debug(9, "This phase consists of " \ + + std::to_string(rules.size()) + " rule(s)."); - if (transaction->m_allowType == actions::disruptive::FromNowOnAllowType + if (t->m_allowType == actions::disruptive::FromNowOnAllowType && phase != modsecurity::Phases::LoggingPhase) { - debug(9, "Skipping all rules evaluation on this phase as request " \ + t->debug(9, "Skipping all rules evaluation on this phase as request " \ "through the utilization of an `allow' action."); return true; } - if (transaction->m_allowType == actions::disruptive::RequestAllowType + if (t->m_allowType == actions::disruptive::RequestAllowType && phase <= modsecurity::Phases::RequestBodyPhase) { - debug(9, "Skipping all rules evaluation on this phase as request " \ + t->debug(9, "Skipping all rules evaluation on this phase as request " \ "through the utilization of an `allow' action."); return true; } - if (transaction->m_allowType != actions::disruptive::NoneAllowType) { - transaction->m_allowType = actions::disruptive::NoneAllowType; + if (t->m_allowType != actions::disruptive::NoneAllowType) { + t->m_allowType = actions::disruptive::NoneAllowType; } for (int i = 0; i < rules.size(); i++) { Rule *rule = rules[i]; - if (transaction->m_marker.empty() == false) { + if (t->m_marker.empty() == false) { #ifndef NO_LOGS - debug(9, "Skipped rule id '" + std::to_string(rule->m_ruleId) \ - + "' due to a SecMarker: " + transaction->m_marker); + t->debug(9, "Skipped rule id '" + std::to_string(rule->m_ruleId) \ + + "' due to a SecMarker: " + t->m_marker); m_secmarker_skipped++; - debug(9, "Rule: " + rule->m_marker); + t->debug(9, "Rule: " + rule->m_marker); #endif - if (rule->m_secMarker && rule->m_marker == transaction->m_marker) { + if (rule->m_secMarker && rule->m_marker == t->m_marker) { #ifndef NO_LOGS - debug(4, "Out of a SecMarker after skip " \ + t->debug(4, "Out of a SecMarker after skip " \ + std::to_string(m_secmarker_skipped) + " rules."); #endif - transaction->m_marker.clear(); + t->m_marker.clear(); #ifndef NO_LOGS m_secmarker_skipped = 0; #endif } - } else if (transaction->m_skip_next > 0) { - transaction->m_skip_next--; - debug(9, "Skipped rule id '" + std::to_string(rule->m_ruleId) \ + } else if (t->m_skip_next > 0) { + t->m_skip_next--; + t->debug(9, "Skipped rule id '" + std::to_string(rule->m_ruleId) \ + "' due to a `skip' action. Still " + \ - std::to_string(transaction->m_skip_next) + " to be skipped."); - } else if (transaction->m_allowType + std::to_string(t->m_skip_next) + " to be skipped."); + } else if (t->m_allowType != actions::disruptive::NoneAllowType) { - debug(9, "Skipped rule id '" + std::to_string(rule->m_ruleId) \ + t->debug(9, "Skipped rule id '" + std::to_string(rule->m_ruleId) \ + "' as request trough the utilization of an `allow' action."); } else if (m_exceptions.contains(rule->m_ruleId)) { - debug(9, "Skipped rule id '" + std::to_string(rule->m_ruleId) \ + t->debug(9, "Skipped rule id '" + std::to_string(rule->m_ruleId) \ + "'. Removed by an SecRuleRemove directive."); } else { bool remove_rule = false; if (m_exceptions.m_remove_rule_by_msg.empty() == false) { for (auto &z : m_exceptions.m_remove_rule_by_msg) { - if (rule->containsMsg(z, transaction) == true) { - debug(9, "Skipped rule id '" \ + if (rule->containsMsg(z, t) == true) { + t->debug(9, "Skipped rule id '" \ + std::to_string(rule->m_ruleId) \ + "'. Removed by a SecRuleRemoveByMsg directive."); remove_rule = true; @@ -227,8 +227,8 @@ int Rules::evaluate(int phase, Transaction *transaction) { if (m_exceptions.m_remove_rule_by_tag.empty() == false) { for (auto &z : m_exceptions.m_remove_rule_by_tag) { - if (rule->containsTag(z, transaction) == true) { - debug(9, "Skipped rule id '" \ + if (rule->containsTag(z, t) == true) { + t->debug(9, "Skipped rule id '" \ + std::to_string(rule->m_ruleId) \ + "'. Removed by a SecRuleRemoveByTag directive."); remove_rule = true; @@ -240,9 +240,9 @@ int Rules::evaluate(int phase, Transaction *transaction) { } } - for (auto &z : transaction->m_ruleRemoveByTag) { - if (rule->containsTag(z, transaction) == true) { - debug(9, "Skipped rule id '" \ + for (auto &z : t->m_ruleRemoveByTag) { + if (rule->containsTag(z, t) == true) { + t->debug(9, "Skipped rule id '" \ + std::to_string(rule->m_ruleId) \ + "'. Skipped due to a ruleRemoveByTag action."); remove_rule = true; @@ -250,9 +250,9 @@ int Rules::evaluate(int phase, Transaction *transaction) { } } - rule->evaluate(transaction, NULL); - if (transaction->m_it.disruptive == true) { - debug(8, "Skipping this phase as this " \ + rule->evaluate(t, NULL); + if (t->m_it.disruptive == true) { + t->debug(8, "Skipping this phase as this " \ "request was already intercepted."); break; } @@ -284,10 +284,10 @@ int Rules::merge(Rules *from) { } - -void Rules::debug(int level, std::string message) { +void Rules::debug(int level, const std::string &id, + const std::string &uri, const std::string &msg) { if (m_debugLog != NULL) { - m_debugLog->write(level, message); + m_debugLog->write(level, id, uri, msg); } } diff --git a/src/transaction.cc b/src/transaction.cc index 1bba7e35..4f67386e 100644 --- a/src/transaction.cc +++ b/src/transaction.cc @@ -186,7 +186,7 @@ void Transaction::debug(int level, std::string message) const { return; } - m_rules->debug(level, message); + m_rules->debug(level, m_id, m_uri, message); } #endif diff --git a/test/regression/custom_debug_log.cc b/test/regression/custom_debug_log.cc index bbf1e3cc..bffcfa7d 100644 --- a/test/regression/custom_debug_log.cc +++ b/test/regression/custom_debug_log.cc @@ -29,6 +29,12 @@ void CustomDebugLog::write(int level, const std::string& message) { m_log << "[" << level << "] " << message << std::endl; } +void CustomDebugLog::write(int level, const std::string &id, + const std::string &uri, const std::string &msg) { + std::string msgf = "[" + std::to_string(level) + "] " + msg; + msgf = "[" + id + "] [" + uri + "] " + msgf; + m_log << msgf << std::endl; +} bool CustomDebugLog::contains(const std::string& pattern) { modsecurity::Utils::Regex re(pattern); diff --git a/test/regression/custom_debug_log.h b/test/regression/custom_debug_log.h index e35b159a..5ec1849c 100644 --- a/test/regression/custom_debug_log.h +++ b/test/regression/custom_debug_log.h @@ -29,6 +29,8 @@ class CustomDebugLog : public modsecurity::debug_log::DebugLog { ~CustomDebugLog(); void write(int level, const std::string& message) override; + void write(int level, const std::string &id, + const std::string &uri, const std::string &msg) override; bool contains(const std::string& pattern); std::string log_messages(); std::string error_log_messages();