Bug 43738 - Who is hiding my buffered POST data from mod_ssl after renegotiation?
Summary: Who is hiding my buffered POST data from mod_ssl after renegotiation?
Status: CLOSED FIXED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_ssl (show other bugs)
Version: 2.2.3
Hardware: All Linux
: P2 major (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
: 46809 (view as bug list)
Depends on:
Blocks:
 
Reported: 2007-10-30 14:57 UTC by Garrett Wollman
Modified: 2009-03-06 02:41 UTC (History)
2 users (show)



Attachments
test fix (638 bytes, patch)
2007-11-01 09:38 UTC, Joe Orton
Details | Diff
working fix (2.27 KB, patch)
2007-11-02 06:33 UTC, Joe Orton
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Garrett Wollman 2007-10-30 14:57:53 UTC
These logs show a connection to a FastCGI server in a directory which requires
SSL renegotiation.  mod_fastcgi uses the deprecated ap_get_client_block() family
 to read POST data from the client, but rewriting it to use the underlying
Apache 2 APIs shows identical results.  I've deleted a few lines that aren't
relevant to this analysis...

[Tue Oct 30 16:41:47 2007] [info] [client 128.30.28.20] Connection to child 9
established (server courses.csail.mit.edu:443)
...
[Tue Oct 30 16:41:47 2007] [debug] ssl_engine_io.c(1478): [client 128.30.28.20]
filling buffer
[Tue Oct 30 16:41:47 2007] [debug] ssl_engine_io.c(1529): [client 128.30.28.20]
total of 525 bytes in buffer, eos=1
...my analysis concentrates here...
[Tue Oct 30 16:42:21 2007] [error] [client 128.30.28.20] FastCGI: comm with
server "/usr/bin/php5-cgi" aborted: idle timeout (30 sec), referer: [URI deleted]
[Tue Oct 30 16:42:21 2007] [debug] ssl_engine_io.c(1561): [client 128.30.28.20]
read from buffered SSL brigade, mode 0, 8192 bytes
[Tue Oct 30 16:42:21 2007] [debug] ssl_engine_io.c(1623): [client 128.30.28.20]
buffered SSL brigade now exhausted; removing filter

The reason for the timeout is that the FastCGI server is waiting to read POST
data from the server which never arrives.  In fact, the server thinks it should
be passing client data, but when ap_get_client_block() attempts to read the
client data, it gets an EOS.  More interestingly, an examination of the
input_filter chain at that point shows "http_in" followed by "ssl/tls filter"; I
believe the second (or maybe the first) filter here should be "ssl/tls buffer"
instead.  (We know from the two previous lines that the POST content has been
successfully buffered.)  The buffer does eventually get read, as the following
log entries show -- but not by mod_fastcgi.  The very last thing that
ssl_io_buffer_fill() does is add the "ssl/tls buffer" filter, so I don't
understand why it doesn't appear at the head of the input filter list when
ap_get_client_block() is running, nor why it does get read (and presumably is in
the filter chain) after the request is aborted.
Comment 1 Joe Orton 2007-10-31 10:02:14 UTC
Curious.  Can you get a dump of the r->input_filters in gdb at the point where
ap_get_client_block() is called in mod_fastcgi?

source /path/to/httpd-source/.gdbinit
dump_filters r->input_filters
Comment 2 Garrett Wollman 2007-10-31 14:40:46 UTC
Here's what GDB thinks
(gdb) b ap_get_client_block
Breakpoint 1 at 0x441f60
(gdb) cont
Continuing.

Breakpoint 1, 0x0000000000441f60 in ap_get_client_block ()
(gdb) up
#1  0x00002b952d63a703 in do_work (r=0x819238, fr=0x84d0c0)
    at mod_fastcgi.c:868
868             if ((countRead = ap_get_client_block(fr->r, end, count)) < 0)
(gdb) source /afs/csail.mit.edu/u/w/wollman/public/apache2/apache2-2.2.3/.gdbinit 
(gdb) dump_filters fr->r->input_filters
http_in(0x826c98): ctx=0x83e990, r=0x819238, c=0x810248
ssl/tls filter(0x81e098): ctx=0x81c048, r=0x0, c=0x810248
log_input_output(0x8109f0): ctx=0x0, r=0x0, c=0x810248
core_in(0x81e140): ctx=0x81e120, r=0x0, c=0x810248
(gdb) p *r
$1 = {pool = 0x825088, connection = 0x810248, server = 0x6d0478, next = 0x0, 
  prev = 0x8250f8, main = 0x0, 
  the_request = 0x8266b0 "POST /16.410/wiki/index.php?title=Special:Preferences
HTTP/1.1", assbackwards = 0, proxyreq = 0, header_only = 0, 
  protocol = 0x8267b0 "HTTP/1.1", proto_num = 1001, 
  hostname = 0x826c78 "more-courses.csail.mit.edu", 
  request_time = 1193866479991696, status_line = 0x0, status = 200, 
  method = 0x826700 "POST", method_number = 2, allowed = 0, 
  allowed_xmethods = 0x0, allowed_methods = 0x84b828, sent_bodyct = 0, 
  bytes_sent = 0, mtime = 0, chunked = 0, range = 0x0, clength = 0, 
  remaining = 525, read_length = 0, read_body = 1, read_chunked = 0, 
  expecting_100 = 0, headers_in = 0x8253d8, headers_out = 0x819af0, 
  err_headers_out = 0x825d20, subprocess_env = 0x819d38, notes = 0x84b688, 
  content_type = 0x84a308 "application/x-httpd-fastphp5", 
  handler = 0x2b952d6428c8 "fastcgi-script", content_encoding = 0x0, 
  content_languages = 0x0, vlist_validator = 0x0, 
  user = 0x84d028 "wollman@MIT.EDU", ap_auth_type = 0x0, no_cache = 0, 
  no_local_copy = 0, 
  unparsed_uri = 0x819518
"/.php5-cgi/16.410/wiki/index.php?title=Special:Preferences", uri = 0x819558
"/.php5-cgi/16.410/wiki/index.php", 
  filename = 0x84c418 "/usr/bin/php5-cgi", 
  canonical_filename = 0x84c418 "/usr/bin/php5-cgi", 
  path_info = 0x84c2f9 "/16.410/wiki/index.php", 
---Type <return> to continue, or q <return> to quit--- 
  args = 0x819580 "title=Special:Preferences", finfo = {pool = 0x825088, 
    valid = 7598448, protection = 1877, filetype = APR_REG, user = 0, 
    group = 0, inode = 283762, device = 2049, nlink = 1, size = 5483216, 
    csize = 8540296, atime = 1193866145000000, mtime = 1183409032000000, 
    ctime = 1193860247000000, fname = 0x84c418 "/usr/bin/php5-cgi", 
    name = 0x6bb731 "/.php5-cgi", filehand = 0x7fff808d1370}, parsed_uri = {
    scheme = 0x0, hostinfo = 0x0, user = 0x0, password = 0x0, hostname = 0x0, 
    port_str = 0x0, path = 0x819558 "/.php5-cgi/16.410/wiki/index.php", 
    query = 0x819580 "title=Special:Preferences", fragment = 0x0, 
    hostent = 0x0, port = 0, is_initialized = 1, dns_looked_up = 0, 
    dns_resolved = 0}, used_path_info = 0, per_dir_config = 0x819e60, 
  request_config = 0x8195a0, htaccess = 0x83cdb0, output_filters = 0x8265d0, 
  input_filters = 0x826c98, proto_output_filters = 0x8265d0, 
  proto_input_filters = 0x826c98, eos_sent = 0}
Comment 3 Joe Orton 2007-11-01 01:43:50 UTC
That all looks correct.  The filter chain is correct; r->remaining is 525 which
matches the number of bytes the SSL buffer captured.

I can't see why this would fail, and I can't think what else to suggest here
other than stepping through the code to see what is happening, or adding a lot
of ap_log_rerror() debugging calls in ap_get_client_block()/ap_http_filter().  

- is this ap_get_client_block() call happening *before* the timeout?
- does ap_get_client_block() fail?
- the topmost filter is ap_http_filter - breakpoint on that; does it get
invoked?  step through; what does it do?

Comment 4 Garrett Wollman 2007-11-01 08:30:35 UTC
What makes you say that the filter chain is correct?  I would expect the
"ssl/tls buffer" filter to be at the head to the chain, since that's where all
the data is being buffered.  There's no chance that reading from "ssl/tls
filter" will give me any data since its data has already been read and stored in
the buffer.

To answer your questions:
>- is this ap_get_client_block() call happening *before* the timeout?

Yes, I thought I made that clear in my analysis.

>- does ap_get_client_block() fail?

No, as I said before, it returns end-of-stream (0).

I haven't traced through ap_http_filter; however, in the course of instrumenting
ap_get_client_block() before I filed this bug, I made it skip over "http_in" and
read directly from "ssl/tls filter".  Same result: end of stream.
Comment 5 Ruediger Pluem 2007-11-01 09:16:12 UTC
(In reply to comment #4)
> What makes you say that the filter chain is correct?  I would expect the
> "ssl/tls buffer" filter to be at the head to the chain, since that's where all
> the data is being buffered.  There's no chance that reading from "ssl/tls
> filter" will give me any data since its data has already been read and stored in
> the buffer.

It is correct. You have to read the whole thing as a stack:


http_in(0x826c98):          HTTP filter: Does dechunking if transfer-encoding of 
                            the body is chunked or reads up to Content-length
                            bytes from the body.
ssl/tls filter(0x81e098):   Does decryption of the input stream and deals with
                            client certificates. Sometimes this filter buffers
                            data.
log_input_output(0x8109f0): Counts bytes that came in.
core_in(0x81e140):          Core network connection to the raw socket.
Comment 6 Garrett Wollman 2007-11-01 09:34:21 UTC
>ssl/tls filter(0x81e098):   Does decryption of the input stream and deals with
>                            client certificates. Sometimes this filter buffers
>                            data.

That's not what the code claims.  See the end of ssl_io_buffer_fill() in
ssl_engine_io.c:

    /* Insert the filter which will supply the buffered data. */
    ap_add_input_filter(ssl_io_buffer, ctx, r, c);

    return 0;

The buffered data can only come from the "ssl/tls buffer" filter, not the
"ssl/tls filter" filter.  As I noted in my original report, we know from the
debug logs that the "ssl/tls buffer" filter's read routine
(ssl_io_filter_buffer) is in fact being called, but not until after the
30-second timeout.
Comment 7 Joe Orton 2007-11-01 09:38:16 UTC
Created attachment 21077 [details]
test fix

Sorry, I read the filter stack wrong; I was only looking to check that http_in
was at the top; the second filter down should be the buffering filter not the
normal SSL filter (they are separate filters).

I note that r->prev is set here so an internal redirect will have happened. 
And that will filters < AP_FTYPE_PROTOCOL, which includes this one... oops. 
Can you try this fix?
Comment 8 Joe Orton 2007-11-01 09:40:27 UTC
should read: ^And that will kill filters < AP_FTYPE_PROTOCOL
Comment 9 Joe Orton 2007-11-01 09:51:57 UTC
Ah, no, that won't work at all.  The buffering filter is AP_FTYPE_PROTOCOL - 1
exactly because it the fill_buffer reads from r->proto_input_filters.  Ick.  I
can't see any obvious fix here.

To confirm the diagnosis can you reproduce without whatever triggered the
internal redirect?
Comment 10 Garrett Wollman 2007-11-01 10:41:26 UTC
> To confirm the diagnosis can you reproduce without whatever triggered the
> internal redirect?

Can you suggest how I might figure out what that was?

For what it's worth, ssl_io_filter_buffer() is eventually called from
ap_discard_request_body() after mod_fastcgi gives up.
Comment 11 Garrett Wollman 2007-11-01 10:48:52 UTC
> To confirm the diagnosis can you reproduce without whatever triggered the
> internal redirect?

I think I figured it out.  This problem is not seen by mod_php4 applications,
nor by regular CGI applications.  The internal redirect is caused by mod_action,
which is used to implement PHP5 under FastCGI.  The configuration looks like this:

FastCgiServer /usr/bin/php5-cgi -processes 5
ScriptAlias /.php5-cgi /usr/bin/php5-cgi
<Directory /usr/bin>
  Order deny,allow
  Deny from all
  <Files php5-cgi>
    Options ExecCGI
    SetHandler fastcgi-script
    Order allow,deny
    Allow from all
  </Files>
</Directory>
Action php5-script /.php5-cgi
Action application/x-httpd-fastphp5 /.php5-cgi

Then in .htaccess, users who want php5 instead of php4 specify:

AddHandler php5-script .php
Comment 12 William A. Rowe Jr. 2007-11-01 12:23:35 UTC
I don't see how your conf is triggering an internal redirect?

Can you differentiate if this is a fast-internal redirect or a straight
redirect?  Is this because the client requests /app/Login instead of
requesting /app/Login.php ?
Comment 13 Garrett Wollman 2007-11-01 12:54:07 UTC
> Can you differentiate if this is a fast-internal redirect or a straight
> redirect?

Not sure I know what that means.  Here is what the two request_rec structures
look like.  Note that the first one is generated in mod_actions by calling
ap_internal_redirect_handler() and the second one is the original request:

(gdb) p *r
$2 = {pool = 0x839398, connection = 0x80ba98, server = 0x6ce468, next = 0x0, 
  prev = 0x839408, main = 0x0, 
  the_request = 0x83a9c0 "GET /16.410/wiki/index.php?title=Special:Preferences
HTTP/1.1", assbackwards = 0, proxyreq = 0, header_only = 0, 
  protocol = 0x83aac0 "HTTP/1.1", proto_num = 1001, 
  hostname = 0x83aeb8 "more-courses.csail.mit.edu", 
  request_time = 1193938941817986, status_line = 0x44efd3 "200 OK", 
  status = 200, method = 0x83aa10 "GET", method_number = 0, allowed = 0, 
  allowed_xmethods = 0x0, allowed_methods = 0x81d928, sent_bodyct = 1, 
  bytes_sent = 8192, mtime = 0, chunked = 1, range = 0x0, clength = 0, 
  remaining = 0, read_length = 0, read_body = 1, read_chunked = 0, 
  expecting_100 = 0, headers_in = 0x8396e8, headers_out = 0x861668, 
  err_headers_out = 0x83a030, subprocess_env = 0x85af28, notes = 0x81d788, 
  content_type = 0x861450 "text/html; charset=utf-8", 
  handler = 0x2b7546f648c8 "fastcgi-script", content_encoding = 0x0, 
  content_languages = 0x0, vlist_validator = 0x0, 
  user = 0x840608 "wollman@MIT.EDU", ap_auth_type = 0x0, no_cache = 0, 
  no_local_copy = 0, 
  unparsed_uri = 0x85a708
"/.php5-cgi/16.410/wiki/index.php?title=Special:Preferences", uri = 0x85a748
"/.php5-cgi/16.410/wiki/index.php", 
  filename = 0x81e518 "/usr/bin/php5-cgi", 
  canonical_filename = 0x81e518 "/usr/bin/php5-cgi", 
  path_info = 0x81e3f9 "/16.410/wiki/index.php", 
---Type <return> to continue, or q <return> to quit--- 
  args = 0x85a770 "title=Special:Preferences", finfo = {pool = 0x839398, 
    valid = 7598448, protection = 1877, filetype = APR_REG, user = 0, 
    group = 0, inode = 283762, device = 2049, nlink = 1, size = 5483216, 
    csize = 8623000, atime = 1193936766000000, mtime = 1183409032000000, 
    ctime = 1193860247000000, fname = 0x81e518 "/usr/bin/php5-cgi", 
    name = 0x6b9721 "/.php5-cgi", filehand = 0x7fff66fafa30}, parsed_uri = {
    scheme = 0x0, hostinfo = 0x0, user = 0x0, password = 0x0, hostname = 0x0, 
    port_str = 0x0, path = 0x85a748 "/.php5-cgi/16.410/wiki/index.php", 
    query = 0x85a770 "title=Special:Preferences", fragment = 0x0, 
    hostent = 0x0, port = 0, is_initialized = 1, dns_looked_up = 0, 
    dns_resolved = 0}, used_path_info = 0, per_dir_config = 0x85b050, 
  request_config = 0x85a790, htaccess = 0x817f00, output_filters = 0x83a908, 
  input_filters = 0x83aed8, proto_output_filters = 0x83a908, 
  proto_input_filters = 0x83aed8, eos_sent = 0}
(gdb) p r->prev
$3 = (request_rec *) 0x839408
(gdb) p *r->prev
$4 = {pool = 0x839398, connection = 0x80ba98, server = 0x6ce468, 
  next = 0x85a428, prev = 0x0, main = 0x0, 
  the_request = 0x83a9c0 "GET /16.410/wiki/index.php?title=Special:Preferences
HTTP/1.1", assbackwards = 0, proxyreq = 0, header_only = 0, 
  protocol = 0x83aac0 "HTTP/1.1", proto_num = 1001, 
  hostname = 0x83aeb8 "more-courses.csail.mit.edu", 
  request_time = 1193938941817986, status_line = 0x0, status = 200, 
  method = 0x83aa10 "GET", method_number = 0, allowed = 0, 
  allowed_xmethods = 0x0, allowed_methods = 0x8396a8, sent_bodyct = 0, 
  bytes_sent = 0, mtime = 0, chunked = 0, range = 0x0, clength = 0, 
  remaining = 0, read_length = 0, read_body = 0, read_chunked = 0, 
  expecting_100 = 0, headers_in = 0x8396e8, headers_out = 0x839de8, 
  err_headers_out = 0x83a030, subprocess_env = 0x839a68, notes = 0x83a1d0, 
  content_type = 0x83daf8 "application/x-httpd-fastphp5", 
  handler = 0x83d980 "php5-script", content_encoding = 0x0, 
  content_languages = 0x0, vlist_validator = 0x0, 
  user = 0x819ac0 "wollman@MIT.EDU", ap_auth_type = 0x0, no_cache = 0, 
  no_local_copy = 0, 
  unparsed_uri = 0x83aa50 "/16.410/wiki/index.php?title=Special:Preferences", 
  uri = 0x83aa88 "/16.410/wiki/index.php", 
  filename = 0x83b108 "/afs/csail.mit.edu/proj/courses/data/16.410/wiki/index.php", 
  canonical_filename = 0x83b108
"/afs/csail.mit.edu/proj/courses/data/16.410/wik---Type <return> to continue, or
q <return> to quit---
i/index.php", path_info = 0x83b03a "", 
  args = 0x83aaa0 "title=Special:Preferences", finfo = {pool = 0x839398, 
    valid = 7598448, protection = 1604, filetype = APR_REG, user = 12369, 
    group = 12369, inode = 831797006, device = 18, nlink = 1, size = 3218, 
    csize = 0, atime = 1183079954000000, mtime = 1183079954000000, 
    ctime = 1183079954000000, 
    fname = 0x83b000
"/afs/csail.mit.edu/proj/courses/data/16.410/wiki/index.php", name = 0x0,
filehand = 0x0}, parsed_uri = {scheme = 0x0, hostinfo = 0x0, 
    user = 0x0, password = 0x0, hostname = 0x0, port_str = 0x0, 
    path = 0x83aa88 "/16.410/wiki/index.php", 
    query = 0x83aaa0 "title=Special:Preferences", fragment = 0x0, 
    hostent = 0x0, port = 0, is_initialized = 1, dns_looked_up = 0, 
    dns_resolved = 0}, used_path_info = 2, per_dir_config = 0x817f58, 
  request_config = 0x83a370, htaccess = 0x817f00, output_filters = 0x83a8e0, 
  input_filters = 0x83aed8, proto_output_filters = 0x83a8e0, 
  proto_input_filters = 0x83aed8, eos_sent = 0}
Comment 14 Garrett Wollman 2007-11-01 12:56:36 UTC
Oops, I should have noticed that that was a GET request that I tripped over
while debugging, rather than the POST requests that are the problem.  I'll try
to grab another dump from the right request.
Comment 15 Garrett Wollman 2007-11-01 13:07:02 UTC
Here's a better example:

(gdb) p *r
$3 = {pool = 0x817ca8, connection = 0x80ba98, server = 0x6ce468, next = 0x0, 
  prev = 0x817d18, main = 0x0, 
  the_request = 0x8192d0 "POST /16.410/wiki/index.php?title=Special:Preferences
HTTP/1.1", assbackwards = 0, proxyreq = 0, header_only = 0, 
  protocol = 0x8193d0 "HTTP/1.1", proto_num = 1001, 
  hostname = 0x819898 "more-courses.csail.mit.edu", 
  request_time = 1193947551567157, status_line = 0x0, status = 200, 
  method = 0x819320 "POST", method_number = 2, allowed = 0, 
  allowed_xmethods = 0x0, allowed_methods = 0x84a5b8, sent_bodyct = 0, 
  bytes_sent = 0, mtime = 0, chunked = 0, range = 0x0, clength = 0, 
  remaining = 528, read_length = 0, read_body = 1, read_chunked = 0, 
  expecting_100 = 0, headers_in = 0x817ff8, headers_out = 0x843ea0, 
  err_headers_out = 0x818940, subprocess_env = 0x8440e8, notes = 0x84a418, 
  content_type = 0x83daf8 "application/x-httpd-fastphp5", 
  handler = 0x2b7546f648c8 "fastcgi-script", content_encoding = 0x0, 
  content_languages = 0x0, vlist_validator = 0x0, 
  user = 0x840608 "wollman@MIT.EDU", ap_auth_type = 0x0, no_cache = 0, 
  no_local_copy = 0, 
  unparsed_uri = 0x8438c8
"/.php5-cgi/16.410/wiki/index.php?title=Special:Preferences", uri = 0x843908
"/.php5-cgi/16.410/wiki/index.php", 
  filename = 0x84b1a8 "/usr/bin/php5-cgi", 
  canonical_filename = 0x84b1a8 "/usr/bin/php5-cgi", 
  path_info = 0x84b089 "/16.410/wiki/index.php", 
---Type <return> to continue, or q <return> to quit--- 
  args = 0x843930 "title=Special:Preferences", finfo = {pool = 0x817ca8, 
    valid = 7598448, protection = 1877, filetype = APR_REG, user = 0, 
    group = 0, inode = 283762, device = 2049, nlink = 1, size = 5483216, 
    csize = 8486056, atime = 1193936766000000, mtime = 1183409032000000, 
    ctime = 1193860247000000, fname = 0x84b1a8 "/usr/bin/php5-cgi", 
    name = 0x6b9721 "/.php5-cgi", filehand = 0x7fff66fafa30}, parsed_uri = {
    scheme = 0x0, hostinfo = 0x0, user = 0x0, password = 0x0, hostname = 0x0, 
    port_str = 0x0, path = 0x843908 "/.php5-cgi/16.410/wiki/index.php", 
    query = 0x843930 "title=Special:Preferences", fragment = 0x0, 
    hostent = 0x0, port = 0, is_initialized = 1, dns_looked_up = 0, 
    dns_resolved = 0}, used_path_info = 0, per_dir_config = 0x844210, 
  request_config = 0x843950, htaccess = 0x82c5a0, output_filters = 0x8191f0, 
  input_filters = 0x8198b8, proto_output_filters = 0x8191f0, 
  proto_input_filters = 0x8198b8, eos_sent = 0}
(gdb) p *r->prev
$4 = {pool = 0x817ca8, connection = 0x80ba98, server = 0x6ce468, 
  next = 0x8435e8, prev = 0x0, main = 0x0, 
  the_request = 0x8192d0 "POST /16.410/wiki/index.php?title=Special:Preferences
HTTP/1.1", assbackwards = 0, proxyreq = 0, header_only = 0, 
  protocol = 0x8193d0 "HTTP/1.1", proto_num = 1001, 
  hostname = 0x819898 "more-courses.csail.mit.edu", 
  request_time = 1193947551567157, status_line = 0x0, status = 200, 
  method = 0x819320 "POST", method_number = 2, allowed = 0, 
  allowed_xmethods = 0x0, allowed_methods = 0x817fb8, sent_bodyct = 0, 
  bytes_sent = 0, mtime = 0, chunked = 0, range = 0x0, clength = 0, 
  remaining = 0, read_length = 0, read_body = 0, read_chunked = 0, 
  expecting_100 = 0, headers_in = 0x817ff8, headers_out = 0x8186f8, 
  err_headers_out = 0x818940, subprocess_env = 0x818378, notes = 0x818ae0, 
  content_type = 0x83daf8 "application/x-httpd-fastphp5", 
  handler = 0x83d980 "php5-script", content_encoding = 0x0, 
  content_languages = 0x0, vlist_validator = 0x0, 
  user = 0x82e1d8 "wollman@MIT.EDU", ap_auth_type = 0x0, no_cache = 0, 
  no_local_copy = 0, 
  unparsed_uri = 0x819360 "/16.410/wiki/index.php?title=Special:Preferences", 
  uri = 0x819398 "/16.410/wiki/index.php", 
  filename = 0x819ae8 "/afs/csail.mit.edu/proj/courses/data/16.410/wiki/index.php", 
  canonical_filename = 0x819ae8
"/afs/csail.mit.edu/proj/courses/data/16.410/wik---Type <return> to continue, or
q <return> to quit--- 
i/index.php", path_info = 0x819a1a "", 
  args = 0x8193b0 "title=Special:Preferences", finfo = {pool = 0x817ca8, 
    valid = 7598448, protection = 1604, filetype = APR_REG, user = 12369, 
    group = 12369, inode = 831797006, device = 18, nlink = 1, size = 3218, 
    csize = 0, atime = 1183079954000000, mtime = 1183079954000000, 
    ctime = 1183079954000000, 
    fname = 0x8199e0
"/afs/csail.mit.edu/proj/courses/data/16.410/wiki/index.php", name = 0x0,
filehand = 0x0}, parsed_uri = {scheme = 0x0, hostinfo = 0x0, 
    user = 0x0, password = 0x0, hostname = 0x0, port_str = 0x0, 
    path = 0x819398 "/16.410/wiki/index.php", 
    query = 0x8193b0 "title=Special:Preferences", fragment = 0x0, 
    hostent = 0x0, port = 0, is_initialized = 1, dns_looked_up = 0, 
    dns_resolved = 0}, used_path_info = 2, per_dir_config = 0x82c5f8, 
  request_config = 0x818c80, htaccess = 0x82c5a0, output_filters = 0x8191f0, 
  input_filters = 0x82e1a0, proto_output_filters = 0x8191f0, 
  proto_input_filters = 0x8198b8, eos_sent = 0}
Comment 16 Garrett Wollman 2007-11-01 13:16:40 UTC
And I can now confirm that the head of the input filter chain for the original
request is "ssl/tls buffer":

(gdb) p *r->prev->input_filters
$7 = {frec = 0x6333b8, ctx = 0x84b760, next = 0x858e18, r = 0x857278, 
  c = 0x80ba98}
(gdb) p *r->prev->input_filters->frec
$8 = {name = 0x628a18 "ssl/tls buffer", filter_func = {
    out_func = 0x2b7547f58370 <ssl_io_filter_buffer>, 
    in_func = 0x2b7547f58370 <ssl_io_filter_buffer>}, filter_init_func = 0, 
  ftype = 29, next = 0x0, providers = 0x0, debug = 0, proto_flags = 0}
Comment 17 Garrett Wollman 2007-11-01 13:18:42 UTC
Here's the full filter chain for both requests:

(gdb) dump_filters r->input_filters
http_in(0x81e8d8): ctx=0x85b050, r=0x818eb8, c=0x80ba98
ssl/tls filter(0x816ce8): ctx=0x814c98, r=0x0, c=0x80ba98
log_input_output(0x80c240): ctx=0x0, r=0x0, c=0x80ba98
core_in(0x816d90): ctx=0x816d70, r=0x0, c=0x80ba98
(gdb) dump_filters r->prev->input_filters
ssl/tls buffer(0x85b070): ctx=0x85b020, r=0x81cd38, c=0x80ba98
http_in(0x81e8d8): ctx=0x85b050, r=0x818eb8, c=0x80ba98
ssl/tls filter(0x816ce8): ctx=0x814c98, r=0x0, c=0x80ba98
log_input_output(0x80c240): ctx=0x0, r=0x0, c=0x80ba98
core_in(0x816d90): ctx=0x816d70, r=0x0, c=0x80ba98
Comment 18 Joe Orton 2007-11-02 06:33:54 UTC
Created attachment 21080 [details]
working fix

Here's a tested fix.  Moving the filter to AP_FTYPE_PROTOCOL is the right thing
to do; there were a few tricks needed to getting this working though.

Further testing welcome!
Comment 19 Joe Orton 2007-11-02 09:51:15 UTC
Fixed on trunk as per attached patch with only comment tweaks:

http://svn.apache.org/viewvc?rev=591393&view=rev

Results from testing still desirable!

Comment 20 Garrett Wollman 2007-11-02 13:02:00 UTC
It appears to work on my test server.
Comment 21 Joe Orton 2007-11-05 03:20:17 UTC
Great, thanks a lot for the testing and debugging work.
Comment 22 Ruediger Pluem 2008-01-02 03:00:15 UTC
Proposed for backport in r608076.
Comment 23 Joe Orton 2008-01-04 02:04:45 UTC
Merged for 2.2.x: http://svn.apache.org/viewvc?view=rev&revision=608787
Comment 24 Joe Orton 2009-03-06 02:41:24 UTC
*** Bug 46809 has been marked as a duplicate of this bug. ***