1 /*
2 * ModSecurity for Apache 2.x, http://www.modsecurity.org/
3 * Copyright (c) 2004-2013 Trustwave Holdings, Inc. (http://www.trustwave.com/)
4 *
5 * You may not use this file except in compliance with
6 * the License. You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * If any of the files related to licensing are missing or if you have any
11 * other questions related to licensing please contact Trustwave Holdings, Inc.
12 * directly using the email address security@modsecurity.org.
13 */
14
15 #include <stdlib.h>
16
17 #include "apr_global_mutex.h"
18
19 #include "modsecurity.h"
20 #include "msc_parsers.h"
21 #include "msc_util.h"
22 #include "msc_json.h"
23 #include "msc_xml.h"
24 #include "apr_version.h"
25
26 #ifdef WITH_CURL
27 #include <curl/curl.h>
28 #endif
29
30 unsigned long int DSOLOCAL unicode_codepage = 0;
31
32 int DSOLOCAL *unicode_map_table = NULL;
33
34 /**
35 * Format an alert message.
36 */
msc_alert_message(modsec_rec * msr,msre_actionset * actionset,const char * action_message,const char * rule_message)37 const char * msc_alert_message(modsec_rec *msr, msre_actionset *actionset, const char *action_message,
38 const char *rule_message)
39 {
40 const char *message = NULL;
41
42 if (rule_message == NULL) rule_message = "Unknown error.";
43
44 if (action_message == NULL) {
45 message = apr_psprintf(msr->mp, "%s%s",
46 rule_message, msre_format_metadata(msr, actionset));
47 }
48 else {
49 message = apr_psprintf(msr->mp, "%s %s%s", action_message,
50 rule_message, msre_format_metadata(msr, actionset));
51 }
52
53 return message;
54 }
55
56 /**
57 * Log an alert message to the log, adding the rule metadata at the end.
58 */
msc_alert(modsec_rec * msr,int level,msre_actionset * actionset,const char * action_message,const char * rule_message)59 void msc_alert(modsec_rec *msr, int level, msre_actionset *actionset, const char *action_message,
60 const char *rule_message)
61 {
62 const char *message = msc_alert_message(msr, actionset, action_message, rule_message);
63
64 msr_log(msr, level, "%s", message);
65 }
66
67 #if 0
68 /**
69 * Return phase name associated with the given phase number.
70 */
71 static const char *phase_name(int phase) {
72 switch(phase) {
73 case 1 :
74 return "REQUEST_HEADERS";
75 break;
76 case 2 :
77 return "REQUEST_BODY";
78 break;
79 case 3 :
80 return "RESPONSE_HEADERS";
81 break;
82 case 4 :
83 return "RESPONSE_BODY";
84 break;
85 case 5 :
86 return "LOGGING";
87 break;
88 }
89
90 return "INVALID";
91 }
92 #endif
93
94 /**
95 * Creates and initialises a ModSecurity engine instance.
96 */
modsecurity_create(apr_pool_t * mp,int processing_mode)97 msc_engine *modsecurity_create(apr_pool_t *mp, int processing_mode) {
98 msc_engine *msce = NULL;
99
100 msce = apr_pcalloc(mp, sizeof(msc_engine));
101 if (msce == NULL) return NULL;
102
103 msce->mp = mp;
104 msce->processing_mode = processing_mode;
105
106 msce->msre = msre_engine_create(msce->mp);
107 if (msce->msre == NULL) return NULL;
108 msre_engine_register_default_variables(msce->msre);
109 msre_engine_register_default_operators(msce->msre);
110 msre_engine_register_default_tfns(msce->msre);
111 msre_engine_register_default_actions(msce->msre);
112 // TODO: msre_engine_register_default_reqbody_processors(msce->msre);
113
114 return msce;
115 }
116
117 /**
118 * Initialise the modsecurity engine. This function must be invoked
119 * after configuration processing is complete as Apache needs to know the
120 * username it is running as.
121 */
modsecurity_init(msc_engine * msce,apr_pool_t * mp)122 int modsecurity_init(msc_engine *msce, apr_pool_t *mp) {
123 apr_status_t rc;
124
125 /**
126 * Notice that curl is initialized here but never cleaned up. First version
127 * of this implementation curl was initialized and cleaned for every
128 * utilization. Turns out that it was not only cleaning stuff that was
129 * utilized by Curl but also other OpenSSL stuff that was utilized by
130 * mod_ssl leading the SSL support to crash.
131 */
132 #ifdef WITH_CURL
133 curl_global_init(CURL_GLOBAL_ALL);
134 #endif
135 /* Serial audit log mutext */
136 rc = apr_global_mutex_create(&msce->auditlog_lock, NULL, APR_LOCK_DEFAULT, mp);
137 if (rc != APR_SUCCESS) {
138 //ap_log_error(APLOG_MARK, APLOG_ERR, rv, s, "mod_security: Could not create modsec_auditlog_lock");
139 //return HTTP_INTERNAL_SERVER_ERROR;
140 return -1;
141 }
142
143 #if !defined(MSC_TEST)
144 #ifdef __SET_MUTEX_PERMS
145 #if AP_SERVER_MAJORVERSION_NUMBER > 1 && AP_SERVER_MINORVERSION_NUMBER > 2
146 rc = ap_unixd_set_global_mutex_perms(msce->auditlog_lock);
147 #else
148 rc = unixd_set_global_mutex_perms(msce->auditlog_lock);
149 #endif
150 if (rc != APR_SUCCESS) {
151 // ap_log_error(APLOG_MARK, APLOG_ERR, rc, s, "mod_security: Could not set permissions on modsec_auditlog_lock; check User and Group directives");
152 // return HTTP_INTERNAL_SERVER_ERROR;
153 return -1;
154 }
155 #endif /* SET_MUTEX_PERMS */
156
157 rc = apr_global_mutex_create(&msce->geo_lock, NULL, APR_LOCK_DEFAULT, mp);
158 if (rc != APR_SUCCESS) {
159 return -1;
160 }
161
162 #ifdef __SET_MUTEX_PERMS
163 #if AP_SERVER_MAJORVERSION_NUMBER > 1 && AP_SERVER_MINORVERSION_NUMBER > 2
164 rc = ap_unixd_set_global_mutex_perms(msce->geo_lock);
165 #else
166 rc = unixd_set_global_mutex_perms(msce->geo_lock);
167 #endif
168 if (rc != APR_SUCCESS) {
169 return -1;
170 }
171 #endif /* SET_MUTEX_PERMS */
172
173 #ifdef GLOBAL_COLLECTION_LOCK
174 rc = apr_global_mutex_create(&msce->dbm_lock, NULL, APR_LOCK_DEFAULT, mp);
175 if (rc != APR_SUCCESS) {
176 return -1;
177 }
178
179 #ifdef __SET_MUTEX_PERMS
180 #if AP_SERVER_MAJORVERSION_NUMBER > 1 && AP_SERVER_MINORVERSION_NUMBER > 2
181 rc = ap_unixd_set_global_mutex_perms(msce->dbm_lock);
182 #else
183 rc = unixd_set_global_mutex_perms(msce->dbm_lock);
184 #endif
185 if (rc != APR_SUCCESS) {
186 return -1;
187 }
188 #endif /* SET_MUTEX_PERMS */
189 #endif
190 #endif
191
192 return 1;
193 }
194
195 /**
196 * Performs per-child (new process) initialisation.
197 */
modsecurity_child_init(msc_engine * msce)198 void modsecurity_child_init(msc_engine *msce) {
199 /* Need to call this once per process before any other XML calls. */
200 xmlInitParser();
201
202 if (msce->auditlog_lock != NULL) {
203 apr_status_t rc = apr_global_mutex_child_init(&msce->auditlog_lock, NULL, msce->mp);
204 if (rc != APR_SUCCESS) {
205 // ap_log_error(APLOG_MARK, APLOG_ERR, rs, s, "Failed to child-init auditlog mutex");
206 }
207 }
208
209 if (msce->geo_lock != NULL) {
210 apr_status_t rc = apr_global_mutex_child_init(&msce->geo_lock, NULL, msce->mp);
211 if (rc != APR_SUCCESS) {
212 // ap_log_error(APLOG_MARK, APLOG_ERR, rs, s, "Failed to child-init geo mutex");
213 }
214 }
215
216 #ifdef GLOBAL_COLLECTION_LOCK
217 if (msce->dbm_lock != NULL) {
218 apr_status_t rc = apr_global_mutex_child_init(&msce->dbm_lock, NULL, msce->mp);
219 if (rc != APR_SUCCESS) {
220 // ap_log_error(APLOG_MARK, APLOG_ERR, rs, s, "Failed to child-init dbm mutex");
221 }
222 }
223 #endif
224
225 }
226
227 /**
228 * Releases resources held by engine instance.
229 */
modsecurity_shutdown(msc_engine * msce)230 void modsecurity_shutdown(msc_engine *msce) {
231 if (msce == NULL) return;
232 }
233
234 /**
235 *
236 */
modsecurity_persist_data(modsec_rec * msr)237 static void modsecurity_persist_data(modsec_rec *msr) {
238 const apr_array_header_t *arr;
239 apr_table_entry_t *te;
240 apr_time_t time_before, time_after;
241 int i;
242
243 time_before = apr_time_now();
244
245 /* Collections, store & remove stale. */
246 arr = apr_table_elts(msr->collections);
247 te = (apr_table_entry_t *)arr->elts;
248 for (i = 0; i < arr->nelts; i++) {
249 apr_table_t *col = (apr_table_t *)te[i].val;
250
251 /* Only store those collections that changed. */
252 if (apr_table_get(msr->collections_dirty, te[i].key)) {
253 collection_store(msr, col);
254 }
255 }
256
257 time_after = apr_time_now();
258
259 msr->time_storage_write += time_after - time_before;
260
261 if (msr->txcfg->debuglog_level >= 4) {
262 msr_log(msr, 4, "Recording persistent data took %" APR_TIME_T_FMT
263 " microseconds.", msr->time_gc);
264 }
265
266 /* Remove stale collections. */
267 #if AP_SERVER_MAJORVERSION_NUMBER > 1 && AP_SERVER_MINORVERSION_NUMBER > 3
268 if (ap_random_pick(0, RAND_MAX) < RAND_MAX/100) {
269 #else
270 if (rand() < RAND_MAX/100) {
271 #endif
272 arr = apr_table_elts(msr->collections);
273 te = (apr_table_entry_t *)arr->elts;
274 for (i = 0; i < arr->nelts; i++) {
275 collections_remove_stale(msr, te[i].key);
276 }
277
278 msr->time_gc = apr_time_now() - time_after;
279
280 if (msr->txcfg->debuglog_level >= 4) {
281 msr_log(msr, 4, "Garbage collection took %" APR_TIME_T_FMT
282 " microseconds.", msr->time_gc);
283 }
284 }
285 }
286
287 /**
288 *
289 */
290 static apr_status_t modsecurity_tx_cleanup(void *data) {
291 modsec_rec *msr = (modsec_rec *)data;
292 char *my_error_msg = NULL;
293
294 if (msr == NULL) return APR_SUCCESS;
295
296 /* Multipart processor cleanup. */
297 if (msr->mpd != NULL) multipart_cleanup(msr);
298
299 /* XML processor cleanup. */
300 if (msr->xml != NULL) xml_cleanup(msr);
301
302 #ifdef WITH_YAJL
303 /* JSON processor cleanup. */
304 if (msr->json != NULL) json_cleanup(msr);
305 #endif
306
307 // TODO: Why do we ignore return code here?
308 modsecurity_request_body_clear(msr, &my_error_msg);
309 if (my_error_msg != NULL) {
310 msr_log(msr, 1, "%s", my_error_msg);
311 }
312
313 if (msr->msc_full_request_length > 0 &&
314 msr->msc_full_request_buffer != NULL) {
315 msr->msc_full_request_length = 0;
316 free(msr->msc_full_request_buffer);
317 }
318
319 #if defined(WITH_LUA)
320 #ifdef CACHE_LUA
321 if(msr->L != NULL) lua_close(msr->L);
322 #endif
323 #endif
324
325 return APR_SUCCESS;
326 }
327
328 /**
329 *
330 */
331 apr_status_t modsecurity_tx_init(modsec_rec *msr) {
332 const char *s = NULL;
333 const apr_array_header_t *arr;
334 char *semicolon = NULL;
335 char *comma = NULL;
336 apr_table_entry_t *te;
337 int i;
338
339 /* Register TX cleanup */
340 apr_pool_cleanup_register(msr->mp, msr, modsecurity_tx_cleanup, apr_pool_cleanup_null);
341
342 /* Initialise C-L */
343 msr->request_content_length = -1;
344 s = apr_table_get(msr->request_headers, "Content-Length");
345 if (s != NULL) {
346 msr->request_content_length = strtol(s, NULL, 10);
347 }
348
349 /* Figure out whether this request has a body */
350 msr->reqbody_chunked = 0;
351 msr->reqbody_should_exist = 0;
352 if (msr->request_content_length == -1) {
353 /* There's no C-L, but is chunked encoding used? */
354 char *transfer_encoding = (char *)apr_table_get(msr->request_headers, "Transfer-Encoding");
355 if ((transfer_encoding != NULL)&&(m_strcasestr(transfer_encoding, "chunked") != NULL)) {
356 msr->reqbody_should_exist = 1;
357 msr->reqbody_chunked = 1;
358 }
359 } else {
360 /* C-L found */
361 msr->reqbody_should_exist = 1;
362 }
363
364 /* Initialise C-T */
365 msr->request_content_type = NULL;
366 s = apr_table_get(msr->request_headers, "Content-Type");
367 if (s != NULL) msr->request_content_type = s;
368
369 /* Decide what to do with the request body. */
370 if ((msr->request_content_type != NULL)
371 && (strncasecmp(msr->request_content_type, "application/x-www-form-urlencoded", 33) == 0))
372 {
373 /* Always place POST requests with
374 * "application/x-www-form-urlencoded" payloads in memory.
375 */
376 msr->msc_reqbody_storage = MSC_REQBODY_MEMORY;
377 msr->msc_reqbody_spilltodisk = 0;
378 msr->msc_reqbody_processor = "URLENCODED";
379 } else {
380 /* If the C-L is known and there's more data than
381 * our limit go to disk straight away.
382 */
383 if ((msr->request_content_length != -1)
384 && (msr->request_content_length > msr->txcfg->reqbody_inmemory_limit))
385 {
386 msr->msc_reqbody_storage = MSC_REQBODY_DISK;
387 }
388
389 /* In all other cases, try using the memory first
390 * but switch over to disk for larger bodies.
391 */
392 msr->msc_reqbody_storage = MSC_REQBODY_MEMORY;
393 msr->msc_reqbody_spilltodisk = 1;
394
395 if (msr->request_content_type != NULL) {
396 if (strncasecmp(msr->request_content_type, "multipart/form-data", 19) == 0) {
397 msr->msc_reqbody_processor = "MULTIPART";
398 }
399 }
400 }
401
402 /* Check if we are forcing buffering, then use memory only. */
403 if (msr->txcfg->reqbody_buffering != REQUEST_BODY_FORCEBUF_OFF) {
404 msr->msc_reqbody_storage = MSC_REQBODY_MEMORY;
405 msr->msc_reqbody_spilltodisk = 0;
406 }
407
408 /* Initialise arguments */
409 msr->arguments = apr_table_make(msr->mp, 32);
410 if (msr->arguments == NULL) return -1;
411 if (msr->query_string != NULL) {
412 int invalid_count = 0;
413
414 if (parse_arguments(msr, msr->query_string, strlen(msr->query_string),
415 msr->txcfg->argument_separator, "QUERY_STRING", msr->arguments,
416 &invalid_count) < 0)
417 {
418 msr_log(msr, 1, "Initialisation: Error occurred while parsing QUERY_STRING arguments.");
419 return -1;
420 }
421
422 if (invalid_count) {
423 msr->urlencoded_error = 1;
424 }
425 }
426
427 msr->arguments_to_sanitize = apr_table_make(msr->mp, 16);
428 if (msr->arguments_to_sanitize == NULL) return -1;
429 msr->request_headers_to_sanitize = apr_table_make(msr->mp, 16);
430 if (msr->request_headers_to_sanitize == NULL) return -1;
431 msr->response_headers_to_sanitize = apr_table_make(msr->mp, 16);
432 if (msr->response_headers_to_sanitize == NULL) return -1;
433 msr->pattern_to_sanitize = apr_table_make(msr->mp, 32);
434 if (msr->pattern_to_sanitize == NULL) return -1;
435
436 /* remove targets */
437 msr->removed_targets = apr_table_make(msr->mp, 16);
438 if (msr->removed_targets == NULL) return -1;
439
440 /* Initialise cookies */
441 msr->request_cookies = apr_table_make(msr->mp, 16);
442 if (msr->request_cookies == NULL) return -1;
443
444 /* Initialize matched vars */
445 msr->matched_vars = apr_table_make(msr->mp, 8);
446 if (msr->matched_vars == NULL) return -1;
447 apr_table_clear(msr->matched_vars);
448
449 msr->perf_rules = apr_table_make(msr->mp, 8);
450 if (msr->perf_rules == NULL) return -1;
451 apr_table_clear(msr->perf_rules);
452
453 /* Locate the cookie headers and parse them */
454 arr = apr_table_elts(msr->request_headers);
455 te = (apr_table_entry_t *)arr->elts;
456 for (i = 0; i < arr->nelts; i++) {
457 if (strcasecmp(te[i].key, "Cookie") == 0) {
458 if (msr->txcfg->cookie_format == COOKIES_V0) {
459 semicolon = apr_pstrdup(msr->mp, te[i].val);
460 while((*semicolon != 0)&&(*semicolon != ';')) semicolon++;
461 if(*semicolon == ';') {
462 parse_cookies_v0(msr, te[i].val, msr->request_cookies, ";");
463 } else {
464 comma = apr_pstrdup(msr->mp, te[i].val);
465 while((*comma != 0)&&(*comma != ',')) comma++;
466 if(*comma == ',') {
467 comma++;
468 if(*comma == 0x20) {// looks like comma is the separator
469 if (msr->txcfg->debuglog_level >= 5) {
470 msr_log(msr, 5, "Cookie v0 parser: Using comma as a separator. Semi-colon was not identified!");
471 }
472 parse_cookies_v0(msr, te[i].val, msr->request_cookies, ",");
473 } else {
474 parse_cookies_v0(msr, te[i].val, msr->request_cookies, ";");
475 }
476 } else {
477 parse_cookies_v0(msr, te[i].val, msr->request_cookies, ";");
478 }
479 }
480 } else {
481 parse_cookies_v1(msr, te[i].val, msr->request_cookies);
482 }
483 }
484 }
485
486 /* Collections. */
487 msr->tx_vars = apr_table_make(msr->mp, 32);
488 if (msr->tx_vars == NULL) return -1;
489
490 msr->geo_vars = apr_table_make(msr->mp, 8);
491 if (msr->geo_vars == NULL) return -1;
492
493 msr->collections_original = apr_table_make(msr->mp, 8);
494 if (msr->collections_original == NULL) return -1;
495 msr->collections = apr_table_make(msr->mp, 8);
496 if (msr->collections == NULL) return -1;
497 msr->collections_dirty = apr_table_make(msr->mp, 8);
498 if (msr->collections_dirty == NULL) return -1;
499
500 /* Other */
501 msr->tcache = NULL;
502 msr->tcache_items = 0;
503
504 msr->matched_rules = apr_array_make(msr->mp, 16, sizeof(void *));
505 if (msr->matched_rules == NULL) return -1;
506
507 msr->matched_var = (msc_string *)apr_pcalloc(msr->mp, sizeof(msc_string));
508 if (msr->matched_var == NULL) return -1;
509
510 msr->highest_severity = 255; /* high, invalid value */
511
512 msr->removed_rules = apr_array_make(msr->mp, 16, sizeof(char *));
513 if (msr->removed_rules == NULL) return -1;
514
515 msr->removed_rules_tag = apr_array_make(msr->mp, 16, sizeof(char *));
516 if (msr->removed_rules_tag == NULL) return -1;
517
518 msr->removed_rules_msg = apr_array_make(msr->mp, 16, sizeof(char *));
519 if (msr->removed_rules_msg == NULL) return -1;
520
521 return 1;
522 }
523
524 /**
525 *
526 */
527 static int is_response_status_relevant(modsec_rec *msr, int status) {
528 char *my_error_msg = NULL;
529 apr_status_t rc;
530 char buf[32];
531
532 /* ENH: Setting is_relevant here will cause an audit even if noauditlog
533 * was set for the last rule that matched. Is this what we want?
534 */
535
536 if ((msr->txcfg->auditlog_relevant_regex == NULL)
537 ||(msr->txcfg->auditlog_relevant_regex == NOT_SET_P))
538 {
539 return 0;
540 }
541
542 apr_snprintf(buf, sizeof(buf), "%d", status);
543
544 rc = msc_regexec(msr->txcfg->auditlog_relevant_regex, buf, strlen(buf), &my_error_msg);
545 if (rc >= 0) return 1;
546 if (rc == PCRE_ERROR_NOMATCH) return 0;
547
548 msr_log(msr, 1, "Regex processing failed (rc %d): %s", rc, my_error_msg);
549
550 return 0;
551 }
552
553 /**
554 *
555 */
556 static apr_status_t modsecurity_process_phase_request_headers(modsec_rec *msr) {
557 apr_time_t time_before;
558 apr_status_t rc = 0;
559
560 if (msr->txcfg->debuglog_level >= 4) {
561 msr_log(msr, 4, "Starting phase REQUEST_HEADERS.");
562 }
563
564 time_before = apr_time_now();
565
566 if (msr->txcfg->ruleset != NULL) {
567 rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr);
568 }
569
570 msr->time_phase1 = apr_time_now() - time_before;
571
572 return rc;
573 }
574
575 /**
576 *
577 */
578 static apr_status_t modsecurity_process_phase_request_body(modsec_rec *msr) {
579 apr_time_t time_before;
580 apr_status_t rc = 0;
581
582
583 if ((msr->allow_scope == ACTION_ALLOW_REQUEST)||(msr->allow_scope == ACTION_ALLOW)) {
584 if (msr->txcfg->debuglog_level >= 4) {
585 msr_log(msr, 4, "Skipping phase REQUEST_BODY (allow used).");
586 }
587
588 return 0;
589 } else {
590 if (msr->txcfg->debuglog_level >= 4) {
591 msr_log(msr, 4, "Starting phase REQUEST_BODY.");
592 }
593 }
594
595 time_before = apr_time_now();
596
597 if (msr->txcfg->ruleset != NULL) {
598 rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr);
599 }
600
601 msr->time_phase2 = apr_time_now() - time_before;
602
603 return rc;
604 }
605
606 /**
607 *
608 */
609 static apr_status_t modsecurity_process_phase_response_headers(modsec_rec *msr) {
610 apr_time_t time_before;
611 apr_status_t rc = 0;
612
613 if (msr->allow_scope == ACTION_ALLOW) {
614 if (msr->txcfg->debuglog_level >= 4) {
615 msr_log(msr, 4, "Skipping phase RESPONSE_HEADERS (allow used).");
616 }
617
618 return 0;
619 } else {
620 if (msr->txcfg->debuglog_level >= 4) {
621 msr_log(msr, 4, "Starting phase RESPONSE_HEADERS.");
622 }
623 }
624
625 time_before = apr_time_now();
626
627 if (msr->txcfg->ruleset != NULL) {
628 rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr);
629 }
630
631 msr->time_phase3 = apr_time_now() - time_before;
632
633 return rc;
634 }
635
636 /**
637 *
638 */
639 static apr_status_t modsecurity_process_phase_response_body(modsec_rec *msr) {
640 apr_time_t time_before;
641 apr_status_t rc = 0;
642
643 if (msr->allow_scope == ACTION_ALLOW) {
644 if (msr->txcfg->debuglog_level >= 4) {
645 msr_log(msr, 4, "Skipping phase RESPONSE_BODY (allow used).");
646 }
647
648 return 0;
649 } else {
650 if (msr->txcfg->debuglog_level >= 4) {
651 msr_log(msr, 4, "Starting phase RESPONSE_BODY.");
652 }
653 }
654
655 time_before = apr_time_now();
656
657 if (msr->txcfg->ruleset != NULL) {
658 rc = msre_ruleset_process_phase(msr->txcfg->ruleset, msr);
659 }
660
661 msr->time_phase4 = apr_time_now() - time_before;
662
663
664 return rc;
665 }
666
667 /**
668 *
669 */
670 static apr_status_t modsecurity_process_phase_logging(modsec_rec *msr) {
671 apr_time_t time_before, time_after;
672
673 if (msr->txcfg->debuglog_level >= 4) {
674 msr_log(msr, 4, "Starting phase LOGGING.");
675 }
676
677 time_before = apr_time_now();
678
679 if (msr->txcfg->ruleset != NULL) {
680 msre_ruleset_process_phase(msr->txcfg->ruleset, msr);
681 }
682
683 modsecurity_persist_data(msr);
684
685 time_after = apr_time_now();
686 msr->time_phase5 = time_after - time_before;
687
688 /* Is this request relevant for logging purposes? */
689 if (msr->is_relevant == 0) {
690 /* Check the status */
691 msr->is_relevant += is_response_status_relevant(msr, msr->r->status);
692
693 /* If we processed two requests and statuses are different then
694 * check the other status too.
695 */
696 if (msr->r_early->status != msr->r->status) {
697 msr->is_relevant += is_response_status_relevant(msr, msr->r_early->status);
698 }
699 }
700
701 /* Figure out if we want to keep the files (if there are any, of course). */
702 if ((msr->txcfg->upload_keep_files == KEEP_FILES_ON)
703 || ((msr->txcfg->upload_keep_files == KEEP_FILES_RELEVANT_ONLY)&&(msr->is_relevant)))
704 {
705 msr->upload_remove_files = 0;
706 } else {
707 msr->upload_remove_files = 1;
708 }
709
710 /* Are we configured for audit logging? */
711 switch(msr->txcfg->auditlog_flag) {
712 case AUDITLOG_OFF :
713 if (msr->txcfg->debuglog_level >= 4) {
714 msr_log(msr, 4, "Audit log: Not configured to run for this request.");
715 }
716
717 return DECLINED;
718 break;
719
720 case AUDITLOG_RELEVANT :
721 if (msr->is_relevant == 0) {
722 if (msr->txcfg->debuglog_level >= 4) {
723 msr_log(msr, 4, "Audit log: Ignoring a non-relevant request.");
724 }
725
726 return DECLINED;
727 }
728 break;
729
730 case AUDITLOG_ON :
731 /* All right, do nothing */
732 break;
733
734 default :
735 msr_log(msr, 1, "Internal error: Could not determine if auditing is needed, so forcing auditing.");
736 break;
737 }
738
739 /* Invoke the Audit logger */
740 if (msr->txcfg->debuglog_level >= 4) {
741 msr_log(msr, 4, "Audit log: Logging this transaction.");
742 }
743
744 sec_audit_logger(msr);
745
746 msr->time_logging = apr_time_now() - time_after;
747
748 return 0;
749 }
750
751 /**
752 * Processes one transaction phase. The phase number does not
753 * need to be explicitly provided since it's already available
754 * in the modsec_rec structure.
755 */
756 apr_status_t modsecurity_process_phase(modsec_rec *msr, unsigned int phase) {
757 /* Check if we should run. */
758 if ((msr->was_intercepted)&&(phase != PHASE_LOGGING)) {
759 if (msr->txcfg->debuglog_level >= 4) {
760 msr_log(msr, 4, "Skipping phase %d as request was already intercepted.", phase);
761 }
762
763 return 0;
764 }
765
766 /* Do not process the same phase twice. */
767 if (msr->phase >= phase) {
768 if (msr->txcfg->debuglog_level >= 4) {
769 msr_log(msr, 4, "Skipping phase %d because it was previously run (at %d now).",
770 phase, msr->phase);
771 }
772
773 return 0;
774 }
775
776 msr->phase = phase;
777
778 /* Clear out the transformation cache at the start of each phase */
779 if (msr->txcfg->cache_trans == MODSEC_CACHE_ENABLED) {
780 if (msr->tcache) {
781 apr_hash_index_t *hi;
782 void *dummy;
783 apr_table_t *tab;
784 const void *key;
785 apr_ssize_t klen;
786 #ifdef CACHE_DEBUG
787 apr_pool_t *mp = msr->msc_rule_mptmp;
788 const apr_array_header_t *ctarr;
789 const apr_table_entry_t *ctelts;
790 msre_cache_rec *rec;
791 int cn = 0;
792 int ri;
793 #else
794 apr_pool_t *mp = msr->mp;
795 #endif
796
797 for (hi = apr_hash_first(mp, msr->tcache); hi; hi = apr_hash_next(hi)) {
798 apr_hash_this(hi, &key, &klen, &dummy);
799 tab = (apr_table_t *)dummy;
800
801 if (tab == NULL) continue;
802
803 #ifdef CACHE_DEBUG
804 /* Dump the cache out as we clear */
805 ctarr = apr_table_elts(tab);
806 ctelts = (const apr_table_entry_t*)ctarr->elts;
807 for (ri = 0; ri < ctarr->nelts; ri++) {
808 cn++;
809 rec = (msre_cache_rec *)ctelts[ri].val;
810 if (rec->changed) {
811 if (msr->txcfg->debuglog_level >= 9) {
812 msr_log(msr, 9, "CACHE: %5d) hits=%d key=%pp %x;%s=\"%s\" (%pp - %pp)",
813 cn, rec->hits, key, rec->num, rec->path, log_escape_nq_ex(mp, rec->val, rec->val_len),
814 rec->val, rec->val + rec->val_len);
815 }
816 }
817 else {
818 if (msr->txcfg->debuglog_level >= 9) {
819 msr_log(msr, 9, "CACHE: %5d) hits=%d key=%pp %x;%s=<no change>",
820 cn, rec->hits, key, rec->num, rec->path);
821 }
822 }
823 }
824 #endif
825
826 apr_table_clear(tab);
827 apr_hash_set(msr->tcache, key, klen, NULL);
828 }
829
830 if (msr->txcfg->debuglog_level >= 9) {
831 msr_log(msr, 9, "Cleared transformation cache for phase %d", msr->phase);
832 }
833 }
834
835 msr->tcache_items = 0;
836 msr->tcache = apr_hash_make(msr->mp);
837 if (msr->tcache == NULL) return -1;
838 }
839
840 switch(phase) {
841 case 1 :
842 return modsecurity_process_phase_request_headers(msr);
843 case 2 :
844 return modsecurity_process_phase_request_body(msr);
845 case 3 :
846 return modsecurity_process_phase_response_headers(msr);
847 case 4 :
848 return modsecurity_process_phase_response_body(msr);
849 case 5 :
850 return modsecurity_process_phase_logging(msr);
851 default :
852 msr_log(msr, 1, "Invalid processing phase: %d", msr->phase);
853 break;
854 }
855
856 return -1;
857 }
858