apache2/msc_logging.c

   1 /*
   2  * ModSecurity for Apache 2.x, http://www.modsecurity.org/
   3  * Copyright (c) 2004-2009 Breach Security, Inc. (http://www.breach.com/)
   4  *
   5  * This product is released under the terms of the General Public Licence,
   6  * version 2 (GPLv2). Please refer to the file LICENSE (included with this
   7  * distribution) which contains the complete text of the licence.
   8  *
   9  * There are special exceptions to the terms and conditions of the GPL
  10  * as it is applied to this software. View the full text of the exception in
  11  * file MODSECURITY_LICENSING_EXCEPTION in the directory of this software
  12  * distribution.
  13  *
  14  * If any of the files related to licensing are missing or if you have any
  15  * other questions related to licensing please contact Breach Security, Inc.
  16  * directly using the email address support@breach.com.
  17  *
  18  */
  19 #include <sys/stat.h>
  20
  21 #include "mod_security2_config.h"
  22 #include "re.h"
  23 #include "msc_logging.h"
  24 #include "httpd.h"
  25 #include "apr_strings.h"
  26 #include "apr_global_mutex.h"
  27 #include "msc_util.h"
  28
  29
  30 /**
  31  * Write the supplied data to the audit log (if the FD is ready), update
  32  * the size counters, update the hash context.
  33  */
  34 static int sec_auditlog_write(modsec_rec *msr, const char *data, unsigned int len) {
  35     apr_size_t nbytes_written, nbytes = len;
  36     apr_status_t rc;
  37
  38     /* Do nothing if there's no data. */
  39     if (data == NULL) return -1;
  40
  41     /* Update size counters and the hash calculation. We always do this,
  42      * even in cases where write fails. That will make it easier to detect
  43      * problems with partial writes.
  44      */
  45     msr->new_auditlog_size += len;
  46     apr_md5_update(&msr->new_auditlog_md5ctx, data, len);
  47
  48     /* Do not write if we do not have a file descriptor. */
  49     if (msr->new_auditlog_fd == NULL) return -1;
  50
  51     /* Write data to file. */
  52     rc = apr_file_write_full(msr->new_auditlog_fd, data, nbytes, &nbytes_written);
  53     if (rc != APR_SUCCESS) {
  54         msr_log(msr, 1, "Audit log: Failed writing (requested %" APR_SIZE_T_FMT
  55             " bytes, written %" APR_SIZE_T_FMT ")", nbytes, nbytes_written);
  56
  57         /* Set to NULL to prevent more than one error message on
  58          * out-of-disk-space events and to prevent further attempts
  59          * to write to the same file in this request.
  60          *
  61          * Note that, as we opened the file through the pool mechanism of
  62          * the APR, we do not need to close the file here. It will be closed
  63          * automatically at the end of the request.
  64          */
  65         msr->new_auditlog_fd = NULL;
  66
  67         return -1;
  68     }
  69
  70     return 1;
  71 }
  72
  73 /**
  74  * Construct a log line in the vcombinedus format (see below).
  75  */
  76 char *construct_log_vcombinedus(modsec_rec *msr) {
  77     const char *local_user, *remote_user;
  78     const char *referer, *user_agent, *uniqueid;
  79     const char *sessionid;
  80
  81     /* remote log name */
  82     if (msr->remote_user == NULL) remote_user = "-";
  83     else remote_user = msr->remote_user;
  84
  85     /* authenticated user */
  86     if (msr->local_user == NULL) local_user = "-";
  87     else local_user = msr->local_user;
  88
  89     /* unique id */
  90     uniqueid = msr->txid;
  91     if (uniqueid == NULL) uniqueid = "-";
  92
  93     /* referer */
  94     referer = "-";
  95     /* Logging Referer is a waste of space.
  96     referer = (char *)apr_table_get(msr->request_headers, "Referer");
  97     if (referer == NULL) referer = "-";
  98     */
  99
 100     /* user agent */
 101     user_agent = "-";
 102     /* Logging User-Agent is a waste of space too.
 103     user_agent = (char *)apr_table_get(msr->request_headers, "User-Agent");
 104     if (user_agent == NULL) user_agent = "-";
 105     */
 106
 107     /* sessionid */
 108     sessionid = (msr->sessionid == NULL ? "-" : msr->sessionid);
 109
 110     return apr_psprintf(msr->mp, "%s %s %s %s [%s] \"%s\" %u %" APR_OFF_T_FMT " \"%s\" \"%s\" %s \"%s\"",
 111         log_escape_nq(msr->mp, msr->hostname), msr->remote_addr, log_escape_nq(msr->mp, remote_user),
 112         log_escape_nq(msr->mp, local_user), current_logtime(msr->mp),
 113         ((msr->request_line == NULL) ? "" : log_escape(msr->mp, msr->request_line)),
 114         msr->response_status, msr->bytes_sent, log_escape(msr->mp, referer),
 115         log_escape(msr->mp, user_agent), log_escape(msr->mp, uniqueid), sessionid);
 116 }
 117
 118 /**
 119  * Constructs a log line in vcombined log format trying to truncate
 120  * some of the fields to make the log line shorter than _limit bytes.
 121  */
 122 char *construct_log_vcombinedus_limited(modsec_rec *msr, int _limit, int *was_limited) {
 123     char *hostname;
 124     char *local_user, *remote_user;
 125     char *referer, *user_agent, *uniqueid;
 126     const char *sessionid;
 127     char *the_request, *bytes_sent;
 128     int limit = _limit;
 129
 130     /* hostname */
 131     hostname = (msr->hostname == NULL ? "-" : log_escape_nq(msr->mp, msr->hostname));
 132
 133     /* remote log name */
 134     if (msr->remote_user == NULL) remote_user = "-";
 135     else remote_user = log_escape_nq(msr->mp, msr->remote_user);
 136
 137     /* authenticated user */
 138     if (msr->local_user == NULL) local_user = "-";
 139     else local_user = log_escape_nq(msr->mp, msr->local_user);
 140
 141     /* unique id */
 142     if (msr->txid == NULL) uniqueid = "-";
 143     else uniqueid = log_escape(msr->mp, msr->txid);
 144
 145     /* referer */
 146     referer = "-";
 147     /*
 148     referer = (char *)apr_table_get(msr->request_headers, "Referer");
 149     if (referer == NULL) referer = "-";
 150     else referer = log_escape(msr->mp, referer);
 151     */
 152
 153     /* user agent */
 154     user_agent = "-";
 155     /*
 156     user_agent = (char *)apr_table_get(msr->request_headers, "User-Agent");
 157     if (user_agent == NULL) user_agent = "-";
 158     else user_agent = log_escape(msr->mp, user_agent);
 159     */
 160
 161     /* sessionid */
 162     sessionid = (msr->sessionid == NULL) ? "-" : log_escape(msr->mp, msr->sessionid);
 163
 164     the_request = (msr->request_line == NULL) ? "" : log_escape(msr->mp, msr->request_line);
 165
 166     bytes_sent = apr_psprintf(msr->mp, "%" APR_OFF_T_FMT, msr->bytes_sent);
 167
 168     /* first take away the size of the
 169      * information we must log
 170      */
 171     limit -= 22;                                 /* spaces and double quotes */
 172     limit -= strlen(hostname);                   /* server name or IP */
 173     limit -= strlen(msr->remote_addr);           /* remote IP */
 174     limit -= 28;                                 /* current_logtime */
 175     limit -= 3;                                  /* status */
 176     limit -= strlen(bytes_sent);                 /* bytes sent */
 177     limit -= strlen(uniqueid);                   /* unique id */
 178     limit -= strlen(sessionid);                  /* session id */
 179
 180     if (limit <= 0) {
 181         msr_log(msr, 1, "GuardianLog: Atomic pipe write size too small: %d", PIPE_BUF);
 182         return NULL;
 183     }
 184
 185     /* we hope to be able to squeeze everything in */
 186     if (limit < (int)(strlen(remote_user) + strlen(local_user) + strlen(referer)
 187         + strlen(user_agent) + strlen(the_request)))
 188     {
 189         /* Boo hoo hoo, there's not enough space available. */
 190         *was_limited = 1;
 191
 192         /* Let's see if we can reduce the size of something. This
 193          * is a very crude approach but it seems to work for our
 194          * needs.
 195          */
 196         if (strlen(remote_user) > 32) {
 197             msr_log(msr, 9, "GuardianLog: Reduced remote_user to 32.");
 198             remote_user[32] = '\0';
 199         }
 200         limit -= strlen(remote_user);
 201
 202         if (strlen(local_user) > 32) {
 203             msr_log(msr, 9, "GuardianLog: Reduced local_user to 32.");
 204             local_user[32] = '\0';
 205         }
 206         limit -= strlen(local_user);
 207
 208         if (strlen(referer) > 64) {
 209             msr_log(msr, 9, "GuardianLog: Reduced referer to 64.");
 210             referer[64] = '\0';
 211         }
 212         limit -= strlen(referer);
 213
 214         if (strlen(user_agent) > 64) {
 215             msr_log(msr, 9, "GuardianLog: Reduced user_agent to 64.");
 216             user_agent[64] = '\0';
 217         }
 218         limit -= strlen(user_agent);
 219
 220         if (limit <= 0) {
 221             msr_log(msr, 1, "GuardianLog: Atomic pipe write size too small: %d.", PIPE_BUF);
 222             return NULL;
 223         }
 224
 225         /* use what's left for the request line */
 226         if ((int)strlen(the_request) > limit) {
 227             the_request[limit] = '\0';
 228             msr_log(msr, 9, "GuardianLog: Reduced the_request to %d bytes.", limit);
 229         }
 230     } else {
 231         /* Yay! We have enough space! */
 232         *was_limited = 0;
 233     }
 234
 235     return apr_psprintf(msr->mp, "%s %s %s %s [%s] \"%s\" %u %s \"%s\" \"%s\" %s \"%s\"",
 236         hostname, msr->remote_addr, remote_user,
 237         local_user, current_logtime(msr->mp), the_request,
 238         msr->response_status, bytes_sent, referer, user_agent,
 239         uniqueid, sessionid
 240     );
 241 }
 242
 243 /**
 244  * Checks if the provided string is a valid audit log parts specification.
 245  */
 246 int is_valid_parts_specification(char *p) {
 247     char c, *t = p;
 248
 249     while((c = *(t++)) != '\0') {
 250         if ((c != AUDITLOG_PART_ENDMARKER)&&((c < AUDITLOG_PART_FIRST)||(c > AUDITLOG_PART_LAST))) {
 251             return 0;
 252         }
 253     }
 254
 255     return 1;
 256 }
 257
 258 /**
 259  * Constructs a filename that will be used to store an
 260  * audit log entry.
 261  */
 262 static char *construct_auditlog_filename(apr_pool_t *mp, const char *uniqueid) {
 263     apr_time_exp_t t;
 264     char tstr[300];
 265     apr_size_t len;
 266
 267     apr_time_exp_lt(&t, apr_time_now());
 268
 269     apr_strftime(tstr, &len, 299, "/%Y%m%d/%Y%m%d-%H%M/%Y%m%d-%H%M%S", &t);
 270     return apr_psprintf(mp, "%s-%s", tstr, uniqueid);
 271 }
 272
 273 /**
 274  * Creates a random 8-character string that
 275  * consists of hexadecimal numbers, to be used
 276  * as an audit log boundary.
 277  */
 278 static char *create_auditlog_boundary(request_rec *r) {
 279     unsigned long data = rand();
 280     /* Do note that I tried using apr_generate_random_bytes but it turned
 281      * out to be terribly slow for some reason. Needs further investigation.
 282      */
 283     return bytes2hex(r->pool, (void *)&data, 4);
 284 }
 285
 286 /**
 287  * Sanitises the request line by removing the parameters
 288  * that have been marked as sensitive.
 289  */
 290 static void sanitise_request_line(modsec_rec *msr) {
 291     const apr_array_header_t *tarr;
 292     const apr_table_entry_t *telts;
 293     int i;
 294     char *qspos;
 295
 296     /* Locate the query string. */
 297     qspos = strstr(msr->request_line, "?");
 298     if (qspos == NULL) return;
 299     qspos++;
 300
 301     /* Loop through the list of sensitive parameters. */
 302     tarr = apr_table_elts(msr->arguments_to_sanitise);
 303     telts = (const apr_table_entry_t*)tarr->elts;
 304     for (i = 0; i < tarr->nelts; i++) {
 305         msc_arg *arg = (msc_arg *)telts[i].val;
 306         /* Only look at the parameters that appeared in the query string. */
 307         if (strcmp(arg->origin, "QUERY_STRING") == 0) {
 308             char *p;
 309             int j;
 310
 311             /* Go to the beginning of the parameter. */
 312             p = qspos;
 313             j = arg->value_origin_offset;
 314             while((*p != '\0')&&(j--)) p++;
 315             if (*p == '\0') {
 316                 msr_log(msr, 1, "Unable to sanitise variable \"%s\" at offset %u of QUERY_STRING"
 317                     "because the request line is too short.",
 318                     log_escape_ex(msr->mp, arg->name, arg->name_len),
 319                     arg->value_origin_offset);
 320                 continue;
 321             }
 322
 323             /* Write over the value. */
 324             j = arg->value_origin_len;
 325             while((*p != '\0')&&(j--)) {
 326                 *p++ = '*';
 327             }
 328             if (*p == '\0') {
 329                 msr_log(msr, 1, "Unable to sanitise variable \"%s\" at offset %u (size %d) "
 330                     "of QUERY_STRING because the request line is too short.",
 331                     log_escape_ex(msr->mp, arg->name, arg->name_len),
 332                     arg->value_origin_offset, arg->value_origin_len);
 333                 continue;
 334             }
 335         }
 336     }
 337 }
 338
 339 /**
 340  * Output the Producer header.
 341  */
 342 static void sec_auditlog_write_producer_header(modsec_rec *msr) {
 343     char **signatures = NULL;
 344     char *text = NULL;
 345     int i;
 346
 347     /* Try to write everything in one go. */
 348     if (msr->txcfg->component_signatures->nelts == 0) {
 349         text = apr_psprintf(msr->mp, "Producer: %s.\n", MODSEC_MODULE_NAME_FULL);
 350         sec_auditlog_write(msr, text, strlen(text));
 351
 352         return;
 353     }
 354
 355     /* Start with the ModSecurity signature. */
 356     text = apr_psprintf(msr->mp, "Producer: %s", MODSEC_MODULE_NAME_FULL);
 357     sec_auditlog_write(msr, text, strlen(text));
 358
 359
 360     /* Then loop through the components and output individual signatures. */
 361     signatures = (char **)msr->txcfg->component_signatures->elts;
 362     for(i = 0; i < msr->txcfg->component_signatures->nelts; i++) {
 363         text = apr_psprintf(msr->mp, "; %s", (char *)signatures[i]);
 364         sec_auditlog_write(msr, text, strlen(text));
 365     }
 366
 367     sec_auditlog_write(msr, ".\n", 2);
 368 }
 369
 370 /**
 371  * Produce an audit log entry.
 372  */
 373 void sec_audit_logger(modsec_rec *msr) {
 374     const apr_array_header_t *arr = NULL;
 375     apr_table_entry_t *te = NULL;
 376     char *str1 = NULL, *str2 = NULL, *text = NULL;
 377     const msre_rule *rule = NULL;
 378     apr_size_t nbytes, nbytes_written;
 379     unsigned char md5hash[APR_MD5_DIGESTSIZE];
 380     int was_limited = 0;
 381     int wrote_response_body = 0;
 382     char *entry_filename, *entry_basename;
 383     apr_status_t rc;
 384     int i, limit;
 385
 386     /* the boundary is used by both audit log types */
 387     msr->new_auditlog_boundary = create_auditlog_boundary(msr->r);
 388
 389     /* Return silently if we don't have a request line. This
 390      * means we will not be logging request timeouts.
 391      */
 392     if (msr->request_line == NULL) {
 393         msr_log(msr, 4, "Audit log: Skipping request whose request_line is null.");
 394         return;
 395     }
 396
 397     /* Also return silently if we don't have a file descriptor. */
 398     if (msr->txcfg->auditlog_fd == NULL) {
 399         msr_log(msr, 4, "Audit log: Skipping request since there is nowhere to write to.");
 400         return;
 401     }
 402
 403     if (msr->txcfg->auditlog_type != AUDITLOG_CONCURRENT) {
 404         /* Serial logging - we already have an open file
 405          * descriptor to write to.
 406          */
 407         msr->new_auditlog_fd = msr->txcfg->auditlog_fd;
 408     } else {
 409         /* Concurrent logging - we need to create a brand
 410          * new file for this request.
 411          */
 412         apr_md5_init(&msr->new_auditlog_md5ctx);
 413
 414         msr->new_auditlog_filename = construct_auditlog_filename(msr->mp, msr->txid);
 415         if (msr->new_auditlog_filename == NULL) return;
 416
 417         /* The audit log storage directory should be explicitly
 418          * defined. But if it isn't try to write to the same
 419          * directory where the index file is placed. Of course,
 420          * it is *very* bad practice to allow the Apache user
 421          * to write to the same directory where a root user is
 422          * writing to but it's not us that's causing the problem
 423          * and there isn't anything we can do about that.
 424          *
 425          * ENH Actually there is something we can do! We will make
 426          * SecAuditStorageDir mandatory, ask the user to explicitly
 427          * define the storage location *and* refuse to work if the
 428          * index and the storage location are in the same folder.
 429          */
 430         if (msr->txcfg->auditlog_storage_dir == NULL) {
 431             entry_filename = file_dirname(msr->mp, msr->txcfg->auditlog_name);
 432         }
 433         else {
 434             entry_filename = msr->txcfg->auditlog_storage_dir;
 435         }
 436         if (entry_filename == NULL) return;
 437
 438         entry_filename = apr_psprintf(msr->mp, "%s%s", entry_filename, msr->new_auditlog_filename);
 439         if (entry_filename == NULL) return;
 440         entry_basename = file_dirname(msr->mp, entry_filename);
 441         if (entry_basename == NULL) return;
 442
 443         /* IMP1 Surely it would be more efficient to check the folders for
 444          * the audit log repository base path in the configuration phase, to reduce
 445          * the work we do on every request. Also, since our path depends on time,
 446          * we could cache the time we last checked and don't check if we know
 447          * the folder is there.
 448          */
 449         rc = apr_dir_make_recursive(entry_basename, msr->txcfg->auditlog_dirperms, msr->mp);
 450         if (rc != APR_SUCCESS) {
 451             msr_log(msr, 1, "Audit log: Failed to create subdirectories: %s (%s)",
 452                 entry_basename, get_apr_error(msr->mp, rc));
 453             return;
 454         }
 455
 456         rc = apr_file_open(&msr->new_auditlog_fd, entry_filename,
 457             APR_WRITE | APR_TRUNCATE | APR_CREATE | APR_BINARY | APR_FILE_NOCLEANUP,
 458             msr->txcfg->auditlog_fileperms, msr->mp);
 459         if (rc != APR_SUCCESS) {
 460             msr_log(msr, 1, "Audit log: Failed to create file: %s (%s)",
 461                 entry_filename, get_apr_error(msr->mp, rc));
 462             return;
 463         }
 464     }
 465
 466     /* Lock the mutex, but only if we are using serial format. */
 467     if (msr->txcfg->auditlog_type != AUDITLOG_CONCURRENT) {
 468         rc = apr_global_mutex_lock(msr->modsecurity->auditlog_lock);
 469         if (rc != APR_SUCCESS) {
 470             msr_log(msr, 1, "Audit log: Failed to lock global mutex: %s",
 471                 get_apr_error(msr->mp, rc));
 472         }
 473     }
 474
 475     /* AUDITLOG_PART_HEADER */
 476
 477     text = apr_psprintf(msr->mp, "--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_HEADER);
 478     sec_auditlog_write(msr, text, strlen(text));
 479
 480     /* Format: time transaction_id remote_addr remote_port local_addr local_port */
 481
 482     text = apr_psprintf(msr->mp, "[%s] %s %s %u %s %u",
 483         current_logtime(msr->mp), msr->txid, msr->remote_addr, msr->remote_port,
 484         msr->local_addr, msr->local_port);
 485     sec_auditlog_write(msr, text, strlen(text));
 486
 487
 488     /* AUDITLOG_PART_REQUEST_HEADERS */
 489
 490     if (strchr(msr->txcfg->auditlog_parts, AUDITLOG_PART_REQUEST_HEADERS) != NULL) {
 491         text = apr_psprintf(msr->mp, "\n--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_REQUEST_HEADERS);
 492         sec_auditlog_write(msr, text, strlen(text));
 493
 494         sanitise_request_line(msr);
 495
 496         sec_auditlog_write(msr, msr->request_line, strlen(msr->request_line));
 497         sec_auditlog_write(msr, "\n", 1);
 498
 499         arr = apr_table_elts(msr->request_headers);
 500         te = (apr_table_entry_t *)arr->elts;
 501         for (i = 0; i < arr->nelts; i++) {
 502             text = apr_psprintf(msr->mp, "%s: %s\n", te[i].key, te[i].val);
 503             /* Do we need to sanitise this request header? */
 504             if (apr_table_get(msr->request_headers_to_sanitise, te[i].key) != NULL) {
 505                 /* Yes, sanitise it. */
 506                 memset(text + strlen(te[i].key) + 2, '*', strlen(te[i].val));
 507             }
 508             sec_auditlog_write(msr, text, strlen(text));
 509         }
 510     }
 511
 512     /* AUDITLOG_PART_REQUEST_BODY */
 513
 514     /* Output this part of it was explicitly requested (C) or if it was the faked
 515      * request body that was requested (I) but we have no reason to fake it (it's
 516      * already in the correct format).
 517      */
 518     if ( (strchr(msr->txcfg->auditlog_parts, AUDITLOG_PART_REQUEST_BODY) != NULL)
 519         || ( (strchr(msr->txcfg->auditlog_parts, AUDITLOG_PART_FAKE_REQUEST_BODY) != NULL)
 520             && (msr->mpd == NULL) ) )
 521     {
 522         if (msr->msc_reqbody_read) {
 523             const apr_array_header_t *tarr;
 524             const apr_table_entry_t *telts;
 525             apr_array_header_t *sorted_args;
 526             unsigned int offset = 0, last_offset = 0;
 527             msc_arg *nextarg = NULL;
 528             int sanitise = 0; /* IMP1 Use constants for "sanitise" values. */
 529             char *my_error_msg = NULL;
 530
 531             sorted_args = apr_array_make(msr->mp, 25, sizeof(const msc_arg *));
 532
 533             /* First we need to sort the arguments that need to be
 534              * sanitised in descending order (we are using a stack structure
 535              * to store then so the order will be ascending when we start
 536              * popping them out). This is because we will
 537              * be reading the request body sequentially and must
 538              * sanitise it as we go.
 539              */
 540
 541             for(;;) {
 542                 nextarg = NULL;
 543
 544                 /* Find the next largest offset (excluding
 545                  * the ones we've used up already).
 546                  */
 547                 tarr = apr_table_elts(msr->arguments_to_sanitise);
 548                 telts = (const apr_table_entry_t*)tarr->elts;
 549                 for(i = 0; i < tarr->nelts; i++) {
 550                     msc_arg *arg = (msc_arg *)telts[i].val;
 551                     if (strcmp(arg->origin, "BODY") != 0) continue;
 552
 553                     if (last_offset == 0) { /* The first time we're here. */
 554                         if (arg->value_origin_offset > offset) {
 555                             offset = arg->value_origin_offset;
 556                             nextarg = arg;
 557                         }
 558                     } else { /* Not the first time. */
 559                         if ((arg->value_origin_offset > offset)
 560                             &&(arg->value_origin_offset < last_offset))
 561                         {
 562                             offset = arg->value_origin_offset;
 563                             nextarg = arg;
 564                         }
 565                     }
 566                 }
 567
 568                 /* If we don't have the next argument that means
 569                  * we're done here.
 570                  */
 571                 if (nextarg == NULL) break;
 572
 573                 sanitise = 2; /* Means time to pop the next argument out. */
 574                 last_offset = offset;
 575                 offset = 0;
 576                 { /* IMP1 Fix this ugly bit here. */
 577                     msc_arg **x = apr_array_push(sorted_args);
 578                     *x = nextarg;
 579                 }
 580             }
 581
 582             /* Now start retrieving the body chunk by chunk and
 583              * sanitise data in pieces.
 584              */
 585
 586             rc = modsecurity_request_body_retrieve_start(msr, &my_error_msg);
 587             if (rc < 0) {
 588                 msr_log(msr, 1, "Audit log: %s", my_error_msg);
 589             } else {
 590                 msc_data_chunk *chunk = NULL;
 591                 unsigned int chunk_offset = 0;
 592                 unsigned int sanitise_offset = 0;
 593                 unsigned int sanitise_length = 0;
 594
 595                 text = apr_psprintf(msr->mp, "\n--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_REQUEST_BODY);
 596                 sec_auditlog_write(msr, text, strlen(text));
 597
 598                 for(;;) {
 599                     rc = modsecurity_request_body_retrieve(msr, &chunk, -1, &my_error_msg);
 600                     if (chunk != NULL) {
 601                         /* Anything greater than 1 means we have more data to sanitise. */
 602                         while (sanitise > 1) {
 603                             msc_arg **arg = NULL;
 604
 605                             if (sanitise == 2) {
 606                                 /* Get the next argument from the stack. */
 607                                 arg = (msc_arg **)apr_array_pop(sorted_args);
 608                                 if (arg == NULL) sanitise = 0; /* We're done sanitising. */
 609                                 else {
 610                                     /* Continue with sanitation to process the
 611                                      * retrieved argument.
 612                                      */
 613                                     sanitise = 1;
 614                                     sanitise_offset = (*arg)->value_origin_offset;
 615                                     sanitise_length = (*arg)->value_origin_len;
 616                                 }
 617                             }
 618
 619                             if (sanitise) {
 620                                 /* Check if the data we want to sanitise is
 621                                  * stored in the current chunk.
 622                                  */
 623                                 if (chunk_offset + chunk->length > sanitise_offset) {
 624                                     unsigned int soff; /* data offset within chunk */
 625                                     unsigned int len;  /* amount in this chunk to sanitise */
 626
 627                                     soff = sanitise_offset - chunk_offset;
 628
 629                                     if (soff + sanitise_length <= chunk->length) {
 630                                         /* The entire argument resides in the current chunk. */
 631                                         len = sanitise_length;
 632                                         sanitise = 2; /* Get another parameter to sanitise. */
 633                                     } else {
 634                                         /* Some work to do here but we'll need to seek
 635                                          * another chunk.
 636                                          */
 637                                         len = chunk->length - soff;
 638                                         sanitise_offset += len;
 639                                         sanitise_length -= len;
 640                                         sanitise = 1; /* It's OK to go to the next chunk. */
 641                                     }
 642
 643                                     /* Yes, we actually write over the original data.
 644                                      * We shouldn't be needing it any more.
 645                                      */
 646                                     if (soff + len <= chunk->length) { /* double check */
 647                                         memset((char *)chunk->data + soff, '*', len);
 648                                     }
 649                                 }
 650                             }
 651                         }
 652
 653                         /* Write the sanitised chunk to the log
 654                          * and advance to the next chunk. */
 655                         sec_auditlog_write(msr, chunk->data, chunk->length);
 656                         chunk_offset += chunk->length;
 657                     }
 658
 659                     if (rc <= 0) {
 660                         break;
 661                     }
 662                 }
 663
 664                 if (rc < 0) {
 665                     msr_log(msr, 1, "Audit log: %s", my_error_msg);
 666                 }
 667
 668                 modsecurity_request_body_retrieve_end(msr);
 669             }
 670         }
 671     }
 672
 673     /* AUDITLOG_PART_FAKE_REQUEST_BODY */
 674
 675     if (strchr(msr->txcfg->auditlog_parts, AUDITLOG_PART_FAKE_REQUEST_BODY) != NULL) {
 676         if ((msr->msc_reqbody_read)&&(msr->mpd != NULL)) {
 677             char *buffer = NULL;
 678
 679             buffer = multipart_reconstruct_urlencoded_body_sanitise(msr);
 680             if (buffer == NULL) {
 681                 msr_log(msr, 1, "Audit log: Failed to reconstruct request body.");
 682             } else {
 683                 text = apr_psprintf(msr->mp, "\n--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_FAKE_REQUEST_BODY);
 684                 sec_auditlog_write(msr, text, strlen(text));
 685                 sec_auditlog_write(msr, buffer, strlen(buffer));
 686             }
 687         }
 688     }
 689
 690     /* AUDITLOG_PART_A_RESPONSE_HEADERS */
 691
 692     if (strchr(msr->txcfg->auditlog_parts, AUDITLOG_PART_A_RESPONSE_HEADERS) != NULL) {
 693         text = apr_psprintf(msr->mp, "\n--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_A_RESPONSE_HEADERS);
 694         sec_auditlog_write(msr, text, strlen(text));
 695
 696         /* There are no response headers (or the status line) in HTTP 0.9 */
 697         if (msr->response_headers_sent) {
 698             if (msr->status_line != NULL) {
 699                 text = apr_psprintf(msr->mp, "%s %s\n", msr->response_protocol,
 700                     msr->status_line);
 701             } else {
 702                 text = apr_psprintf(msr->mp, "%s %u\n", msr->response_protocol,
 703                     msr->response_status);
 704             }
 705             sec_auditlog_write(msr, text, strlen(text));
 706
 707             /* Output headers */
 708
 709             arr = apr_table_elts(msr->response_headers);
 710             te = (apr_table_entry_t *)arr->elts;
 711             for (i = 0; i < arr->nelts; i++) {
 712                 text = apr_psprintf(msr->mp, "%s: %s\n", te[i].key, te[i].val);
 713                 /* Do we need to sanitise this response header? */
 714                 if (apr_table_get(msr->response_headers_to_sanitise, te[i].key) != NULL) {
 715                     /* Yes, sanitise it. */
 716                     memset(text + strlen(te[i].key) + 2, '*', strlen(te[i].val));
 717                 }
 718                 sec_auditlog_write(msr, text, strlen(text));
 719             }
 720         }
 721     }
 722
 723     /* AUDITLOG_PART_RESPONSE_BODY */
 724
 725     if (strchr(msr->txcfg->auditlog_parts, AUDITLOG_PART_RESPONSE_BODY) != NULL) {
 726         if (msr->resbody_data != NULL) {
 727             text = apr_psprintf(msr->mp, "\n--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_RESPONSE_BODY);
 728             sec_auditlog_write(msr, text, strlen(text));
 729             sec_auditlog_write(msr, msr->resbody_data, msr->resbody_length);
 730             wrote_response_body = 1;
 731         }
 732     }
 733
 734     /* AUDITLOG_PART_TRAILER */
 735
 736     if (strchr(msr->txcfg->auditlog_parts, AUDITLOG_PART_TRAILER) != NULL) {
 737         apr_time_t now = apr_time_now();
 738
 739         text = apr_psprintf(msr->mp, "\n--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_TRAILER);
 740         sec_auditlog_write(msr, text, strlen(text));
 741
 742         /* Messages */
 743         for(i = 0; i < msr->alerts->nelts; i++) {
 744             text = apr_psprintf(msr->mp, "Message: %s\n", ((char **)msr->alerts->elts)[i]);
 745             sec_auditlog_write(msr, text, strlen(text));
 746         }
 747
 748         /* Apache error messages */
 749         for(i = 0; i < msr->error_messages->nelts; i++) {
 750             error_message *em = (((error_message**)msr->error_messages->elts)[i]);
 751             text = apr_psprintf(msr->mp, "Apache-Error: %s\n",
 752                 format_error_log_message(msr->mp, em));
 753             sec_auditlog_write(msr, text, strlen(text));
 754         }
 755
 756         /* Action */
 757         if (msr->was_intercepted) {
 758             text = apr_psprintf(msr->mp, "Action: Intercepted (phase %d)\n", msr->intercept_phase);
 759             sec_auditlog_write(msr, text, strlen(text));
 760         }
 761
 762         /* Apache-Handler */
 763         if (msr->r->handler != NULL) {
 764             text = apr_psprintf(msr->mp, "Apache-Handler: %s\n", msr->r->handler);
 765             sec_auditlog_write(msr, text, strlen(text));
 766         }
 767
 768         /* Processing times */
 769         if (msr->time_checkpoint_1 == 0) {
 770             text = apr_psprintf(msr->mp, "Stopwatch: %" APR_TIME_T_FMT " %" APR_TIME_T_FMT
 771                 " (- - -)\n", (msr->request_time), (now - msr->request_time));
 772         } else {
 773             char sw_str2[101] = "-";
 774             char sw_str3[101] = "-";
 775
 776             if (msr->time_checkpoint_2 != 0) {
 777                 apr_snprintf(sw_str2, sizeof(sw_str2), "%" APR_TIME_T_FMT,
 778                     (msr->time_checkpoint_2 - msr->request_time));
 779             }
 780
 781             if (msr->time_checkpoint_3 != 0) {
 782                 apr_snprintf(sw_str3, sizeof(sw_str3), "%" APR_TIME_T_FMT,
 783                     (msr->time_checkpoint_3 - msr->request_time));
 784             }
 785
 786             text = apr_psprintf(msr->mp, "Stopwatch: %" APR_TIME_T_FMT
 787                 " %" APR_TIME_T_FMT " (%" APR_TIME_T_FMT
 788                 "%s %s %s)\n",
 789                 (msr->request_time), (now - msr->request_time),
 790                 (msr->time_checkpoint_1 - msr->request_time),
 791                 ((msr->msc_reqbody_read == 0) ? "" : "*"),
 792                 sw_str2, sw_str3
 793                 );
 794         }
 795
 796         sec_auditlog_write(msr, text, strlen(text));
 797
 798         /* Our response body does not contain chunks */
 799         /* ENH Only write this when the output was chunked. */
 800         /* ENH Add info when request body was decompressed, dechunked too. */
 801         if (wrote_response_body) {
 802             text = apr_psprintf(msr->mp, "Response-Body-Transformed: Dechunked\n");
 803             sec_auditlog_write(msr, text, strlen(text));
 804         }
 805
 806         sec_auditlog_write_producer_header(msr);
 807
 808         /* Server */
 809         if (msr->server_software != NULL) {
 810             text = apr_psprintf(msr->mp, "Server: %s\n", msr->server_software);
 811             sec_auditlog_write(msr, text, strlen(text));
 812         }
 813
 814         /* Sanitised arguments */
 815         {
 816             const apr_array_header_t *tarr;
 817             const apr_table_entry_t *telts;
 818
 819             tarr = apr_table_elts(msr->arguments_to_sanitise);
 820             telts = (const apr_table_entry_t*)tarr->elts;
 821
 822             if (tarr->nelts > 0) {
 823                 text = apr_psprintf(msr->mp, "Sanitised-Args: ");
 824                 sec_auditlog_write(msr, text, strlen(text));
 825             }
 826
 827             for(i = 0; i < tarr->nelts; i++) {
 828                 msc_arg *arg = (msc_arg *)telts[i].val;
 829                 text = apr_psprintf(msr->mp, "%s\"%s\"%s", ((i == 0) ? "" : ", "),
 830                     log_escape(msr->mp, arg->name), ((i == (tarr->nelts - 1)) ? ".\n" : ""));
 831                 sec_auditlog_write(msr, text, strlen(text));
 832             }
 833         }
 834
 835         /* Sanitised request headers */
 836         {
 837             const apr_array_header_t *tarr;
 838             const apr_table_entry_t *telts;
 839
 840             tarr = apr_table_elts(msr->request_headers_to_sanitise);
 841             telts = (const apr_table_entry_t*)tarr->elts;
 842
 843             if (tarr->nelts > 0) {
 844                 text = apr_psprintf(msr->mp, "Sanitised-Request-Headers: ");
 845                 sec_auditlog_write(msr, text, strlen(text));
 846             }
 847
 848             for(i = 0; i < tarr->nelts; i++) {
 849                 text = apr_psprintf(msr->mp, "%s\"%s\"%s", ((i == 0) ? "" : ", "),
 850                     log_escape(msr->mp, telts[i].key), ((i == (tarr->nelts - 1)) ? ".\n" : ""));
 851                 sec_auditlog_write(msr, text, strlen(text));
 852             }
 853         }
 854
 855         /* Sanitised response headers */
 856         {
 857             const apr_array_header_t *tarr;
 858             const apr_table_entry_t *telts;
 859
 860             tarr = apr_table_elts(msr->response_headers_to_sanitise);
 861             telts = (const apr_table_entry_t*)tarr->elts;
 862
 863             if (tarr->nelts > 0) {
 864                 text = apr_psprintf(msr->mp, "Sanitised-Response-Headers: ");
 865                 sec_auditlog_write(msr, text, strlen(text));
 866             }
 867
 868             for(i = 0; i < tarr->nelts; i++) {
 869                 text = apr_psprintf(msr->mp, "%s\"%s\"%s", ((i == 0) ? "" : ", "),
 870                     log_escape(msr->mp, telts[i].key), ((i == (tarr->nelts - 1)) ? ".\n" : ""));
 871                 sec_auditlog_write(msr, text, strlen(text));
 872             }
 873         }
 874
 875         /* Web application info. */
 876         if ( ((msr->txcfg->webappid != NULL)&&(strcmp(msr->txcfg->webappid, "default") != 0))
 877             || (msr->sessionid != NULL) || (msr->userid != NULL))
 878         {
 879             text = apr_psprintf(msr->mp, "WebApp-Info: \"%s\" \"%s\" \"%s\"\n",
 880                 msr->txcfg->webappid == NULL ? "-" : log_escape(msr->mp, msr->txcfg->webappid),
 881                 msr->sessionid == NULL ? "-" : log_escape(msr->mp, msr->sessionid),
 882                 msr->userid == NULL ? "-" : log_escape(msr->mp, msr->userid));
 883             sec_auditlog_write(msr, text, strlen(text));
 884         }
 885     }
 886
 887     /* AUDITLOG_PART_UPLOADS */
 888     /* ENH: Implement */
 889
 890
 891     /* AUDITLOG_PART_MATCHEDRULES */
 892
 893     if (strchr(msr->txcfg->auditlog_parts, AUDITLOG_PART_MATCHEDRULES) != NULL) {
 894         text = apr_psprintf(msr->mp, "\n--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_MATCHEDRULES);
 895         sec_auditlog_write(msr, text, strlen(text));
 896
 897         /* Matched Rules */
 898         for(i = 0; i < msr->matched_rules->nelts; i++) {
 899             rule = ((msre_rule **)msr->matched_rules->elts)[i];
 900             text = apr_psprintf(msr->mp, "%s\n", rule->unparsed);
 901             sec_auditlog_write(msr, text, strlen(text));
 902         }
 903     }
 904
 905
 906     /* AUDITLOG_PART_ENDMARKER */
 907
 908     text = apr_psprintf(msr->mp, "\n--%s-%c--\n", msr->new_auditlog_boundary, AUDITLOG_PART_ENDMARKER);
 909     sec_auditlog_write(msr, text, strlen(text));
 910
 911     /* Return here if we were writing to a serial log
 912      * as it does not need an index file.
 913      */
 914     if (msr->txcfg->auditlog_type != AUDITLOG_CONCURRENT) {
 915         sec_auditlog_write(msr, "\n", 1);
 916
 917         /* Unlock the mutex we used to serialise access to the audit log file. */
 918         rc = apr_global_mutex_unlock(msr->modsecurity->auditlog_lock);
 919         if (rc != APR_SUCCESS) {
 920             msr_log(msr, 1, "Audit log: Failed to unlock global mutex: %s",
 921                 get_apr_error(msr->mp, rc));
 922         }
 923
 924         return;
 925     }
 926
 927     /* From here on only concurrent-style processing. */
 928
 929     apr_file_close(msr->new_auditlog_fd);
 930
 931     /* Write an entry to the index file */
 932
 933     /* Calculate hash of the entry. */
 934     apr_md5_final(md5hash, &msr->new_auditlog_md5ctx);
 935
 936     str2 = apr_psprintf(msr->mp, "%s %d %d md5:%s", msr->new_auditlog_filename, 0,
 937         msr->new_auditlog_size, bytes2hex(msr->mp, md5hash, 16));
 938     if (str2 == NULL) return;
 939
 940     /* We do not want the index line to be longer than 3980 bytes. */
 941     limit = 3980;
 942     was_limited = 0;
 943
 944     /* If we are logging to a pipe we need to observe and
 945      * obey the pipe atomic write limit - PIPE_BUF. For
 946      * more details see the discussion in sec_guardian_logger code.
 947      */
 948     if (msr->txcfg->auditlog_name[0] == '|') {
 949         if (PIPE_BUF < limit) {
 950             limit = PIPE_BUF;
 951         }
 952     }
 953
 954     limit = limit - strlen(str2) - 5;
 955     if (limit <= 0) {
 956         msr_log(msr, 1, "Audit Log: Atomic PIPE write buffer too small: %d", PIPE_BUF);
 957         return;
 958     }
 959
 960     str1 = construct_log_vcombinedus_limited(msr, limit, &was_limited);
 961     if (str1 == NULL) return;
 962
 963     if (was_limited == 0) {
 964         text = apr_psprintf(msr->mp, "%s %s \n", str1, str2);
 965     } else {
 966         text = apr_psprintf(msr->mp, "%s %s L\n", str1, str2);
 967     }
 968     if (text == NULL) return;
 969
 970     nbytes = strlen(text);
 971     if (msr->txcfg->debuglog_level >= 9) {
 972         msr_log(msr, 9, "Audit Log: Writing %" APR_SIZE_T_FMT " bytes to primary concurrent index", nbytes);
 973     }
 974     apr_file_write_full(msr->txcfg->auditlog_fd, text, nbytes, &nbytes_written);
 975
 976     /* Write to the secondary audit log if we have one */
 977     if (msr->txcfg->auditlog2_fd != NULL) {
 978         if (msr->txcfg->debuglog_level >= 9) {
 979             msr_log(msr, 9, "Audit Log: Writing %" APR_SIZE_T_FMT " bytes to secondary concurrent index", nbytes);
 980         }
 981         apr_file_write_full(msr->txcfg->auditlog2_fd, text, nbytes, &nbytes_written);
 982     }
 983 }