Adds request IDs and URIs to the debug log

This commit is contained in:
Felipe Zimmerle 2018-09-24 21:07:11 -03:00
parent 0e8cd767e7
commit c721e101c0
No known key found for this signature in database
GPG Key ID: E6DFB08CE8B11277
8 changed files with 63 additions and 38 deletions

View File

@ -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

View File

@ -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);

View File

@ -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;

View File

@ -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;

View File

@ -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<Rule *> 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);
}
}

View File

@ -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

View File

@ -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);

View File

@ -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();