--- httpd-2.4.16/modules/debugging/mod_dumpio.c.orig 2015-09-25 18:39:05.000000000 -0700 +++ httpd-2.4.16/modules/debugging/mod_dumpio.c 2015-10-04 18:38:42.000000000 -0700 @@ -16,17 +16,20 @@ /* * Originally written @ Covalent by Jim Jagielski + * + * Modified in October 2015 by Kurtis Rader (krader@skepticism.us) to correctly + * handle null (zero) bytes so they appear in the logged output. Fixing PR57045: + * https://bz.apache.org/bugzilla/show_bug.cgi?id=57045 */ /* * mod_dumpio.c: - * Think of this as a filter sniffer for Apache 2.x. It logs - * all filter data right before and after it goes out on the - * wire (BUT right before SSL encoded or after SSL decoded). - * It can produce a *huge* amount of data. + * Think of this as a filter sniffer for Apache 2.x. It logs all filter data + * right before and after it goes out on the wire (BUT right before SSL + * encoded or after SSL decoded). It can produce a *huge* amount of data in + * the error log. */ - #include "httpd.h" #include "http_connection.h" #include "http_config.h" @@ -41,79 +44,136 @@ int enable_output; } dumpio_conf_t; -/* consider up to 80 additional characters, and factor the longest - * line length of all \xNN sequences; log_error cannot record more - * than MAX_STRING_LEN characters. - */ -#define dumpio_MAX_STRING_LEN (MAX_STRING_LEN / 4 - 80) +// Function ap_log_cerror cannot record more than MAX_STRING_LEN characters. +// Excluding the IP address and port number the message prefix is ~130 chars +// long. The longest IPv6 address:port pair is 46 chars (IPv4 is 21 chars). We +// want to provide a margin of safety. So add a fudge factor of 100 characters +// to help ensure we don't attempt to log more data than can be written in case +// the length of the message prefix is longer than we expect. Note that we take +// into account which bytes are printable and those that might be expanded to a +// hex encoded sequence (\xNN) when determining if we've exceeded the following +// limit. +#define DUMPIO_MAX_DATA_LEN (MAX_STRING_LEN - 130 - 46 - 100) + +// The dumpbuf* functions are the workhorses of this module. Log the data in the +// bucket to the current error_log. The following three vars are private to the +// dumpbuf* functions. +// +// The encoded_buf is needed to correctly handle null (i.e., zero) bytes in the +// data we want to log. It allows us to encode 0x00 and 0xff bytes into +// sequences of 0xff 0x01 (\xff\x01) and 0xff 0x02 (\xff\x02) respectively. +// This is necessary because the logging functions stop processing data (i.e., +// logging it) when a zero byte is seen because they only handle null +// terminated strings. +static unsigned char encoded_buf[DUMPIO_MAX_DATA_LEN]; +static int space_left; +static int encoded_idx; + +static void dumpbuf_init() { + // Initialize the data structures to begin logging data we receive. + space_left = DUMPIO_MAX_DATA_LEN; + encoded_idx = 0; +} -/* - * Workhorse function: simply log to the current error_log - * info about the data in the bucket as well as the data itself - */ -static void dumpit(ap_filter_t *f, apr_bucket *b, dumpio_conf_t *ptr) +static void dumpbuf_end(const ap_filter_t *f, const char *bucket_type) { - conn_rec *c = f->c; + // Log any data we've buffered since the most recent call to dumpbuf. + if (encoded_idx) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c, + "mod_dumpio: %s (%s-%s): %.*s", f->frec->name, + "data", bucket_type, encoded_idx, encoded_buf); + } +} - ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c, - "mod_dumpio: %s (%s-%s): %" APR_SIZE_T_FMT " bytes", - f->frec->name, - (APR_BUCKET_IS_METADATA(b)) ? "metadata" : "data", - b->type->name, - b->length) ; - - if (!(APR_BUCKET_IS_METADATA(b))) - { -#if APR_CHARSET_EBCDIC - char xlatebuf[dumpio_MAX_STRING_LEN + 1]; -#endif - const char *buf; - apr_size_t nbytes; - apr_status_t rv = apr_bucket_read(b, &buf, &nbytes, APR_BLOCK_READ); - - if (rv == APR_SUCCESS) - { - while (nbytes) - { - apr_size_t logbytes = nbytes; - if (logbytes > dumpio_MAX_STRING_LEN) - logbytes = dumpio_MAX_STRING_LEN; - nbytes -= logbytes; - -#if APR_CHARSET_EBCDIC - memcpy(xlatebuf, buf, logbytes); - ap_xlate_proto_from_ascii(xlatebuf, logbytes); - xlatebuf[logbytes] = '\0'; - ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c, - "mod_dumpio: %s (%s-%s): %s", f->frec->name, - (APR_BUCKET_IS_METADATA(b)) ? "metadata" : "data", - b->type->name, xlatebuf); -#else - /* XXX: Seriously flawed; we do not pay attention to embedded - * \0's in the request body, these should be escaped; however, - * the logging function already performs a significant amount - * of escaping, and so any escaping would be double-escaped. - * The coding solution is to throw away the current logic - * within ap_log_error, and introduce new vformatter %-escapes - * for escaping text, and for binary text (fixed len strings). - */ - ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c, - "mod_dumpio: %s (%s-%s): %.*s", f->frec->name, - (APR_BUCKET_IS_METADATA(b)) ? "metadata" : "data", - b->type->name, (int)logbytes, buf); -#endif - buf += logbytes; - } +static void dumpbuf(ap_filter_t *f, const char *bucket_type, + unsigned char *input_buf, apr_size_t nbytes) +{ + for (unsigned char *c = input_buf; c < input_buf + nbytes; ++c) { + if (space_left < 8) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c, + "mod_dumpio: %s (%s-%s): %.*s", f->frec->name, + "data", bucket_type, encoded_idx, encoded_buf); + dumpbuf_init(); + } + + // We could use isprint() but we don't need the baggage. + if (*c >= 0x20 && *c <= 0x7e) { // this range needs one char in the log + encoded_buf[encoded_idx++] = *c; + space_left -= 1; + } + else if (*c == 0) { + encoded_buf[encoded_idx++] = 0xff; + encoded_buf[encoded_idx++] = 0x01; + space_left -= 8; + } + else if (*c == 0xff) { + encoded_buf[encoded_idx++] = 0xff; + encoded_buf[encoded_idx++] = 0x02; + space_left -= 8; } else { - ap_log_cerror(APLOG_MARK, APLOG_TRACE7, rv, c, - "mod_dumpio: %s (%s-%s): %s", f->frec->name, - (APR_BUCKET_IS_METADATA(b)) ? "metadata" : "data", - b->type->name, "error reading data"); + // It isn't worth it to special-case the few control chars, such + // as \t, that get encoded into two characters. Assume they all + // get encoded into a \xNN four char sequence. + encoded_buf[encoded_idx++] = *c; + space_left -= 4; } } } +// Log info about the data in the bucket as well as the data itself to the +// current error_log. +static void dumpit(ap_filter_t *f, apr_bucket *b, dumpio_conf_t *ptr) +{ + int is_metadata = APR_BUCKET_IS_METADATA(b); + + // I've commented this out because in the normal course of events it + // doesn't tell us anything we need to know and takes measurable time to + // execute and wastes space in the log file. In my testing just adding this + // log message increases the log file size by 2%. Uncomment it if you're + // trying to debug something wrong with this module. + // + // ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c, + // "mod_dumpio: %s (%s-%s): %" APR_SIZE_T_FMT " bytes", + // f->frec->name, is_metadata ? "metadata" : "data", + // b->type->name, b->length); + if (is_metadata) { + return; + } + + apr_size_t nbytes; + unsigned char *input_buf; + apr_status_t rv = apr_bucket_read(b, (const char **)&input_buf, &nbytes, + APR_BLOCK_READ); + if (rv != APR_SUCCESS) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE7, rv, f->c, + "mod_dumpio: %s (%s-%s): %s", f->frec->name, + "data", b->type->name, "error reading data"); + return; + } + +#if !APR_CHARSET_EBCDIC + dumpbuf(f, b->type->name, input_buf, nbytes); // the common case: ASCII charset +#else + // This obviously screws up any binary data in the buffer such as a zip + // archive in a POST request. But people running on an IBM mainframe + // probably don't care since the original data is almost certainly unusable + // in their environment. It's better that we make the incoming and ougoing + // ASCII text easily readable in the error log on systems using EBCDIC. + unsigned char xlatebuf[MAX_STRING_LEN]; + while (nbytes) { + apr_size_t logbytes = nbytes; + if (logbytes > MAX_STRING_LEN) { + logbytes = MAX_STRING_LEN; + } + memcpy(xlatebuf, input_buf, logbytes); + ap_xlate_proto_from_ascii(xlatebuf, logbytes); + dumpbuf(f, b->type->name, xlatebuf, logbytes); + nbytes -= logbytes + } +#endif +} + #define whichmode( mode ) \ ( (( mode ) == AP_MODE_READBYTES) ? "readbytes" : \ (( mode ) == AP_MODE_GETLINE) ? "getline" : \ @@ -126,28 +186,29 @@ static int dumpio_input_filter (ap_filter_t *f, apr_bucket_brigade *bb, ap_input_mode_t mode, apr_read_type_e block, apr_off_t readbytes) { - apr_bucket *b; apr_status_t ret; - conn_rec *c = f->c; dumpio_conf_t *ptr = f->ctx; - ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c, "mod_dumpio: %s [%s-%s] %" APR_OFF_T_FMT " readbytes", - f->frec->name, - whichmode(mode), + f->frec->name, whichmode(mode), ((block) == APR_BLOCK_READ) ? "blocking" : "nonblocking", readbytes); ret = ap_get_brigade(f->next, bb, mode, block, readbytes); if (ret == APR_SUCCESS) { - for (b = APR_BRIGADE_FIRST(bb); b != APR_BRIGADE_SENTINEL(bb); b = APR_BUCKET_NEXT(b)) { - dumpit(f, b, ptr); + dumpbuf_init(); + apr_bucket *first_b = APR_BRIGADE_FIRST(bb); + apr_bucket *sentinel_b = APR_BRIGADE_SENTINEL(bb); + for (b = first_b; b != sentinel_b; b = APR_BUCKET_NEXT(b)) { + dumpit(f, b, ptr); } + dumpbuf_end(f, first_b->type->name); } else { - ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c, "mod_dumpio: %s - %d", f->frec->name, ret) ; return ret; } @@ -158,51 +219,51 @@ static int dumpio_output_filter (ap_filter_t *f, apr_bucket_brigade *bb) { apr_bucket *b; - conn_rec *c = f->c; dumpio_conf_t *ptr = f->ctx; - ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c, "mod_dumpio: %s", f->frec->name); + ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c, "mod_dumpio: %s", f->frec->name); - for (b = APR_BRIGADE_FIRST(bb); b != APR_BRIGADE_SENTINEL(bb); b = APR_BUCKET_NEXT(b)) { - /* - * If we ever see an EOS, make sure to FLUSH. - */ - if (APR_BUCKET_IS_EOS(b)) { + dumpbuf_init(); + apr_bucket *first_b = APR_BRIGADE_FIRST(bb); + apr_bucket *sentinel_b = APR_BRIGADE_SENTINEL(bb); + for (b = first_b; b != sentinel_b; b = APR_BUCKET_NEXT(b)) { + if (APR_BUCKET_IS_EOS(b)) { // if we ever see an EOS, make sure to FLUSH apr_bucket *flush = apr_bucket_flush_create(f->c->bucket_alloc); APR_BUCKET_INSERT_BEFORE(b, flush); } dumpit(f, b, ptr); } + dumpbuf_end(f, first_b->type->name); return ap_pass_brigade(f->next, bb) ; } static int dumpio_pre_conn(conn_rec *c, void *csd) { - dumpio_conf_t *ptr; - - ptr = (dumpio_conf_t *) ap_get_module_config(c->base_server->module_config, - &dumpio_module); + dumpio_conf_t *ptr = (dumpio_conf_t *)ap_get_module_config( + c->base_server->module_config, &dumpio_module); if (ptr->enable_input) ap_add_input_filter("DUMPIO_IN", ptr, NULL, c); if (ptr->enable_output) ap_add_output_filter("DUMPIO_OUT", ptr, NULL, c); + return OK; } static void dumpio_register_hooks(apr_pool_t *p) { -/* - * We know that SSL is CONNECTION + 5 - */ - ap_register_output_filter("DUMPIO_OUT", dumpio_output_filter, - NULL, AP_FTYPE_CONNECTION + 3) ; - - ap_register_input_filter("DUMPIO_IN", dumpio_input_filter, - NULL, AP_FTYPE_CONNECTION + 3) ; + // We know that the SSL code inserts itself at AP_FTYPE_CONNECTION + 5 and + // AP_FTYPE_CONNECTION + 4 (see the ssl_io_filter_register() function in + // modules/ssl/ssl_engine_io.c). We want to be inserted just ahead of that + // module so we use "+ 3" to ensure we're called just before the SSL filter + // but hopefully after anything else that might alter the data. + ap_register_output_filter("DUMPIO_OUT", dumpio_output_filter, + NULL, AP_FTYPE_CONNECTION + 3); + ap_register_input_filter("DUMPIO_IN", dumpio_input_filter, + NULL, AP_FTYPE_CONNECTION + 3); - ap_hook_pre_connection(dumpio_pre_conn, NULL, NULL, APR_HOOK_MIDDLE); + ap_hook_pre_connection(dumpio_pre_conn, NULL, NULL, APR_HOOK_MIDDLE); } static void *dumpio_create_sconfig(apr_pool_t *p, server_rec *s) @@ -241,10 +302,10 @@ AP_DECLARE_MODULE(dumpio) = { STANDARD20_MODULE_STUFF, - NULL, /* create per-dir config structures */ - NULL, /* merge per-dir config structures */ - dumpio_create_sconfig, /* create per-server config structures */ - NULL, /* merge per-server config structures */ - dumpio_cmds, /* table of config file commands */ - dumpio_register_hooks /* register hooks */ + NULL, // create per-dir config structures + NULL, // merge per-dir config structures + dumpio_create_sconfig, // create per-server config structures + NULL, // merge per-server config structures + dumpio_cmds, // table of config file commands + dumpio_register_hooks // register hooks };