View | Details | Raw Unified | Return to bug 57045
Collapse All | Expand All

(-)httpd-2.4.16/modules/debugging/mod_dumpio.c.orig (-103 / +164 lines)
Lines 16-32 Link Here
16
16
17
/*
17
/*
18
 * Originally written @ Covalent by Jim Jagielski
18
 * Originally written @ Covalent by Jim Jagielski
19
 *
20
 * Modified in October 2015 by Kurtis Rader (krader@skepticism.us) to correctly
21
 * handle null (zero) bytes so they appear in the logged output. Fixing PR57045:
22
 * https://bz.apache.org/bugzilla/show_bug.cgi?id=57045
19
 */
23
 */
20
24
21
/*
25
/*
22
 * mod_dumpio.c:
26
 * mod_dumpio.c:
23
 *  Think of this as a filter sniffer for Apache 2.x. It logs
27
 *  Think of this as a filter sniffer for Apache 2.x. It logs all filter data
24
 *  all filter data right before and after it goes out on the
28
 *  right before and after it goes out on the wire (BUT right before SSL
25
 *  wire (BUT right before SSL encoded or after SSL decoded).
29
 *  encoded or after SSL decoded). It can produce a *huge* amount of data in
26
 *  It can produce a *huge* amount of data.
30
 *  the error log.
27
 */
31
 */
28
32
29
30
#include "httpd.h"
33
#include "httpd.h"
31
#include "http_connection.h"
34
#include "http_connection.h"
32
#include "http_config.h"
35
#include "http_config.h"
Lines 41-119 Link Here
41
    int enable_output;
44
    int enable_output;
42
} dumpio_conf_t;
45
} dumpio_conf_t;
43
46
44
/* consider up to 80 additional characters, and factor the longest
47
// Function ap_log_cerror cannot record more than MAX_STRING_LEN characters.
45
 * line length of all \xNN sequences; log_error cannot record more
48
// Excluding the IP address and port number the message prefix is ~130 chars
46
 * than MAX_STRING_LEN characters.
49
// long. The longest IPv6 address:port pair is 46 chars (IPv4 is 21 chars). We
47
 */
50
// want to provide a margin of safety. So add a fudge factor of 100 characters
48
#define dumpio_MAX_STRING_LEN (MAX_STRING_LEN / 4 - 80)
51
// to help ensure we don't attempt to log more data than can be written in case
52
// the length of the message prefix is longer than we expect. Note that we take
53
// into account which bytes are printable and those that might be expanded to a
54
// hex encoded sequence (\xNN) when determining if we've exceeded the following
55
// limit.
56
#define DUMPIO_MAX_DATA_LEN (MAX_STRING_LEN - 130 - 46 - 100)
57
58
// The dumpbuf* functions are the workhorses of this module. Log the data in the
59
// bucket to the current error_log. The following three vars are private to the
60
// dumpbuf* functions.
61
//
62
// The encoded_buf is needed to correctly handle null (i.e., zero) bytes in the
63
// data we want to log. It allows us to encode 0x00 and 0xff bytes into
64
// sequences of 0xff 0x01 (\xff\x01) and 0xff 0x02 (\xff\x02) respectively.
65
// This is necessary because the logging functions stop processing data (i.e.,
66
// logging it) when a zero byte is seen because they only handle null
67
// terminated strings.
68
static unsigned char encoded_buf[DUMPIO_MAX_DATA_LEN];
69
static int space_left;
70
static int encoded_idx;
71
72
static void dumpbuf_init() {
73
    // Initialize the data structures to begin logging data we receive.
74
    space_left = DUMPIO_MAX_DATA_LEN;
75
    encoded_idx = 0;
76
}
49
77
50
/*
78
static void dumpbuf_end(const ap_filter_t *f, const char *bucket_type)
51
 * Workhorse function: simply log to the current error_log
52
 * info about the data in the bucket as well as the data itself
53
 */
54
static void dumpit(ap_filter_t *f, apr_bucket *b, dumpio_conf_t *ptr)
55
{
79
{
56
    conn_rec *c = f->c;
80
    // Log any data we've buffered since the most recent call to dumpbuf.
81
    if (encoded_idx) {
82
        ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c,
83
                "mod_dumpio:  %s (%s-%s): %.*s", f->frec->name,
84
                "data", bucket_type, encoded_idx, encoded_buf);
85
    }
86
}
57
87
58
    ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c,
88
static void dumpbuf(ap_filter_t *f, const char *bucket_type,
59
                  "mod_dumpio:  %s (%s-%s): %" APR_SIZE_T_FMT " bytes",
89
        unsigned char *input_buf, apr_size_t nbytes)
60
                  f->frec->name,
90
{
61
                  (APR_BUCKET_IS_METADATA(b)) ? "metadata" : "data",
91
    for (unsigned char *c = input_buf; c < input_buf + nbytes; ++c) {
62
                  b->type->name,
92
        if (space_left < 8) {
63
                  b->length) ;
93
            ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c,
64
94
                    "mod_dumpio:  %s (%s-%s): %.*s", f->frec->name,
65
    if (!(APR_BUCKET_IS_METADATA(b)))
95
                    "data", bucket_type, encoded_idx, encoded_buf);
66
    {
96
            dumpbuf_init();
67
#if APR_CHARSET_EBCDIC
97
        }
68
        char xlatebuf[dumpio_MAX_STRING_LEN + 1];
98
69
#endif
99
        // We could use isprint() but we don't need the baggage.
70
        const char *buf;
100
        if (*c >= 0x20 && *c <= 0x7e) { // this range needs one char in the log
71
        apr_size_t nbytes;
101
            encoded_buf[encoded_idx++] = *c;
72
        apr_status_t rv = apr_bucket_read(b, &buf, &nbytes, APR_BLOCK_READ);
102
            space_left -= 1;
73
103
        }
74
        if (rv == APR_SUCCESS)
104
        else if (*c == 0) {
75
        {
105
            encoded_buf[encoded_idx++] = 0xff;
76
            while (nbytes)
106
            encoded_buf[encoded_idx++] = 0x01;
77
            {
107
            space_left -= 8;
78
                apr_size_t logbytes = nbytes;
108
        }
79
                if (logbytes > dumpio_MAX_STRING_LEN)
109
        else if (*c == 0xff) {
80
                    logbytes = dumpio_MAX_STRING_LEN;
110
            encoded_buf[encoded_idx++] = 0xff;
81
                nbytes -= logbytes;
111
            encoded_buf[encoded_idx++] = 0x02;
82
112
            space_left -= 8;
83
#if APR_CHARSET_EBCDIC
84
                memcpy(xlatebuf, buf, logbytes);
85
                ap_xlate_proto_from_ascii(xlatebuf, logbytes);
86
                xlatebuf[logbytes] = '\0';
87
                ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c,
88
                              "mod_dumpio:  %s (%s-%s): %s", f->frec->name,
89
                              (APR_BUCKET_IS_METADATA(b)) ? "metadata" : "data",
90
                              b->type->name, xlatebuf);
91
#else
92
                /* XXX: Seriously flawed; we do not pay attention to embedded
93
                 * \0's in the request body, these should be escaped; however,
94
                 * the logging function already performs a significant amount
95
                 * of escaping, and so any escaping would be double-escaped.
96
                 * The coding solution is to throw away the current logic
97
                 * within ap_log_error, and introduce new vformatter %-escapes
98
                 * for escaping text, and for binary text (fixed len strings).
99
                 */
100
                ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c,
101
                              "mod_dumpio:  %s (%s-%s): %.*s", f->frec->name,
102
                              (APR_BUCKET_IS_METADATA(b)) ? "metadata" : "data",
103
                              b->type->name, (int)logbytes, buf);
104
#endif
105
                buf += logbytes;
106
            }
107
        }
113
        }
108
        else {
114
        else {
109
            ap_log_cerror(APLOG_MARK, APLOG_TRACE7, rv, c,
115
            // It isn't worth it to special-case the few control chars, such
110
                          "mod_dumpio:  %s (%s-%s): %s", f->frec->name,
116
            // as \t, that get encoded into two characters. Assume they all
111
                          (APR_BUCKET_IS_METADATA(b)) ? "metadata" : "data",
117
            // get encoded into a \xNN four char sequence.
112
                          b->type->name, "error reading data");
118
            encoded_buf[encoded_idx++] = *c;
119
            space_left -= 4;
113
        }
120
        }
114
    }
121
    }
115
}
122
}
116
123
124
// Log info about the data in the bucket as well as the data itself to the
125
// current error_log.
126
static void dumpit(ap_filter_t *f, apr_bucket *b, dumpio_conf_t *ptr)
127
{
128
    int is_metadata = APR_BUCKET_IS_METADATA(b);
129
130
    // I've commented this out because in the normal course of events it
131
    // doesn't tell us anything we need to know and takes measurable time to
132
    // execute and wastes space in the log file. In my testing just adding this
133
    // log message increases the log file size by 2%. Uncomment it if you're
134
    // trying to debug something wrong with this module.
135
    //
136
    // ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c,
137
    //               "mod_dumpio:  %s (%s-%s): %" APR_SIZE_T_FMT " bytes",
138
    //               f->frec->name, is_metadata ? "metadata" : "data",
139
    //               b->type->name, b->length);
140
    if (is_metadata) {
141
        return;
142
    }
143
144
    apr_size_t nbytes;
145
    unsigned char *input_buf;
146
    apr_status_t rv = apr_bucket_read(b, (const char **)&input_buf, &nbytes,
147
        APR_BLOCK_READ);
148
    if (rv != APR_SUCCESS) {
149
        ap_log_cerror(APLOG_MARK, APLOG_TRACE7, rv, f->c,
150
                      "mod_dumpio:  %s (%s-%s): %s", f->frec->name,
151
                      "data", b->type->name, "error reading data");
152
        return;
153
    }
154
155
#if !APR_CHARSET_EBCDIC
156
    dumpbuf(f, b->type->name, input_buf, nbytes);  // the common case: ASCII charset
157
#else
158
    // This obviously screws up any binary data in the buffer such as a zip
159
    // archive in a POST request. But people running on an IBM mainframe
160
    // probably don't care since the original data is almost certainly unusable
161
    // in their environment. It's better that we make the incoming and ougoing
162
    // ASCII text easily readable in the error log on systems using EBCDIC.
163
    unsigned char xlatebuf[MAX_STRING_LEN];
164
    while (nbytes) {
165
        apr_size_t logbytes = nbytes;
166
        if (logbytes > MAX_STRING_LEN) {
167
            logbytes = MAX_STRING_LEN;
168
        }
169
        memcpy(xlatebuf, input_buf, logbytes);
170
        ap_xlate_proto_from_ascii(xlatebuf, logbytes);
171
        dumpbuf(f, b->type->name, xlatebuf, logbytes);
172
        nbytes -= logbytes
173
    }
174
#endif
175
}
176
117
#define whichmode( mode ) \
177
#define whichmode( mode ) \
118
 ( (( mode ) == AP_MODE_READBYTES) ? "readbytes" : \
178
 ( (( mode ) == AP_MODE_READBYTES) ? "readbytes" : \
119
   (( mode ) == AP_MODE_GETLINE) ? "getline" : \
179
   (( mode ) == AP_MODE_GETLINE) ? "getline" : \
Lines 126-153 Link Here
126
static int dumpio_input_filter (ap_filter_t *f, apr_bucket_brigade *bb,
186
static int dumpio_input_filter (ap_filter_t *f, apr_bucket_brigade *bb,
127
    ap_input_mode_t mode, apr_read_type_e block, apr_off_t readbytes)
187
    ap_input_mode_t mode, apr_read_type_e block, apr_off_t readbytes)
128
{
188
{
129
130
    apr_bucket *b;
189
    apr_bucket *b;
131
    apr_status_t ret;
190
    apr_status_t ret;
132
    conn_rec *c = f->c;
133
    dumpio_conf_t *ptr = f->ctx;
191
    dumpio_conf_t *ptr = f->ctx;
134
192
135
    ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c,
193
    ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c,
136
                  "mod_dumpio: %s [%s-%s] %" APR_OFF_T_FMT " readbytes",
194
                  "mod_dumpio: %s [%s-%s] %" APR_OFF_T_FMT " readbytes",
137
                  f->frec->name,
195
                  f->frec->name, whichmode(mode),
138
                  whichmode(mode),
139
                  ((block) == APR_BLOCK_READ) ? "blocking" : "nonblocking",
196
                  ((block) == APR_BLOCK_READ) ? "blocking" : "nonblocking",
140
                  readbytes);
197
                  readbytes);
141
198
142
    ret = ap_get_brigade(f->next, bb, mode, block, readbytes);
199
    ret = ap_get_brigade(f->next, bb, mode, block, readbytes);
143
200
144
    if (ret == APR_SUCCESS) {
201
    if (ret == APR_SUCCESS) {
145
        for (b = APR_BRIGADE_FIRST(bb); b != APR_BRIGADE_SENTINEL(bb); b = APR_BUCKET_NEXT(b)) {
202
        dumpbuf_init();
146
          dumpit(f, b, ptr);
203
        apr_bucket *first_b = APR_BRIGADE_FIRST(bb);
204
        apr_bucket *sentinel_b = APR_BRIGADE_SENTINEL(bb);
205
        for (b = first_b; b != sentinel_b; b = APR_BUCKET_NEXT(b)) {
206
            dumpit(f, b, ptr);
147
        }
207
        }
208
        dumpbuf_end(f, first_b->type->name);
148
    }
209
    }
149
    else {
210
    else {
150
        ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c,
211
        ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c,
151
                      "mod_dumpio: %s - %d", f->frec->name, ret) ;
212
                      "mod_dumpio: %s - %d", f->frec->name, ret) ;
152
        return ret;
213
        return ret;
153
    }
214
    }
Lines 158-208 Link Here
158
static int dumpio_output_filter (ap_filter_t *f, apr_bucket_brigade *bb)
219
static int dumpio_output_filter (ap_filter_t *f, apr_bucket_brigade *bb)
159
{
220
{
160
    apr_bucket *b;
221
    apr_bucket *b;
161
    conn_rec *c = f->c;
162
    dumpio_conf_t *ptr = f->ctx;
222
    dumpio_conf_t *ptr = f->ctx;
163
223
164
    ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, c, "mod_dumpio: %s", f->frec->name);
224
    ap_log_cerror(APLOG_MARK, APLOG_TRACE7, 0, f->c, "mod_dumpio: %s", f->frec->name);
165
225
166
    for (b = APR_BRIGADE_FIRST(bb); b != APR_BRIGADE_SENTINEL(bb); b = APR_BUCKET_NEXT(b)) {
226
    dumpbuf_init();
167
        /*
227
    apr_bucket *first_b = APR_BRIGADE_FIRST(bb);
168
         * If we ever see an EOS, make sure to FLUSH.
228
    apr_bucket *sentinel_b = APR_BRIGADE_SENTINEL(bb);
169
         */
229
    for (b = first_b; b != sentinel_b; b = APR_BUCKET_NEXT(b)) {
170
        if (APR_BUCKET_IS_EOS(b)) {
230
        if (APR_BUCKET_IS_EOS(b)) { // if we ever see an EOS, make sure to FLUSH
171
            apr_bucket *flush = apr_bucket_flush_create(f->c->bucket_alloc);
231
            apr_bucket *flush = apr_bucket_flush_create(f->c->bucket_alloc);
172
            APR_BUCKET_INSERT_BEFORE(b, flush);
232
            APR_BUCKET_INSERT_BEFORE(b, flush);
173
        }
233
        }
174
        dumpit(f, b, ptr);
234
        dumpit(f, b, ptr);
175
    }
235
    }
236
    dumpbuf_end(f, first_b->type->name);
176
237
177
    return ap_pass_brigade(f->next, bb) ;
238
    return ap_pass_brigade(f->next, bb) ;
178
}
239
}
179
240
180
static int dumpio_pre_conn(conn_rec *c, void *csd)
241
static int dumpio_pre_conn(conn_rec *c, void *csd)
181
{
242
{
182
    dumpio_conf_t *ptr;
243
    dumpio_conf_t *ptr = (dumpio_conf_t *)ap_get_module_config(
183
244
            c->base_server->module_config, &dumpio_module);
184
    ptr = (dumpio_conf_t *) ap_get_module_config(c->base_server->module_config,
185
                                                 &dumpio_module);
186
245
187
    if (ptr->enable_input)
246
    if (ptr->enable_input)
188
        ap_add_input_filter("DUMPIO_IN", ptr, NULL, c);
247
        ap_add_input_filter("DUMPIO_IN", ptr, NULL, c);
189
    if (ptr->enable_output)
248
    if (ptr->enable_output)
190
        ap_add_output_filter("DUMPIO_OUT", ptr, NULL, c);
249
        ap_add_output_filter("DUMPIO_OUT", ptr, NULL, c);
250
191
    return OK;
251
    return OK;
192
}
252
}
193
253
194
static void dumpio_register_hooks(apr_pool_t *p)
254
static void dumpio_register_hooks(apr_pool_t *p)
195
{
255
{
196
/*
256
    // We know that the SSL code inserts itself at AP_FTYPE_CONNECTION + 5 and
197
 * We know that SSL is CONNECTION + 5
257
    // AP_FTYPE_CONNECTION + 4 (see the ssl_io_filter_register() function in
198
 */
258
    // modules/ssl/ssl_engine_io.c). We want to be inserted just ahead of that
199
  ap_register_output_filter("DUMPIO_OUT", dumpio_output_filter,
259
    // module so we use "+ 3" to ensure we're called just before the SSL filter
200
        NULL, AP_FTYPE_CONNECTION + 3) ;
260
    // but hopefully after anything else that might alter the data.
201
261
    ap_register_output_filter("DUMPIO_OUT", dumpio_output_filter,
202
  ap_register_input_filter("DUMPIO_IN", dumpio_input_filter,
262
        NULL, AP_FTYPE_CONNECTION + 3);
203
        NULL, AP_FTYPE_CONNECTION + 3) ;
263
    ap_register_input_filter("DUMPIO_IN", dumpio_input_filter,
264
        NULL, AP_FTYPE_CONNECTION + 3);
204
265
205
  ap_hook_pre_connection(dumpio_pre_conn, NULL, NULL, APR_HOOK_MIDDLE);
266
    ap_hook_pre_connection(dumpio_pre_conn, NULL, NULL, APR_HOOK_MIDDLE);
206
}
267
}
207
268
208
static void *dumpio_create_sconfig(apr_pool_t *p, server_rec *s)
269
static void *dumpio_create_sconfig(apr_pool_t *p, server_rec *s)
Lines 241-250 Link Here
241
302
242
AP_DECLARE_MODULE(dumpio) = {
303
AP_DECLARE_MODULE(dumpio) = {
243
        STANDARD20_MODULE_STUFF,
304
        STANDARD20_MODULE_STUFF,
244
        NULL,                   /* create per-dir    config structures */
305
        NULL,                   // create per-dir    config structures
245
        NULL,                   /* merge  per-dir    config structures */
306
        NULL,                   // merge  per-dir    config structures
246
        dumpio_create_sconfig,  /* create per-server config structures */
307
        dumpio_create_sconfig,  // create per-server config structures
247
        NULL,                   /* merge  per-server config structures */
308
        NULL,                   // merge  per-server config structures
248
        dumpio_cmds,            /* table of config file commands       */
309
        dumpio_cmds,            // table of config file commands
249
        dumpio_register_hooks   /* register hooks                      */
310
        dumpio_register_hooks   // register hooks
250
};
311
};

Return to bug 57045