in apache2/re.c [2770:3308]
static apr_status_t msre_rule_process_normal(msre_rule *rule, modsec_rec *msr) {
const apr_array_header_t *arr = NULL;
const apr_table_entry_t *te = NULL;
msre_actionset *acting_actionset = NULL;
msre_var **targets = NULL;
apr_pool_t *mptmp = msr->msc_rule_mptmp;
apr_table_t *tartab = NULL;
apr_table_t *vartab = NULL;
int i, rc = 0, match_count = 0;
int invocations = 0;
int multi_match = 0;
/* Choose the correct metadata/disruptive action actionset. */
acting_actionset = rule->actionset;
if (rule->chain_starter != NULL) {
acting_actionset = rule->chain_starter->actionset;
}
/* Configure recursive matching. */
if (apr_table_get(rule->actionset->actions, "multiMatch") != NULL) {
multi_match = 1;
}
/* ENH: What is a good initial size? */
tartab = apr_table_make(mptmp, 24);
if (tartab == NULL) return -1;
vartab = apr_table_make(mptmp, 24);
if (vartab == NULL) return -1;
/* Expand variables to create a list of targets. */
targets = (msre_var **)rule->targets->elts;
for (i = 0; i < rule->targets->nelts; i++) {
int j, list_count;
apr_table_clear(vartab);
/* ENH Introduce a new variable hook that would allow the code
* behind the variable to return the size of the collection
* without having to generate the variables.
*/
/* Expand individual variables first. */
list_count = targets[i]->metadata->generate(msr, targets[i], rule, vartab, mptmp);
if (targets[i]->is_counting) {
/* Count how many there are and just add the score to the target list. */
msre_var *newvar = (msre_var *)apr_pmemdup(mptmp, targets[i], sizeof(msre_var));
newvar->value = apr_psprintf(mptmp, "%d", list_count);
newvar->value_len = strlen(newvar->value);
apr_table_addn(tartab, newvar->name, (void *)newvar);
} else {
/* And either add them or remove from the final target list. */
arr = apr_table_elts(vartab);
te = (apr_table_entry_t *)arr->elts;
for(j = 0; j < arr->nelts; j++) {
if (targets[i]->is_negated == 0) {
apr_table_addn(tartab, te[j].key, te[j].val);
} else {
apr_table_unset(tartab, te[j].key);
}
}
}
}
/* Log the target variable expansion */
if (msr->txcfg->debuglog_level >= 4) {
const char *expnames = NULL;
arr = apr_table_elts(tartab);
if (arr->nelts > 1) {
te = (apr_table_entry_t *)arr->elts;
expnames = apr_pstrdup(mptmp, ((msre_var *)te[0].val)->name);
for(i = 1; i < arr->nelts; i++) {
expnames = apr_psprintf(mptmp, "%s|%s", expnames, ((msre_var *)te[i].val)->name);
}
if (strcmp(rule->p1, expnames) != 0) {
msr_log(msr, 4, "Expanded \"%s\" to \"%s\".", rule->p1, expnames);
}
}
}
/* Loop through targets on the final target list,
* perform transformations as necessary, and invoke
* the operator.
*/
arr = apr_table_elts(tartab);
te = (apr_table_entry_t *)arr->elts;
for (i = 0; i < arr->nelts; i++) {
/* Variable was modified by *any* transformation */
int changed;
/* Variable was modified by *last applied* transformation (needed by multimatch) */
int tfnchanged;
int usecache = 0;
apr_table_t *cachetab = NULL;
apr_time_t time_before_trans = 0;
msre_var *var;
/* Take one target. */
var = (msre_var *)te[i].val;
/* Is this var cacheable? */
if (msr->txcfg->cache_trans != MODSEC_CACHE_DISABLED) {
usecache = 1;
/* Counting vars are not cacheable due to them being created
* in a local per-rule pool.
*/
if (var->is_counting) {
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "CACHE: Disabled - &%s is dynamic", var->name);
}
usecache = 0;
}
/* Only cache if if the variable is available in this phase */
else if (msr->phase < var->metadata->availability) {
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "CACHE: Disabled - %s is not yet available in phase %d (requires phase %d or later)", var->name, msr->phase, var->metadata->availability);
}
usecache = 0;
}
/* check the cache options */
else if (var->value_len < msr->txcfg->cache_trans_min) {
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "CACHE: Disabled - %s value length=%u, smaller than minlen=%" APR_SIZE_T_FMT, var->name, var->value_len, msr->txcfg->cache_trans_min);
}
usecache = 0;
}
else if ((msr->txcfg->cache_trans_max != 0) && (var->value_len > msr->txcfg->cache_trans_max)) {
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "CACHE: Disabled - %s value length=%u, larger than maxlen=%" APR_SIZE_T_FMT, var->name, var->value_len, msr->txcfg->cache_trans_max);
}
usecache = 0;
}
/* if cache is still enabled, check the VAR for cacheablity */
if (usecache) {
if (var->metadata->is_cacheable == VAR_CACHE) {
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "CACHE: Enabled");
}
#ifdef CACHE_DEBUG
msr_log(msr, 9, "CACHE: Fetching cache entry from hash=%pp: %pp=%s", msr->tcache, var, var->name);
#endif
/* Fetch cache table for this target */
cachetab = (apr_table_t *)apr_hash_get(msr->tcache, var->value, sizeof(var->value));
/* Create an empty cache table if this is the first time */
#ifdef CACHE_DEBUG
if (cachetab) {
msr_log(msr, 9, "CACHE: Using cache table %pp", cachetab);
}
else
#else
if (cachetab == NULL)
#endif
{
/* NOTE: We use the pointer to the var value as a hash
* key as it is unique. This pointer *must*
* remain valid through the entire phase. If
* it does not, then we will not receive a cache
* hit and just wasted RAM. So, it is important
* that any such vars be marked as VAR_DONT_CACHE.
*
* ENH: Only use pointer for non-scalar vars
*/
cachetab = apr_table_make(msr->mp, 3);
apr_hash_set(msr->tcache, var->value, sizeof(var->value), cachetab);
#ifdef CACHE_DEBUG
msr_log(msr, 9, "CACHE: Created a new cache table %pp for %pp", cachetab, var->value);
#endif
}
}
else {
usecache = 0;
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "CACHE: %s transformations are not cacheable", var->name);
}
}
}
}
#if defined(PERFORMANCE_MEASUREMENT)
time_before_trans = apr_time_now();
#else
if (msr->txcfg->debuglog_level >= 4) {
time_before_trans = apr_time_now();
}
#endif
/* Transform target. */
{
const apr_array_header_t *tarr;
const apr_table_entry_t *telts;
const char *tfnspath = NULL;
char *tfnskey = NULL;
int tfnscount = 0;
int last_cached_tfn = 0;
msre_cache_rec *crec = NULL;
msre_cache_rec *last_crec = NULL;
int k;
msre_action *action;
msre_tfn_metadata *metadata;
apr_table_t *normtab;
const char *lastvarval = NULL;
apr_size_t lastvarlen = 0;
tfnchanged = 0;
changed = 0;
normtab = apr_table_make(mptmp, 10);
if (normtab == NULL) return -1;
tarr = apr_table_elts(rule->actionset->actions);
telts = (const apr_table_entry_t*)tarr->elts;
/* Build the final list of transformation functions. */
for (k = 0; k < tarr->nelts; k++) {
action = (msre_action *)telts[k].val;
if (strcmp(telts[k].key, "t") == 0) {
if (strcmp(action->param, "none") == 0) {
apr_table_clear(normtab);
tfnspath = NULL;
tfnskey = NULL;
tfnscount = 0;
last_crec = NULL;
last_cached_tfn = 0;
continue;
}
if (action->param_plusminus == NEGATIVE_VALUE) {
apr_table_unset(normtab, action->param);
}
else {
tfnscount++;
apr_table_addn(normtab, action->param, (void *)action);
/* Check the cache, saving the 'most complete' as a
* starting point
*/
if (usecache) {
tfnspath = apr_psprintf(mptmp, "%s%s%s", (tfnspath?tfnspath:""), (tfnspath?",":""), action->param);
tfnskey = apr_psprintf(mptmp, "%x;%s", tfnscount, tfnspath);
crec = (msre_cache_rec *)apr_table_get(cachetab, tfnskey);
#ifdef CACHE_DEBUG
msr_log(msr, 9, "CACHE: %s %s cached=%d", var->name, tfnskey, (crec ? 1 : 0));
#endif
if (crec != NULL) {
last_crec = crec;
last_cached_tfn = tfnscount;
}
}
}
}
}
/* If the last cached tfn is the last in the list
* then we can stop here and just execute the action immediatly
*/
if (usecache && !multi_match &&
(crec != NULL) && (crec == last_crec))
{
crec->hits++;
if (crec->changed) {
var->value = apr_pmemdup(mptmp, crec->val, crec->val_len);
var->value_len = crec->val_len;
}
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "T (%d) %s: \"%s\" [fully cached hits=%d]", crec->changed, crec->path,
log_escape_nq_ex(mptmp, var->value, var->value_len), crec->hits);
}
#if defined(PERFORMANCE_MEASUREMENT)
{
apr_time_t t1 = apr_time_now();
rule->trans_time += (t1 - time_before_trans);
}
#else
if (msr->txcfg->debuglog_level >= 4) {
apr_time_t t1 = apr_time_now();
msr_log(msr, 4, "Transformation completed in %" APR_TIME_T_FMT " usec.",
(t1 - time_before_trans));
}
#endif
rc = execute_operator(var, rule, msr, acting_actionset, mptmp);
if (rc < 0) {
return -1;
}
if (rc == RULE_MATCH) {
match_count++;
/* Return straight away if the transaction
* was intercepted - no need to process the remaining
* targets.
*/
if (msr->rule_was_intercepted) {
return RULE_MATCH;
}
}
continue; /* next target */
}
/* Perform transformations. */
tarr = apr_table_elts(normtab);
/* Execute transformations in a loop. */
/* Start after the last known cached transformation if we can */
if (!multi_match && (last_crec != NULL)) {
k = last_cached_tfn;
tfnspath = last_crec->path;
last_crec->hits++;
if ((changed = last_crec->changed) > 0) {
var->value = last_crec->val;
var->value_len = last_crec->val_len;
}
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "T (%d) %s: \"%s\" [partially cached hits=%d]", last_crec->changed,
tfnspath, log_escape_nq_ex(mptmp, var->value, var->value_len), last_crec->hits);
}
}
else {
tfnspath = NULL;
k = 0;
}
/* Make a copy of the value so that we can change it in-place. */
if (tarr->nelts) {
var->value = apr_pstrmemdup(mptmp, var->value, var->value_len);
/* var->value_len remains the same */
}
telts = (const apr_table_entry_t*)tarr->elts;
for (; k < tarr->nelts; k++) {
char *rval = NULL;
long int rval_length = -1;
/* In multi-match mode we execute the operator
* once at the beginning and then once every
* time the variable is changed by the transformation
* function.
*/
if (multi_match && (k == 0 || tfnchanged)) {
invocations++;
#if defined(PERFORMANCE_MEASUREMENT)
{
apr_time_t t1 = apr_time_now();
rule->trans_time += (t1 - time_before_trans);
}
#else
if (msr->txcfg->debuglog_level >= 4) {
apr_time_t t1 = apr_time_now();
msr_log(msr, 4, "Transformation completed in %" APR_TIME_T_FMT " usec.",
(t1 - time_before_trans));
}
#endif
rc = execute_operator(var, rule, msr, acting_actionset, mptmp);
if (rc < 0) {
return -1;
}
if (rc == RULE_MATCH) {
match_count++;
/* Return straight away if the transaction
* was intercepted - no need to process the remaining
* targets.
*/
if (msr->rule_was_intercepted) {
return RULE_MATCH;
}
}
}
/* Perform one transformation. */
action = (msre_action *)telts[k].val;
metadata = (msre_tfn_metadata *)action->param_data;
tfnchanged = metadata->execute(mptmp,
(unsigned char *)var->value, var->value_len,
&rval, &rval_length);
if (tfnchanged < 0) {
return -1;
}
if (tfnchanged) {
changed++;
}
/* Use the new values */
var->value = rval;
var->value_len = rval_length;
/* Cache the transformation */
if (usecache) {
int tfnsnum = k + 1;
/* Generate the cache key */
tfnspath = apr_psprintf(msr->mp, "%s%s%s", (tfnspath ? tfnspath : ""),
(tfnspath ? "," : ""), action->param);
tfnskey = apr_psprintf(msr->mp, "%x;%s", tfnsnum, tfnspath);
if ((msr->txcfg->cache_trans_maxitems != 0) &&
(msr->tcache_items >= msr->txcfg->cache_trans_maxitems))
{
/* Warn only once if we attempt to go over the cache limit. */
if (msr->tcache_items == msr->txcfg->cache_trans_maxitems) {
msr->tcache_items++;
msr_log(msr, 4, "CACHE: Disabled - phase=%d"
" maxitems=%" APR_SIZE_T_FMT
" limit reached.",
msr->phase,
msr->txcfg->cache_trans_maxitems);
}
}
else if (msr->txcfg->cache_trans_incremental ||
(tfnsnum == tarr->nelts))
{
/* ENH1: Add flag to vars to tell which ones can change across phases store the rest in a global cache */
crec = (msre_cache_rec *)apr_pcalloc(msr->mp, sizeof(msre_cache_rec));
if (crec == NULL) return -1;
crec->hits = 0;
crec->changed = changed;
crec->num = k + 1;
crec->path = tfnspath;
/* We want to cache a copy if it changed otherwise
* we just want to use a pointer to the last changed value.
*/
crec->val = (!lastvarval || tfnchanged) ? apr_pmemdup(msr->mp, var->value, var->value_len) : lastvarval;
crec->val_len = changed ? ((!lastvarval || tfnchanged) ? var->value_len : lastvarlen) : 0;
/* Keep track of the last changed var value */
if (tfnchanged) {
lastvarval = crec->val;
lastvarlen = crec->val_len;
}
#ifdef CACHE_DEBUG
if (changed) {
msr_log(msr, 9, "CACHE: Caching %s=\"%s\" (%pp)",
tfnskey,
log_escape_nq_ex(mptmp,
crec->val,
crec->val_len),
var);
}
else {
msr_log(msr, 9, "CACHE: Caching %s=<no change> (%pp)",
tfnskey,
var);
}
#endif
msr->tcache_items++;
apr_table_setn(cachetab, tfnskey, (void *)crec);
}
}
if (msr->txcfg->debuglog_level >= 9) {
msr_log(msr, 9, "T (%d) %s: \"%s\"", rc, metadata->name,
log_escape_nq_ex(mptmp, var->value, var->value_len));
}
}
}
/* Execute operator if multi-matching is not enabled,
* or if it is and we need to process the result of the
* last transformation.
*/
if (!multi_match || tfnchanged) {
invocations++;
#if defined(PERFORMANCE_MEASUREMENT)
{
apr_time_t t1 = apr_time_now();
rule->trans_time += (t1 - time_before_trans);
}
#else
if (msr->txcfg->debuglog_level >= 4) {
apr_time_t t1 = apr_time_now();
msr_log(msr, 4, "Transformation completed in %" APR_TIME_T_FMT " usec.",
(t1 - time_before_trans));
}
#endif
rc = execute_operator(var, rule, msr, acting_actionset, mptmp);
if (rc < 0) {
return -1;
}
if (rc == RULE_MATCH) {
match_count++;
/* Return straight away if the transaction
* was intercepted - no need to process the remaining
* targets.
*/
if (msr->rule_was_intercepted) {
return RULE_MATCH;
}
}
}
}
return (match_count ? RULE_MATCH : RULE_NO_MATCH);
}