Implemented a new time-measuring mechanism. Added Stopwatch2.

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]
 

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). */

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.

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

apache2/modsecurity.c

@@ -80,6 +80,7 @@ static const char *phase_name(int phase) {
             return "LOGGING";
             break;
     }
+    
     return "INVALID";
 }
 #endif
@@ -166,6 +167,7 @@ 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;
 
@@ -173,6 +175,8 @@ static apr_status_t modsecurity_tx_cleanup(void *data) {
         collect_garbage = 1;
     }
     
+    time_before = apr_time_now();
+
     /* Collections, store & remove stale. */
     arr = apr_table_elts(msr->collections);
     te = (apr_table_entry_t *)arr->elts;
@@ -189,6 +193,8 @@ static apr_status_t modsecurity_tx_cleanup(void *data) {
         }
     }
     
+    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,79 +396,133 @@ 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->ruleset != NULL) {
+    if (msr->txcfg->debuglog_level >= 4) {
-        return msre_ruleset_process_phase(msr->txcfg->ruleset, msr);
+        msr_log(msr, 4, "Starting phase REQUEST_HEADERS.");
     }
     
-    return 0;
+    time_before = apr_time_now();
+
+    if (msr->txcfg->ruleset != NULL) {
+        rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr);
+    }
+    
+    msr->time_phase1 = apr_time_now() - time_before;
+
+    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);
     }
     
-    return 0;
+    msr->time_phase2 = apr_time_now() - time_before;
+
+    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);
     }
     
-    return 0;
+    msr->time_phase3 = apr_time_now() - time_before;
+
+    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);
     }
     
-    return 0;
+    msr->time_phase4 = apr_time_now() - time_before;
+
+    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) {
         /* Check the status */
@@ -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,10 +575,14 @@ 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).",
+        if (msr->txcfg->debuglog_level >= 4) {
-            phase, msr->phase);
+            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=<no change>", cn, rec->hits, key, rec->num, rec->path);
+                            msr_log(msr, 9, "CACHE: %5d) hits=%d key=%pp %x;%s=<no change>",
+                                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;

apache2/modsecurity.h

@@ -318,9 +318,13 @@ struct modsec_rec {
 
     /* performance measurement */
     apr_time_t           request_time;
-    apr_time_t           time_checkpoint_1;
+    apr_time_t		 time_phase1;
-    apr_time_t           time_checkpoint_2;
+    apr_time_t		 time_phase2;
-    apr_time_t           time_checkpoint_3;
+    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;

apache2/msc_logging.c

@@ -765,33 +765,19 @@ void sec_audit_logger(modsec_rec *msr) {
             sec_auditlog_write(msr, text, strlen(text));
         }
         
-        /* Processing times */
+        /* Stopwatch; left in for compatibility reasons */
-        if (msr->time_checkpoint_1 == 0) {
+        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
+            msr->request_time, (now - msr->request_time));
-                " (- - -)\n", (msr->request_time), (now - msr->request_time));
+        sec_auditlog_write(msr, text, strlen(text));        
-        } else {
-            char sw_str2[101] = "-";
-            char sw_str3[101] = "-";
         
-            if (msr->time_checkpoint_2 != 0) {
+        /* Stopwatch2 */
-                apr_snprintf(sw_str2, sizeof(sw_str2), "%" APR_TIME_T_FMT,
-                    (msr->time_checkpoint_2 - msr->request_time));
-            }
         
-            if (msr->time_checkpoint_3 != 0) {
+        text = apr_psprintf(msr->mp, "Stopwatch2: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT
-                apr_snprintf(sw_str3, sizeof(sw_str3), "%" APR_TIME_T_FMT,
+          "; p1=%" APR_TIME_T_FMT ", p2=%" APR_TIME_T_FMT ", p3=%" APR_TIME_T_FMT
-                    (msr->time_checkpoint_3 - msr->request_time));
+          ", 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,
-            text = apr_psprintf(msr->mp, "Stopwatch: %" APR_TIME_T_FMT
+          msr->time_phase5, msr->time_persistence, msr->time_logging);
-                " %" 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
-                );
-        }
           
         sec_auditlog_write(msr, text, strlen(text));
 

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,10 +304,17 @@ cleanup:
  *
  */
 apr_table_t *collection_retrieve(modsec_rec *msr, const char *col_name,
-    const char *col_key, int col_key_len) {
+    const char *col_key, int col_key_len)
-    return collection_retrieve_ex(NULL, msr, col_name, col_key, 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.",
+            "SecDataDir to define data directory first.", log_escape_ex(msr->mp, var_name->value, var_name->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));
+            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),
+                            "key \"%s\").", log_escape(msr->mp, col_name),
-                                log_escape_ex(msr->mp, key.dptr, key.dsize - 1));
+                            log_escape_ex(msr->mp, key.dptr, key.dsize - 1));
                     }
                 }
             }