Additional updates for JSON logging

* Write Stopwatch2 values into a separate map
* Remove legacy Stopwatch
* Proper sanitization of request/response headers
* Lazily open maps for keys that may not have content
This commit is contained in:
Robert Paprocki
2015-07-16 15:33:52 -07:00
committed by Felipe Zimmerle
parent 7b2ca1617e
commit dd79bea0b4

View File

@@ -520,6 +520,26 @@ static int chained_is_matched(modsec_rec *msr, const msre_rule *next_rule) {
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
/**
* Write detailed information about performance metrics into a JSON generator
*/
static void format_performance_variables_json(modsec_rec *msr, yajl_gen g) {
yajl_string(g, "stopwatch");
yajl_gen_map_open(g);
yajl_kv_int(g, "p1", msr->time_phase1);
yajl_kv_int(g, "p2", msr->time_phase2);
yajl_kv_int(g, "p3", msr->time_phase3);
yajl_kv_int(g, "p4", msr->time_phase4);
yajl_kv_int(g, "p5", msr->time_phase5);
yajl_kv_int(g, "sr", msr->time_storage_read);
yajl_kv_int(g, "sw", msr->time_storage_write);
yajl_kv_int(g, "l", msr->time_logging);
yajl_kv_int(g, "gc", msr->time_gc);
yajl_gen_map_close(g);
}
/** /**
* Write detailed information about a rule and its actionset into a JSON generator * Write detailed information about a rule and its actionset into a JSON generator
*/ */
@@ -558,6 +578,9 @@ static void write_rule_json(modsec_rec *msr, const msre_rule *rule, yajl_gen g)
yajl_kv_int(g, "phase", rule->actionset->phase); yajl_kv_int(g, "phase", rule->actionset->phase);
} }
yajl_kv_bool(g, "is_chained", rule->actionset->is_chained); yajl_kv_bool(g, "is_chained", rule->actionset->is_chained);
if (rule->actionset->is_chained && (rule->chain_starter == NULL)) {
yajl_kv_bool(g, "chain_starter", 1);
}
yajl_gen_map_close(g); yajl_gen_map_close(g);
yajl_string(g, "operator"); yajl_string(g, "operator");
@@ -602,6 +625,7 @@ void sec_audit_logger(modsec_rec *msr) {
int arg_min, arg_max, sanitize_matched; int arg_min, arg_max, sanitize_matched;
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_gen g; yajl_gen g;
int been_opened = 0; // helper flag for conditionally opening maps
#endif #endif
#ifndef WITH_JSON_LOGGING #ifndef WITH_JSON_LOGGING
@@ -704,7 +728,7 @@ void sec_audit_logger(modsec_rec *msr) {
g = yajl_gen_alloc(NULL); g = yajl_gen_alloc(NULL);
/** /**
* don't pretty print JSON by default * don't pretty print JSON
* this is harder to eyeball but much easier to parse programmatically * this is harder to eyeball but much easier to parse programmatically
*/ */
yajl_gen_config(g, yajl_gen_beautify, 0); yajl_gen_config(g, yajl_gen_beautify, 0);
@@ -771,16 +795,14 @@ void sec_audit_logger(modsec_rec *msr) {
for (i = 0; i < arr->nelts; i++) { for (i = 0; i < arr->nelts; i++) {
sanitized_partial = 0; sanitized_partial = 0;
sanitize_matched = 0; sanitize_matched = 0;
#ifndef WITH_JSON_LOGGING
text = apr_psprintf(msr->mp, "%s: %s\n", te[i].key, te[i].val); text = apr_psprintf(msr->mp, "%s: %s\n", te[i].key, te[i].val);
#else #ifdef WITH_JSON_LOGGING
// write the key no matter what // write the key no matter what
// since sanitization only occurs on the value // since sanitization only occurs on the value
yajl_string(g, te[i].key); yajl_string(g, te[i].key);
#endif #endif
if (apr_table_get(msr->request_headers_to_sanitize, te[i].key) != NULL) { if (apr_table_get(msr->request_headers_to_sanitize, te[i].key) != NULL) {
buf = apr_psprintf(msr->mp, "%s",text+strlen(te[i].key)+2); buf = apr_psprintf(msr->mp, "%s",text+strlen(te[i].key)+2);
for ( k = 0; k < tarr_pattern->nelts; k++) { for ( k = 0; k < tarr_pattern->nelts; k++) {
if(strncmp(telts_pattern[k].key,te[i].key,strlen(te[i].key)) ==0 ) { if(strncmp(telts_pattern[k].key,te[i].key,strlen(te[i].key)) ==0 ) {
mparm = (msc_parm *)telts_pattern[k].val; mparm = (msc_parm *)telts_pattern[k].val;
@@ -818,7 +840,8 @@ void sec_audit_logger(modsec_rec *msr) {
#ifndef WITH_JSON_LOGGING #ifndef WITH_JSON_LOGGING
memset(text + strlen(te[i].key) + 2, '*', strlen(te[i].val)); memset(text + strlen(te[i].key) + 2, '*', strlen(te[i].val));
#else #else
yajl_string(g, "****"); // fix this later memset(buf, '*', strlen(buf)); // strlen also includes the appended newline on the header
yajl_string(g, buf);
#endif #endif
} }
} }
@@ -827,7 +850,9 @@ void sec_audit_logger(modsec_rec *msr) {
#else #else
// we diverge from the original logic a bit because we always print the key // we diverge from the original logic a bit because we always print the key
// at this no point sanitization had occured, so we just print the value // at this no point sanitization had occured, so we just print the value
yajl_string(g, te[i].val); else {
yajl_string(g, te[i].val);
}
#endif #endif
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
@@ -1025,7 +1050,6 @@ void sec_audit_logger(modsec_rec *msr) {
sec_auditlog_write(msr, text, strlen(text)); sec_auditlog_write(msr, text, strlen(text));
sec_auditlog_write(msr, buffer, strlen(buffer)); sec_auditlog_write(msr, buffer, strlen(buffer));
#else #else
// this is a key instead 'request', doesn't need an array or map since it's one value
yajl_kv_string(g, "fake_body", buffer); yajl_kv_string(g, "fake_body", buffer);
#endif #endif
} }
@@ -1055,7 +1079,8 @@ void sec_audit_logger(modsec_rec *msr) {
msr->status_line); msr->status_line);
#else #else
yajl_kv_string(g, "protocol", msr->response_protocol); yajl_kv_string(g, "protocol", msr->response_protocol);
yajl_kv_string(g, "status", msr->status_line); // as an integer, response status is easier to parse than status_line
yajl_kv_int(g, "status", (int)msr->response_status);
#endif #endif
} else { } else {
#ifndef WITH_JSON_LOGGING #ifndef WITH_JSON_LOGGING
@@ -1084,9 +1109,8 @@ void sec_audit_logger(modsec_rec *msr) {
for (i = 0; i < arr->nelts; i++) { for (i = 0; i < arr->nelts; i++) {
sanitized_partial = 0; sanitized_partial = 0;
sanitize_matched = 0; sanitize_matched = 0;
#ifndef WITH_JSON_LOGGING
text = apr_psprintf(msr->mp, "%s: %s\n", te[i].key, te[i].val); text = apr_psprintf(msr->mp, "%s: %s\n", te[i].key, te[i].val);
#else #ifdef WITH_JSON_LOGGING
// write the key no matter what // write the key no matter what
// since sanitization only occurs on the value // since sanitization only occurs on the value
yajl_string(g, te[i].key); yajl_string(g, te[i].key);
@@ -1131,7 +1155,8 @@ void sec_audit_logger(modsec_rec *msr) {
#ifndef WITH_JSON_LOGGING #ifndef WITH_JSON_LOGGING
memset(text + strlen(te[i].key) + 2, '*', strlen(te[i].val)); memset(text + strlen(te[i].key) + 2, '*', strlen(te[i].val));
#else #else
yajl_string(g, "****"); // fix this later memset(buf, '*', strlen(buf));
yajl_string(g, buf);
#endif #endif
} }
} }
@@ -1140,7 +1165,9 @@ void sec_audit_logger(modsec_rec *msr) {
#else #else
// we diverge from the original logic a bit because we always print the key // we diverge from the original logic a bit because we always print the key
// at this point no sanitization had occured, so we just print the value // at this point no sanitization had occured, so we just print the value
yajl_string(g, te[i].val); else {
yajl_string(g, te[i].val);
}
#endif #endif
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
@@ -1169,8 +1196,8 @@ void sec_audit_logger(modsec_rec *msr) {
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_gen_map_close(g); // response top-level key is finished yajl_gen_map_close(g); // response top-level key is finished
yajl_string(g, "data"); yajl_string(g, "audit_data");
yajl_gen_map_open(g); // data top-level key yajl_gen_map_open(g); // audit_data top-level key
#endif #endif
/* AUDITLOG_PART_TRAILER */ /* AUDITLOG_PART_TRAILER */
@@ -1184,8 +1211,12 @@ void sec_audit_logger(modsec_rec *msr) {
/* Messages */ /* Messages */
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_string(g, "messages"); been_opened = 0;
yajl_gen_array_open(g); if (msr->alerts->nelts > 0) {
yajl_string(g, "messages");
yajl_gen_array_open(g);
been_opened = 1;
}
#endif #endif
for(i = 0; i < msr->alerts->nelts; i++) { for(i = 0; i < msr->alerts->nelts; i++) {
#ifndef WITH_JSON_LOGGING #ifndef WITH_JSON_LOGGING
@@ -1196,13 +1227,19 @@ void sec_audit_logger(modsec_rec *msr) {
#endif #endif
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_gen_array_close(g); if (been_opened == 1) {
yajl_gen_array_close(g);
}
#endif #endif
/* Apache error messages */ /* Apache error messages */
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_string(g, "error_messages"); been_opened = 0;
yajl_gen_array_open(g); if (msr->error_messages->nelts > 0) {
yajl_string(g, "error_messages");
yajl_gen_array_open(g);
been_opened = 1;
}
#endif #endif
for(i = 0; i < msr->error_messages->nelts; i++) { for(i = 0; i < msr->error_messages->nelts; i++) {
error_message_t *em = (((error_message_t **)msr->error_messages->elts)[i]); error_message_t *em = (((error_message_t **)msr->error_messages->elts)[i]);
@@ -1215,7 +1252,9 @@ void sec_audit_logger(modsec_rec *msr) {
#endif #endif
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_gen_array_close(g); if (been_opened == 1) {
yajl_gen_array_close(g);
}
#endif #endif
/* Action */ /* Action */
@@ -1228,6 +1267,7 @@ void sec_audit_logger(modsec_rec *msr) {
yajl_gen_map_open(g); yajl_gen_map_open(g);
yajl_kv_bool(g, "intercepted", 1); yajl_kv_bool(g, "intercepted", 1);
yajl_kv_int(g, "phase", msr->intercept_phase); yajl_kv_int(g, "phase", msr->intercept_phase);
yajl_kv_string(g, "message", msr->intercept_message);
yajl_gen_map_close(g); yajl_gen_map_close(g);
#endif #endif
} }
@@ -1242,27 +1282,25 @@ void sec_audit_logger(modsec_rec *msr) {
#endif #endif
} }
#ifndef WITH_JSON_LOGGING
/* Stopwatch; left in for compatibility reasons */ /* Stopwatch; left in for compatibility reasons */
text = apr_psprintf(msr->mp, "Stopwatch: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT " (- - -)\n", text = apr_psprintf(msr->mp, "Stopwatch: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT " (- - -)\n",
msr->request_time, (now - msr->request_time)); msr->request_time, (now - msr->request_time));
#ifndef WITH_JSON_LOGGING
sec_auditlog_write(msr, text, strlen(text)); sec_auditlog_write(msr, text, strlen(text));
#else
yajl_kv_string(g, "stopwatch", text);
#endif #endif
/* Stopwatch2 */ /* Stopwatch2 */
#ifndef WITH_JSON_LOGGING
{ {
char *perf_all = format_all_performance_variables(msr, msr->mp); char *perf_all = format_all_performance_variables(msr, msr->mp);
text = apr_psprintf(msr->mp, "Stopwatch2: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT text = apr_psprintf(msr->mp, "Stopwatch2: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT
"; %s\n", msr->request_time, (now - msr->request_time), perf_all); "; %s\n", msr->request_time, (now - msr->request_time), perf_all);
#ifndef WITH_JSON_LOGGING
sec_auditlog_write(msr, text, strlen(text)); sec_auditlog_write(msr, text, strlen(text));
#else
yajl_kv_string(g, "stopwatch2", text);
#endif
} }
#else
format_performance_variables_json(msr, g);
#endif
/* Our response body does not contain chunks */ /* Our response body does not contain chunks */
/* ENH Only write this when the output was chunked. */ /* ENH Only write this when the output was chunked. */
@@ -1293,8 +1331,7 @@ void sec_audit_logger(modsec_rec *msr) {
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_string(g, "sanitized"); been_opened = 0;
yajl_gen_map_open(g); // open a separate map for sanitized values
#endif #endif
/* Sanitised arguments */ /* Sanitised arguments */
@@ -1310,6 +1347,12 @@ void sec_audit_logger(modsec_rec *msr) {
text = apr_psprintf(msr->mp, "Sanitised-Args: "); text = apr_psprintf(msr->mp, "Sanitised-Args: ");
sec_auditlog_write(msr, text, strlen(text)); sec_auditlog_write(msr, text, strlen(text));
#else #else
if (been_opened == 0) {
yajl_string(g, "sanitized");
yajl_gen_map_open(g);
been_opened = 1;
}
yajl_string(g, "args"); yajl_string(g, "args");
yajl_gen_array_open(g); yajl_gen_array_open(g);
#endif #endif
@@ -1346,6 +1389,12 @@ void sec_audit_logger(modsec_rec *msr) {
text = apr_psprintf(msr->mp, "Sanitised-Request-Headers: "); text = apr_psprintf(msr->mp, "Sanitised-Request-Headers: ");
sec_auditlog_write(msr, text, strlen(text)); sec_auditlog_write(msr, text, strlen(text));
#else #else
if (been_opened == 0) {
yajl_string(g, "sanitized");
yajl_gen_map_open(g);
been_opened = 1;
}
yajl_string(g, "request_headers"); yajl_string(g, "request_headers");
yajl_gen_array_open(g); yajl_gen_array_open(g);
#endif #endif
@@ -1380,6 +1429,12 @@ void sec_audit_logger(modsec_rec *msr) {
text = apr_psprintf(msr->mp, "Sanitised-Response-Headers: "); text = apr_psprintf(msr->mp, "Sanitised-Response-Headers: ");
sec_auditlog_write(msr, text, strlen(text)); sec_auditlog_write(msr, text, strlen(text));
#else #else
if (been_opened == 0) {
yajl_string(g, "sanitized");
yajl_gen_map_open(g);
been_opened = 1;
}
yajl_string(g, "response_headers"); yajl_string(g, "response_headers");
yajl_gen_array_open(g); yajl_gen_array_open(g);
#endif #endif
@@ -1402,7 +1457,9 @@ void sec_audit_logger(modsec_rec *msr) {
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_gen_map_close(g); // sanitized args map is finished if (been_opened == 1) {
yajl_gen_map_close(g); // sanitized args map is finished
}
#endif #endif
/* Web application info. */ /* Web application info. */
@@ -1493,7 +1550,7 @@ void sec_audit_logger(modsec_rec *msr) {
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_gen_map_close(g); // data top-level key is finished yajl_gen_map_close(g); // audit_data top-level key is finished
#endif #endif
/* AUDITLOG_PART_UPLOADS */ /* AUDITLOG_PART_UPLOADS */
@@ -1552,7 +1609,6 @@ void sec_audit_logger(modsec_rec *msr) {
yajl_gen_array_open(g); // matched_rules top-level key yajl_gen_array_open(g); // matched_rules top-level key
#endif #endif
/* Matched Rules */ /* Matched Rules */
for(i = 0; i < msr->matched_rules->nelts; i++) { for(i = 0; i < msr->matched_rules->nelts; i++) {
@@ -1608,7 +1664,7 @@ void sec_audit_logger(modsec_rec *msr) {
} }
} }
#ifdef WITH_JSON_LOGGING #ifdef WITH_JSON_LOGGING
yajl_gen_array_close(g); // matched_rules top-level key is finished yajl_gen_array_close(g); // matched_rules top-level key is finished
#endif #endif
} }