From 7b56982f26731f7bffa40c532c8c2f2e079684b6 Mon Sep 17 00:00:00 2001 From: ivanr Date: Mon, 1 Feb 2010 09:42:23 +0000 Subject: [PATCH] Implemented a new time-measuring mechanism. Added Stopwatch2. --- CHANGES | 10 ++- apache2/apache2_io.c | 2 - apache2/apache2_util.c | 34 ----------- apache2/mod_security2.c | 4 -- apache2/modsecurity.c | 132 ++++++++++++++++++++++++++++++++-------- apache2/modsecurity.h | 12 ++-- apache2/msc_logging.c | 44 +++++--------- apache2/persist_dbm.c | 40 ++++++++---- 8 files changed, 167 insertions(+), 111 deletions(-) diff --git a/CHANGES b/CHANGES index 465e7c63..b541c3eb 100644 --- a/CHANGES +++ b/CHANGES @@ -1,7 +1,15 @@ -27 Jan 2010 - trunk +1 Feb 2010 - trunk ------------------- + * Replaced the previous time-measuring mechanism with a new one, which + provides the following information: request time, request duration, + phase duration (for all 5 phases), time spent dealing with persistent + storage, and time spent on audit logging. The new information is now + available in the Stopwatch2 audit log header. The Stopwatch header + remains for backward compatiblity, although it now only includes + the request time and request duration values. [Ivan Ristic] + * Added DURATION, which contains the time ellapsed since the beginning of the current transaction, in milliseconds. [Ivan Ristic] diff --git a/apache2/apache2_io.c b/apache2/apache2_io.c index 1bed6e56..7c46c8b7 100644 --- a/apache2/apache2_io.c +++ b/apache2/apache2_io.c @@ -782,8 +782,6 @@ apr_status_t output_filter(ap_filter_t *f, apr_bucket_brigade *bb_in) { * (full-buffering only). */ if ((msr->of_skipping == 0)&&(!msr->of_partial)) { - record_time_checkpoint(msr, 3); - prepend_content_to_of_brigade(msr, f); /* Inject content into response (append & buffering). */ diff --git a/apache2/apache2_util.c b/apache2/apache2_util.c index 011f49a9..8d24f115 100644 --- a/apache2/apache2_util.c +++ b/apache2/apache2_util.c @@ -163,40 +163,6 @@ int apache2_exec(modsec_rec *msr, const char *command, const char **argv, char * return 1; } -/** - * Record the current time and store for later. - */ -void record_time_checkpoint(modsec_rec *msr, int checkpoint_no) { - char note[100], note_name[100]; - apr_time_t now; - - now = apr_time_now(); - switch(checkpoint_no) { - case 1 : - msr->time_checkpoint_1 = now; - break; - case 2 : - msr->time_checkpoint_2 = now; - break; - case 3 : - msr->time_checkpoint_3 = now; - break; - default : - msr_log(msr, 1, "Internal Error: Unknown checkpoint: %d", checkpoint_no); - return; - break; - } - - /* Apache-specific stuff. */ - apr_snprintf(note, 99, "%" APR_TIME_T_FMT, (now - msr->request_time)); - apr_snprintf(note_name, 99, "mod_security-time%d", checkpoint_no); - apr_table_set(msr->r->notes, note_name, note); - - if (msr->txcfg->debuglog_level >= 4) { - msr_log(msr, 4, "Time #%d: %s", checkpoint_no, note); - } -} - /** * Returns a new string that contains the error * message for the given return code. diff --git a/apache2/mod_security2.c b/apache2/mod_security2.c index 178bdc0d..43531f63 100644 --- a/apache2/mod_security2.c +++ b/apache2/mod_security2.c @@ -734,15 +734,11 @@ static int hook_request_late(request_rec *r) { msr->request_headers = apr_table_copy(msr->mp, r->headers_in); /* Process phase REQUEST_BODY */ - record_time_checkpoint(msr, 1); - rc = DECLINED; if (modsecurity_process_phase(msr, PHASE_REQUEST_BODY) > 0) { rc = perform_interception(msr); } - record_time_checkpoint(msr, 2); - return rc; } diff --git a/apache2/modsecurity.c b/apache2/modsecurity.c index 37035ca4..0d03e738 100644 --- a/apache2/modsecurity.c +++ b/apache2/modsecurity.c @@ -80,6 +80,7 @@ static const char *phase_name(int phase) { return "LOGGING"; break; } + return "INVALID"; } #endif @@ -166,12 +167,15 @@ static apr_status_t modsecurity_tx_cleanup(void *data) { int collect_garbage = 0; int i; char *my_error_msg = NULL; + apr_time_t time_before; if (msr == NULL) return APR_SUCCESS; if (rand() < RAND_MAX/100) { collect_garbage = 1; } + + time_before = apr_time_now(); /* Collections, store & remove stale. */ arr = apr_table_elts(msr->collections); @@ -188,6 +192,8 @@ static apr_status_t modsecurity_tx_cleanup(void *data) { collections_remove_stale(msr, te[i].key); } } + + msr->time_persistence += apr_time_now() - time_before; /* Multipart processor cleanup. */ if (msr->mpd != NULL) multipart_cleanup(msr); @@ -382,6 +388,7 @@ static int is_response_status_relevant(modsec_rec *msr, int status) { if (rc == PCRE_ERROR_NOMATCH) return 0; msr_log(msr, 1, "Regex processing failed (rc %d): %s", rc, my_error_msg); + return 0; } @@ -389,78 +396,132 @@ static int is_response_status_relevant(modsec_rec *msr, int status) { * */ static apr_status_t modsecurity_process_phase_request_headers(modsec_rec *msr) { - msr_log(msr, 4, "Starting phase REQUEST_HEADERS."); + apr_time_t time_before; + apr_status_t rc = 0; + + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Starting phase REQUEST_HEADERS."); + } + + time_before = apr_time_now(); if (msr->txcfg->ruleset != NULL) { - return msre_ruleset_process_phase(msr->txcfg->ruleset, msr); + rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr); } + + msr->time_phase1 = apr_time_now() - time_before; - return 0; + return rc; } /** * */ static apr_status_t modsecurity_process_phase_request_body(modsec_rec *msr) { + apr_time_t time_before; + apr_status_t rc = 0; + if ((msr->allow_scope == ACTION_ALLOW_REQUEST)||(msr->allow_scope == ACTION_ALLOW)) { - msr_log(msr, 4, "Skipping phase REQUEST_BODY (allow used)."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Skipping phase REQUEST_BODY (allow used)."); + } + return 0; } else { - msr_log(msr, 4, "Starting phase REQUEST_BODY."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Starting phase REQUEST_BODY."); + } } + + time_before = apr_time_now(); if (msr->txcfg->ruleset != NULL) { - return msre_ruleset_process_phase(msr->txcfg->ruleset, msr); + rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr); } + + msr->time_phase2 = apr_time_now() - time_before; - return 0; + return rc; } /** * */ static apr_status_t modsecurity_process_phase_response_headers(modsec_rec *msr) { + apr_time_t time_before; + apr_status_t rc = 0; + if (msr->allow_scope == ACTION_ALLOW) { - msr_log(msr, 4, "Skipping phase RESPONSE_HEADERS (allow used)."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Skipping phase RESPONSE_HEADERS (allow used)."); + } + return 0; } else { - msr_log(msr, 4, "Starting phase RESPONSE_HEADERS."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Starting phase RESPONSE_HEADERS."); + } } + + time_before = apr_time_now(); if (msr->txcfg->ruleset != NULL) { - return msre_ruleset_process_phase(msr->txcfg->ruleset, msr); + rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr); } + + msr->time_phase3 = apr_time_now() - time_before; - return 0; + return rc; } /** * */ static apr_status_t modsecurity_process_phase_response_body(modsec_rec *msr) { + apr_time_t time_before; + apr_status_t rc = 0; + if (msr->allow_scope == ACTION_ALLOW) { - msr_log(msr, 4, "Skipping phase RESPONSE_BODY (allow used)."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Skipping phase RESPONSE_BODY (allow used)."); + } + return 0; } else { - msr_log(msr, 4, "Starting phase RESPONSE_BODY."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Starting phase RESPONSE_BODY."); + } } + + time_before = apr_time_now(); if (msr->txcfg->ruleset != NULL) { - return msre_ruleset_process_phase(msr->txcfg->ruleset, msr); + rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr); } + + msr->time_phase4 = apr_time_now() - time_before; - return 0; + return rc; } /** * */ static apr_status_t modsecurity_process_phase_logging(modsec_rec *msr) { - msr_log(msr, 4, "Starting phase LOGGING."); + apr_time_t time_before, time_after; + + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Starting phase LOGGING."); + } + + time_before = apr_time_now(); if (msr->txcfg->ruleset != NULL) { msre_ruleset_process_phase(msr->txcfg->ruleset, msr); } + + time_after = apr_time_now(); + msr->time_phase5 = time_after - time_before; /* Is this request relevant for logging purposes? */ if (msr->is_relevant == 0) { @@ -487,13 +548,19 @@ static apr_status_t modsecurity_process_phase_logging(modsec_rec *msr) { /* Are we configured for audit logging? */ switch(msr->txcfg->auditlog_flag) { case AUDITLOG_OFF : - msr_log(msr, 4, "Audit log: Not configured to run for this request."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Audit log: Not configured to run for this request."); + } + return DECLINED; break; case AUDITLOG_RELEVANT : if (msr->is_relevant == 0) { - msr_log(msr, 4, "Audit log: Ignoring a non-relevant request."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Audit log: Ignoring a non-relevant request."); + } + return DECLINED; } break; @@ -508,9 +575,13 @@ static apr_status_t modsecurity_process_phase_logging(modsec_rec *msr) { } /* Invoke the Audit logger */ - msr_log(msr, 4, "Audit log: Logging this transaction."); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Audit log: Logging this transaction."); + } sec_audit_logger(msr); + + msr->time_logging = apr_time_now() - time_after; return 0; } @@ -523,14 +594,20 @@ static apr_status_t modsecurity_process_phase_logging(modsec_rec *msr) { apr_status_t modsecurity_process_phase(modsec_rec *msr, unsigned int phase) { /* Check if we should run. */ if ((msr->was_intercepted)&&(phase != PHASE_LOGGING)) { - msr_log(msr, 4, "Skipping phase %d as request was already intercepted.", phase); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Skipping phase %d as request was already intercepted.", phase); + } + return 0; } /* Do not process the same phase twice. */ if (msr->phase >= phase) { - msr_log(msr, 4, "Skipping phase %d because it was previously run (at %d now).", - phase, msr->phase); + if (msr->txcfg->debuglog_level >= 4) { + msr_log(msr, 4, "Skipping phase %d because it was previously run (at %d now).", + phase, msr->phase); + } + return 0; } @@ -570,12 +647,15 @@ apr_status_t modsecurity_process_phase(modsec_rec *msr, unsigned int phase) { rec = (msre_cache_rec *)ctelts[ri].val; if (rec->changed) { if (msr->txcfg->debuglog_level >= 9) { - msr_log(msr, 9, "CACHE: %5d) hits=%d key=%pp %x;%s=\"%s\" (%pp - %pp)", cn, rec->hits, key, rec->num, rec->path, log_escape_nq_ex(mp, rec->val, rec->val_len), rec->val, rec->val + rec->val_len); + msr_log(msr, 9, "CACHE: %5d) hits=%d key=%pp %x;%s=\"%s\" (%pp - %pp)", + cn, rec->hits, key, rec->num, rec->path, log_escape_nq_ex(mp, rec->val, rec->val_len), + rec->val, rec->val + rec->val_len); } } else { if (msr->txcfg->debuglog_level >= 9) { - msr_log(msr, 9, "CACHE: %5d) hits=%d key=%pp %x;%s=", cn, rec->hits, key, rec->num, rec->path); + msr_log(msr, 9, "CACHE: %5d) hits=%d key=%pp %x;%s=", + cn, rec->hits, key, rec->num, rec->path); } } } @@ -585,7 +665,9 @@ apr_status_t modsecurity_process_phase(modsec_rec *msr, unsigned int phase) { apr_hash_set(msr->tcache, key, klen, NULL); } - msr_log(msr, 9, "Cleared transformation cache for phase %d", msr->phase); + if (msr->txcfg->debuglog_level >= 9) { + msr_log(msr, 9, "Cleared transformation cache for phase %d", msr->phase); + } } msr->tcache_items = 0; diff --git a/apache2/modsecurity.h b/apache2/modsecurity.h index 42d15768..9c6025ff 100644 --- a/apache2/modsecurity.h +++ b/apache2/modsecurity.h @@ -318,10 +318,14 @@ struct modsec_rec { /* performance measurement */ apr_time_t request_time; - apr_time_t time_checkpoint_1; - apr_time_t time_checkpoint_2; - apr_time_t time_checkpoint_3; - + apr_time_t time_phase1; + apr_time_t time_phase2; + apr_time_t time_phase3; + apr_time_t time_phase4; + apr_time_t time_phase5; + apr_time_t time_persistence; + apr_time_t time_logging; + apr_array_header_t *matched_rules; msc_string *matched_var; int highest_severity; diff --git a/apache2/msc_logging.c b/apache2/msc_logging.c index 85e94bbf..fa45218d 100644 --- a/apache2/msc_logging.c +++ b/apache2/msc_logging.c @@ -764,35 +764,21 @@ void sec_audit_logger(modsec_rec *msr) { text = apr_psprintf(msr->mp, "Apache-Handler: %s\n", msr->r->handler); sec_auditlog_write(msr, text, strlen(text)); } - - /* Processing times */ - if (msr->time_checkpoint_1 == 0) { - text = apr_psprintf(msr->mp, "Stopwatch: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT - " (- - -)\n", (msr->request_time), (now - msr->request_time)); - } else { - char sw_str2[101] = "-"; - char sw_str3[101] = "-"; - - if (msr->time_checkpoint_2 != 0) { - apr_snprintf(sw_str2, sizeof(sw_str2), "%" APR_TIME_T_FMT, - (msr->time_checkpoint_2 - msr->request_time)); - } - - if (msr->time_checkpoint_3 != 0) { - apr_snprintf(sw_str3, sizeof(sw_str3), "%" APR_TIME_T_FMT, - (msr->time_checkpoint_3 - msr->request_time)); - } - - text = apr_psprintf(msr->mp, "Stopwatch: %" APR_TIME_T_FMT - " %" APR_TIME_T_FMT " (%" APR_TIME_T_FMT - "%s %s %s)\n", - (msr->request_time), (now - msr->request_time), - (msr->time_checkpoint_1 - msr->request_time), - ((msr->msc_reqbody_read == 0) ? "" : "*"), - sw_str2, sw_str3 - ); - } - + + /* Stopwatch; left in for compatibility reasons */ + text = apr_psprintf(msr->mp, "Stopwatch: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT " (- - -)\n", + msr->request_time, (now - msr->request_time)); + sec_auditlog_write(msr, text, strlen(text)); + + /* Stopwatch2 */ + + text = apr_psprintf(msr->mp, "Stopwatch2: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT + "; p1=%" APR_TIME_T_FMT ", p2=%" APR_TIME_T_FMT ", p3=%" APR_TIME_T_FMT + ", p4=%" APR_TIME_T_FMT ", p5=%" APR_TIME_T_FMT ", s=%" APR_TIME_T_FMT + ", l=%" APR_TIME_T_FMT "\n", msr->request_time, (now - msr->request_time), + msr->time_phase1, msr->time_phase2, msr->time_phase3, msr->time_phase4, + msr->time_phase5, msr->time_persistence, msr->time_logging); + sec_auditlog_write(msr, text, strlen(text)); /* Our response body does not contain chunks */ diff --git a/apache2/persist_dbm.c b/apache2/persist_dbm.c index f7946746..89bf3584 100644 --- a/apache2/persist_dbm.c +++ b/apache2/persist_dbm.c @@ -174,15 +174,19 @@ static apr_table_t *collection_retrieve_ex(apr_sdbm_t *existing_dbm, modsec_rec if (strcmp(key_to_expire, "__expire_KEY") == 0) { expired = 1; } + if (msr->txcfg->debuglog_level >= 9) { msr_log(msr, 9, "Removing key \"%s\" from collection.", key_to_expire + 9); msr_log(msr, 9, "Removing key \"%s\" from collection.", key_to_expire); } + apr_table_unset(col, key_to_expire + 9); apr_table_unset(col, key_to_expire); + if (msr->txcfg->debuglog_level >= 4) { msr_log(msr, 4, "Removed expired variable \"%s\".", key_to_expire + 9); } + break; } } @@ -225,7 +229,8 @@ static apr_table_t *collection_retrieve_ex(apr_sdbm_t *existing_dbm, modsec_rec } if (expired && (msr->txcfg->debuglog_level >= 9)) { - msr_log(msr, 9, "Collection expired (name \"%s\", key \"%s\").", col_name, log_escape_ex(msr->mp, col_key, col_key_len)); + msr_log(msr, 9, "Collection expired (name \"%s\", key \"%s\").", col_name, + log_escape_ex(msr->mp, col_key, col_key_len)); } if (msr->txcfg->debuglog_level >= 4) { msr_log(msr, 4, "Deleted collection (name \"%s\", key \"%s\").", @@ -273,13 +278,13 @@ static apr_table_t *collection_retrieve_ex(apr_sdbm_t *existing_dbm, modsec_rec if (msr->txcfg->debuglog_level >= 4) { msr_log(msr, 4, "Retrieved collection (name \"%s\", key \"%s\").", - log_escape(msr->mp, col_name), log_escape_ex(msr->mp, col_key, col_key_len)); + log_escape(msr->mp, col_name), log_escape_ex(msr->mp, col_key, col_key_len)); } if ((existing_dbm == NULL) && dbm) { /* Should not ever get here */ msr_log(msr, 1, "Internal Error: Collection remained open (name \"%s\", key \"%s\").", - log_escape(msr->mp, col_name), log_escape_ex(msr->mp, col_key, col_key_len)); + log_escape(msr->mp, col_name), log_escape_ex(msr->mp, col_key, col_key_len)); apr_sdbm_close(dbm); } @@ -299,11 +304,18 @@ cleanup: * */ apr_table_t *collection_retrieve(modsec_rec *msr, const char *col_name, - const char *col_key, int col_key_len) { - return collection_retrieve_ex(NULL, msr, col_name, col_key, col_key_len); + const char *col_key, int col_key_len) +{ + apr_time_t time_before = apr_time_now(); + apr_table_t *rtable = NULL; + + rtable = collection_retrieve_ex(NULL, msr, col_name, col_key, col_key_len); + + msr->time_persistence += apr_time_now() - time_before; + + return rtable; } - /** * */ @@ -334,8 +346,8 @@ int collection_store(modsec_rec *msr, apr_table_t *col) { if (msr->txcfg->data_dir == NULL) { msr_log(msr, 1, "Unable to store collection (name \"%s\", key \"%s\"). Use " - "SecDataDir to define data directory first.", - log_escape_ex(msr->mp, var_name->value, var_name->value_len), log_escape_ex(msr->mp, var_key->value, var_key->value_len)); + "SecDataDir to define data directory first.", log_escape_ex(msr->mp, var_name->value, var_name->value_len), + log_escape_ex(msr->mp, var_key->value, var_key->value_len)); goto error; } @@ -417,7 +429,8 @@ int collection_store(modsec_rec *msr, apr_table_t *col) { orig_col = (const apr_table_t *)apr_table_get(msr->collections_original, var_name->value); if (orig_col != NULL) { if (msr->txcfg->debuglog_level >= 9) { - msr_log(msr, 9, "Re-retrieving collection prior to store: %s", apr_psprintf(msr->mp, "%.*s", var_name->value_len, var_name->value)); + msr_log(msr, 9, "Re-retrieving collection prior to store: %s", + apr_psprintf(msr->mp, "%.*s", var_name->value_len, var_name->value)); } stored_col = (const apr_table_t *)collection_retrieve_ex(dbm, msr, var_name->value, var_key->value, var_key->value_len); @@ -448,6 +461,7 @@ int collection_store(modsec_rec *msr, apr_table_t *col) { var->value = apr_psprintf(msr->mp, "%d", newval); var->value_len = strlen(var->value); + if (msr->txcfg->debuglog_level >= 9) { msr_log(msr, 9, "Delta applied for %s.%s %d->%d (%d): %d + (%d) = %d [%s,%d]", log_escape_ex(msr->mp, var_name->value, var_name->value_len), @@ -530,7 +544,8 @@ int collection_store(modsec_rec *msr, apr_table_t *col) { if (msr->txcfg->debuglog_level >= 4) { msr_log(msr, 4, "Persisted collection (name \"%s\", key \"%s\").", - log_escape_ex(msr->mp, var_name->value, var_name->value_len), log_escape_ex(msr->mp, var_key->value, var_key->value_len)); + log_escape_ex(msr->mp, var_name->value, var_name->value_len), + log_escape_ex(msr->mp, var_key->value, var_key->value_len)); } return 0; @@ -645,10 +660,11 @@ int collections_remove_stale(modsec_rec *msr, const char *col_name) { log_escape_ex(msr->mp, key.dptr, key.dsize - 1), get_apr_error(msr->mp, rc)); goto error; } + if (msr->txcfg->debuglog_level >= 4) { msr_log(msr, 4, "Removed stale collection (name \"%s\", " - "key \"%s\").", log_escape(msr->mp, col_name), - log_escape_ex(msr->mp, key.dptr, key.dsize - 1)); + "key \"%s\").", log_escape(msr->mp, col_name), + log_escape_ex(msr->mp, key.dptr, key.dsize - 1)); } } }