httpd-38123

Version:

2.2.0

How it is diagnosed (reproduced or source analysis)?

We reproduced the failure.

How to reproduce:

Compile httpd by enabling worker and proxy.

/usr/local/apache-proxy-worker-2.2.0/

Then use telnet to send the following (see symptom);

Symptom:

When Apache was sent the following lines using telnet:

GET / HTTP/1.1
Host: whatever.hostname.com
Expect: %8p

It "hangs" for some period of time

In the log (not the default verbose level!!):

[Sun Oct 17 20:55:05 2010] [info] [client 137.110.161.138] client sent an unrecognized expectation value of Expect: %8p

Root cause:

Did not handle the invalid input (%8p) well! Under spec, only “100-continue” is allowed after “Expect:” header.

protocol.c

request_rec *ap_read_request(conn_rec *conn) {

       ... ...

       if (strcasecmp(expect, "100-continue") == 0) {

           r->expecting_100 = 1;

       }

       else {

           /* Errlog will add a log point here: input check pattern! */

           r->status = HTTP_EXPECTATION_FAILED;

           ap_log_rerror(APLOG_MARK, APLOG_INFO, 0, r,

                         "client sent an unrecognized expectation value of "

                         "Expect: %s", expect);

   /* Hang in ap_send_error_response -- which is trying to use the customized

  timeout based IO (by nonblock write + poll). See bug 22030 for detail about

    Apache’s timeout based I/O and how it often hang. */

           ap_send_error_response(r, 0);

           ap_update_child_status(conn->sbh, SERVER_BUSY_LOG, r);

           ap_run_log_transaction(r);

           return r;

       }

}

/* Timeout-based I/O. Hang at the poll. See 22030 for detail. */

apr_wait_for_io_or_timeout (... …) {

   … …

    /* Where it hang: */

   poll (&pfd, 1, timeout); // timeout == 30000

}

#0  apr_wait_for_io_or_timeout (f=0x0, s=0xc730f8, for_read=1)

   at support/unix/waitio.c:52

#1  0x00007f7b403fe323 in apr_socket_recv (sock=0xc730f8,

   buf=0xc7b0e8 "\r\npect: %8p\r\n.com\r\n", len=0x4d644df8)

   at network_io/unix/sendrecv.c:87

#2  0x00007f7b40b304bb in socket_bucket_read (a=0xc770e8, str=0x4d644e00,

   len=0x4d644df8, block=APR_BLOCK_READ) at buckets/apr_buckets_socket.c:36

#3  0x00000000004388dc in ap_core_input_filter (f=0xc73a98, b=0xc7a980,

   mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)

   at core_filters.c:245

#4  0x00000000004476b1 in ap_get_brigade (next=0xc73a98, bb=0xc7a980,

   mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)

   at util_filter.c:489

#5  0x0000000000475c31 in ap_discard_request_body (r=0xc79128)

   at http_filters.c:1091

#6  0x000000000042b5f9 in ap_finalize_request_protocol (r=0xc79128)

   at protocol.c:1119

#7  0x00000000004723b6 in ap_send_error_response (r=0xc79128,

   recursive_error=0) at http_protocol.c:1255

#8  0x000000000042b226 in ap_read_request (conn=0xc73310) at protocol.c:1015

#9  0x000000000046fe59 in ap_process_http_connection (c=0xc73310)

   at http_core.c:164

Now, the patch... ...

Index: server/protocol.c

===================================================================

--- server/protocol.c        (Revision 371132)

+++ server/protocol.c        (Arbeitskopie)

request_rec *ap_read_request(conn_rec *conn) {

@@ -982,6 +982,16 @@

                      "(see RFC2616 section 14.23): %s", r->uri);

    }

+    /*

+     * Add the HTTP_IN filter here to ensure that ap_discard_request_body

+     * called by ap_die and by ap_send_error_response works correctly on

+     * status codes that do not cause the connection to be dropped and

+     * in situations where the connection should be kept alive.

+     */

+

+    ap_add_input_filter_handle(ap_http_input_filter_handle,

+                               NULL, r, r->connection);

+

 

1007:        if (strcasecmp(expect, "100-continue") == 0) {

           r->expecting_100 = 1;

       }

       else {

           r->status = HTTP_EXPECTATION_FAILED;

           ap_log_rerror(APLOG_MARK, APLOG_INFO, 0, r,

                         "client sent an unrecognized expectation value of "

                         "Expect: %s", expect);

           ap_send_error_response(r, 0); // where it hang...

           ap_update_child_status(conn->sbh, SERVER_BUSY_LOG, r);

           ap_run_log_transaction(r);

           return r;

       }

@@ -1021,9 +1029,6 @@

        }

    }

-    ap_add_input_filter_handle(ap_http_input_filter_handle,

-                               NULL, r, r->connection);

-

    return r;

}

So the patch is to call ‘ap_add_input_filter_handle’ before calling ‘ap_send_error_response’.

But why?

------------------------------------------- fixed bt -----------------------------------

#0  ap_http_filter (f=0x220ea60, b=0x220ec58, mode=AP_MODE_READBYTES,

   block=APR_BLOCK_READ, readbytes=8192) at http_filters.c:82

#1  0x0000000000445ae1 in ap_get_brigade (next=0x220ea60, bb=0x220ec58,

   mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)

   at util_filter.c:489

#2  0x000000000044c0d5 in ap_discard_request_body (r=0x220d238)

   at http_filters.c:1091

------------------------------------------- error bt -----------------------------------

#3  0x00000000004388dc in ap_core_input_filter (f=0xc73a98, b=0xc7a980,

   mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)

   at core_filters.c:245

#4  0x00000000004476b1 in ap_get_brigade (next=0xc73a98, bb=0xc7a980,

   mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)

   at util_filter.c:489

#5  0x0000000000475c31 in ap_discard_request_body (r=0xc79128)

   at http_filters.c:1091

ap_get_brigade(... ...)

{

   if (next) {

489:        return next->frec->filter_func.in_func(next, bb, mode, block,

                                              readbytes);

   }

   return AP_NOBODY_READ;

}

Can Errlog anticipate the error?

Yes. This falls into the ‘input check’ pattern, which is to check the input and print an error message when Apache finds unexpected input.

Since this case is also a hang on the timeout-based I/O (similar to 22030), Errlog can also print an error message before it hang. (see 22030 for detail).

Is there default level Error Message?

No. (the log point is not under default verbosity level).