httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rainer Jung <rainer.j...@kippdata.de>
Subject Re: Proxy regressions
Date Wed, 03 Nov 2010 23:50:46 GMT
On 03.11.2010 21:12, Stefan Fritsch wrote:
> some of the recent changes in the proxy code introduced some
> regressions:
>
> Two proxy-related tests fail:
>
> t/modules/rewrite.t       (Wstat: 0 Tests: 29 Failed: 2)
>    Failed tests:  23-24

Not reproducable with prefork here, using Solaris 10, r1030642 of httpd 
trunk and r1004302 apr trunk. But the two tests fail for worker and event:

# testing : request was proxied
# expected: JACKPOT
# received: 500 unexpected EOF before status line seen
not ok 23
# Failed test 23 in t/modules/rewrite.t at line 68
# testing : per-dir proxied rewrite escaping worked
# expected: foo bar
# received: 500 unexpected EOF before status line seen
not ok 24

> Also, the runtime of the suite seems to have increased greatly for me
> (from around 80 to 360 seconds). I haven't made detailed measurements,
> but my feeling is that most of the time is spent in the ssl/proxy.t
> and modules/proxy.t tests.

In my prefork run, t/modules/proxy.t was a bit slow, but t/ssl/proxy.t 
was very slow.

For worker, also t/modules/proxy.t was slow, in fact hanging. Typical 
stack hangs in apr_reslist_acquire:

#0  0xff0c8d3c in __lwp_park () from /lib/libc.so.1
No symbol table info available.
#1  0xff0c2b94 in cond_sleep_queue () from /lib/libc.so.1
No symbol table info available.
#2  0xff0c2d58 in cond_wait_queue () from /lib/libc.so.1
No symbol table info available.
#3  0xff0c32a0 in cond_wait () from /lib/libc.so.1
No symbol table info available.
#4  0xff0c32dc in pthread_cond_wait () from /lib/libc.so.1
No symbol table info available.
#5  0xff333d9c in apr_reslist_acquire (reslist=0x482758, 
resource=0xfd37ba24) at 
/shared/build/dev/httpd/sources/apr/trunk/r1004302/util-misc/apr_reslist.c:374
         rv = 0
         res = (apr_res_t *) 0xfd37ba7f
         now = 1288826750667273
#6  0xfe24e784 in ap_proxy_acquire_connection (proxy_function=0xfe1e8618 
"HTTP", conn=0xfd37ba24, worker=0x4dc8d8, s=0x3b5ef8)
     at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/proxy_util.c:2068
         rv = -31135876
#7  0xfe1e598c in proxy_http_handler (r=0x4f63d8, worker=0x4dc8d8, 
conf=0x4dc7d0, url=0x5429a6 
"http://localhost:8529/modules/cgi/nph-102.pl", proxyname=0x0, proxyport=0)
     at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/mod_proxy_http.c:2054
         status = 5202904
         server_portstr = ":8541\000$¸ýJ\n", '\0' <repeats 12 times>, 
"\001ý7»¬\000\000\000\030"
         scheme = 0x543880 "http"
         proxy_function = 0xfe1e8618 "HTTP"
         backend = (proxy_conn_rec *) 0x0
         is_ssl = 0
         c = (conn_rec *) 0x4f2688
         retry = 0
         p = (apr_pool_t *) 0x4f6398
         uri = (apr_uri_t *) 0x543850
#8  0xfe245c08 in proxy_run_scheme_handler (r=0x4f63d8, worker=0x4dc8d8, 
conf=0x4dc7d0, url=0x5429a6 
"http://localhost:8529/modules/cgi/nph-102.pl", proxyhost=0x0,
     proxyport=0) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/mod_proxy.c:2451
         pHook = (proxy_LINK_scheme_handler_t *) 0x0
         n = 1
         rv = 5202904
#9  0xfe24974c in proxy_handler (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/mod_proxy.c:1067
         url = 0x5429a6 "http://localhost:8529/modules/cgi/nph-102.pl"
         uri = 0x5429a6 "http://localhost:8529/modules/cgi/nph-102.pl"
         scheme = 0x5437e8 "http"
         sconf = (void *) 0x5429a0
         conf = (proxy_server_conf *) 0x4dc7d0
         proxies = (apr_array_header_t *) 0x4dc828
         ents = (struct proxy_remote *) 0x195098
         i = 0
         access_status = 0
         direct_connect = 0
         maxfwd = 5202904
         balancer = (proxy_balancer *) 0x0
         worker = (proxy_worker *) 0x4dc8d8
         attempts = 0
         max_attempts = 0
         list = (struct dirconn_entry *) 0x1952c0
#10 0x00044b10 in ap_run_handler (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/server/config.c:164
         pHook = (ap_LINK_handler_t *) 0x4dc828
         n = 3
         rv = 5202904
#11 0x00044fa0 in ap_invoke_handler (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/server/config.c:406
         handler = 0x4f63d8 ""
         result = 5202904
         old_handler = 0xfe252098 "proxy-server"
#12 0x00056cfc in ap_process_async_request (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/http/http_request.c:316
         i = 502784
         t_h = (const apr_array_header_t *) 0x2
         t_elt = (const apr_table_entry_t *) 0xa
         c = (conn_rec *) 0x4f2688
         access_status = 0
#13 0x00056e60 in ap_process_request (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/http/http_request.c:361
         bb = (apr_bucket_brigade *) 0xfd4c00e8
         b = (apr_bucket *) 0x4f63d8
         c = (conn_rec *) 0x4f2688
         rv = 502784
...


The data for ap_reslist_acquire is:

#5  0xff333d9c in apr_reslist_acquire (reslist=0x482758, 
resource=0xfd37ba24) at 
/shared/build/dev/httpd/sources/apr/trunk/r1004302/util-misc/apr_reslist.c:374
374                 apr_thread_cond_wait(reslist->avail, reslist->listlock);

(gdb) print *reslist

$1 = {pool = 0x482718, ntotal = 2, nidle = 0, min = 0, smax = 2, hmax = 
2, ttl = 0, timeout = 0, constructor = 0xfe24d830 <connection_constructor>,
   destructor = 0xfe24d8e0 <connection_destructor>, params = 0x4dc8d8, 
avail_list = {next = 0x482780, prev = 0x482780}, free_list = {next = 
0x482820, prev = 0x482820},
   listlock = 0x4827a8, avail = 0x4827d8}

(gdb) print *resource

$2 = (void *) 0x0

(gdb) print reslist->avail

$3 = (apr_thread_cond_t *) 0x4827d8

(gdb) print *(reslist->avail)

$4 = {pool = 0x482718, cond = {__pthread_cond_flags = 
{__pthread_cond_flag = "\000\003\001", __pthread_cond_type = 0, 
__pthread_cond_magic = 17238},
     __pthread_cond_data = 0}}

(gdb) print *(reslist->listlock)

$5 = {pool = 0x482718, mutex = {__pthread_mutex_flags = 
{__pthread_mutex_flag1 = 4, __pthread_mutex_flag2 = 0 '\0', 
__pthread_mutex_ceiling = 0 '\0',
       __pthread_mutex_type = 0, __pthread_mutex_magic = 19800}, 
__pthread_mutex_lock = {__pthread_mutex_lock64 = {__pthread_mutex_pad = 
"\000\000\000\000\000\000\000"},
       __pthread_mutex_lock32 = {__pthread_ownerpid = 0, 
__pthread_lockword = 0}, __pthread_mutex_owner64 = 0}, 
__pthread_mutex_data = 0}}

(gdb) print *reslist->pool

$6 = {parent = 0x3ea3b0, child = 0x490750, sibling = 0x480710, ref = 
0x484728, cleanups = 0x482810, free_cleanups = 0x0, allocator = 0x80488, 
subprocesses = 0x0,
   abort_fn = 0x2ac90 <abort_on_oom>, user_data = 0x0, tag = 0xfe253b00 
"proxy_worker_cp", active = 0x482700, self = 0x482700, self_first_avail 
= 0x482758 "",
   pre_cleanups = 0x0}

(gdb) print *reslist->avail_list->next

$7 = {freed = -133744383980414752, opaque = 0x4dc8d8, link = {next = 
0x482780, prev = 0x482780}}

(gdb) print *reslist->free_list->next

$8 = {freed = 1288826743985216, opaque = 0x490790, link = {next = 
0x482788, prev = 0x482788}}

(gdb) up

#6  0xfe24e784 in ap_proxy_acquire_connection (proxy_function=0xfe1e8618 
"HTTP", conn=0xfd37ba24, worker=0x4dc8d8, s=0x3b5ef8)
     at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/proxy_util.c:2068
2068            rv = apr_reslist_acquire(worker->cp->res, (void **)conn);

(gdb) print *conn

$9 = (proxy_conn_rec *) 0x0

(gdb) print *worker

$10 = {name = 0x3bc6a0 "http://localhost:8529/", scheme = 0x3bc638 
"http", hostname = 0x3bc650 "localhost", route = 0x0, redirect = 0x0, id 
= 0, status = 1, lbfactor = 0,
   lbset = 0, min = 0, smax = 2, hmax = 2, ttl = 0, retry = 60000000, 
timeout = 0, acquire = 0, ping_timeout = 0, conn_timeout = 0, 
recv_buffer_size = 0,
   io_buffer_size = 8192, port = 8529, keepalive = 0 '\0', disablereuse 
= 0 '\0', is_address_reusable = -1, cp = 0x3eab10, s = 0xfd4fa0e8, 
opaque = 0x0, context = 0x0,
   flush_packets = flush_off, flush_wait = 10000, flusher = 0x0, mutex = 
0x3eab20, retry_set = 0, timeout_set = 0, acquire_set = 0, 
ping_timeout_set = 0,
   conn_timeout_set = 0, recv_buffer_size_set = 0, io_buffer_size_set = 
0, keepalive_set = 0, disablereuse_set = 0, apr_hash = 513223906, 
our_hash = 3592597298}

(gdb) print *s

$11 = {process = 0x845b0, next = 0x3b0b68, error_fname = 0x0, error_log 
= 0x84560, log = {module_levels = 0x0, level = 7}, module_config = 0x3ba0b0,
   lookup_defaults = 0x4dc9f8, defn_name = 0x283400 
"/shared/build/dev/httpd/test/httpd/trunk/r1030642/solaris10.sparc-trunk-all-shared/worker/t/conf/extra.conf",
   defn_line_number = 263, is_virtual = 1 '\001', port = 8541, 
server_scheme = 0x0, server_admin = 0x3a8018 "you@example.com", 
server_hostname = 0x3ba860 "localhost",
   addrs = 0x3ba5f8, timeout = 300000000, keep_alive_timeout = 5000000, 
keep_alive_max = 100, keep_alive = 1, names = 0x3b5f70, wild_names = 
0x3b5f98, path = 0x0,
   pathlen = 0, limit_req_line = 8190, limit_req_fieldsize = 8190, 
limit_req_fields = 100, context = 0x0}


I had to kill the processes.

Event was not hanging and not very slow. But note, that the test 
includes explicit MPM configs with small number of threads and processes 
for worker, but default settings for event!


During the final shutdown, worker and event crash. The data for worker 
(couldn't get reasoable data for event):

#0  0xff31e498 in apr_brigade_cleanup (data=0x5050a8) at 
/shared/build/dev/httpd/sources/apr/trunk/r1004302/buckets/apr_brigade.c:46
No locals.
#1  0xfe1e3f9c in ap_proxy_http_process_response (p=0x4f6398, 
r=0x4f63d8, backend=0x486768, worker=0x3ea810, conf=0x194fe8, 
server_portstr=0xfd27ba60 ":8529")
     at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/mod_proxy_http.c:1931
         readbytes = 8
         rv = 5263528
         mode = APR_NONBLOCK_READ
         finish = 1
         c = (conn_rec *) 0x4f2680
         buffer = "\000\nntent-Type\000 
text/html\000\n7ac0\"\000\n15:52:51 GMT\000\ndev OpenSSL/0.9.8o 
DAV/2\000\n", '\0' <repeats 409 times>, "\v\232\210", '\0' <repeats 12 
times>, "þ%\021Ð\000\000\004)\000\000\000A\000\000\000\a", '\0' <repeats 
17 times>, "Thu Nov 04 00:41:34.563204 2010] [proxy:debug] [pid 
19304:tid 4] mod_proxy.c(10"...
         buf = 0x5050a8 ""
         keepchar = -84 '¬'
         rp = (request_rec *) 0x5050c8
         e = (apr_bucket *) 0x5050a8
         bb = (apr_bucket_brigade *) 0x5050a8
         tmp_bb = (apr_bucket_brigade *) 0x508018
         pass_bb = (apr_bucket_brigade *) 0x5050b8
         len = 15
         backasswards = 0
         interim_response = 0
         pread_len = 0
         save_table = (apr_table_t *) 0x508030
         backend_broke = 0
         hop_by_hop_hdrs = {0xfe1e7fd0 "Keep-Alive", 0xfe1e7fe0 
"Proxy-Authenticate", 0xfe1e7ff8 "TE", 0xfe1e8000 "Trailer", 0xfe1e8008 
"Upgrade", 0x0}
         i = 5263532
         te = 0x0
         original_status = 200
         proxy_status = 200
         original_status_line = 0x0
         origin = (conn_rec *) 0x48ea38
         old_timeout = 0
         dconf = (proxy_dir_conf *) 0x195c28
         do_100_continue = 0
#2  0xfe1e79ac in proxy_http_handler (r=0x4f63d8, worker=0x3ea810, 
conf=0x194fe8, url=0x5025be 
"http://localhost:8529/modules/rewrite/foo%20bar.html", proxyname=0x0,
     proxyport=0) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/mod_proxy_http.c:2133
         temp_dir = 0x4faf90 ""
         template = 0x4f63d8 ""
         status = 0
         server_portstr = 
":8529\000c\230\000\000\000\000\000\000\000\000\000Oc\230\000P\023¨ý'»¬\000\000\000\030"
         scheme = 0x0
         proxy_function = 0xfe1e8618 "HTTP"
         backend = (proxy_conn_rec *) 0x486768
         is_ssl = 0
         c = (conn_rec *) 0x4f2680
         retry = 0
         p = (apr_pool_t *) 0x4f6398
         uri = (apr_uri_t *) 0x503f60
#3  0xfe245c08 in proxy_run_scheme_handler (r=0x4f63d8, worker=0x3ea810, 
conf=0x194fe8, url=0x5025be 
"http://localhost:8529/modules/rewrite/foo%20bar.html",
     proxyhost=0x0, proxyport=0) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/mod_proxy.c:2451
         pHook = (proxy_LINK_scheme_handler_t *) 0x0
         n = 1
         rv = 0
#4  0xfe24974c in proxy_handler (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/proxy/mod_proxy.c:1067
         url = 0x5025be 
"http://localhost:8529/modules/rewrite/foo%20bar.html"
         uri = 0x5025be 
"http://localhost:8529/modules/rewrite/foo%20bar.html"
         scheme = 0x503ec8 "http"
         sconf = (void *) 0x5025b8
         conf = (proxy_server_conf *) 0x194fe8
         proxies = (apr_array_header_t *) 0x195080
         ents = (struct proxy_remote *) 0x195098
         i = 0
         access_status = 0
---Type <return> to continue, or q <return> to quit---
         direct_connect = 0
         maxfwd = 5202904
         balancer = (proxy_balancer *) 0x0
         worker = (proxy_worker *) 0x3ea810
         attempts = 0
         max_attempts = 0
         list = (struct dirconn_entry *) 0x1952c0
#5  0x00044b10 in ap_run_handler (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/server/config.c:164
         pHook = (ap_LINK_handler_t *) 0x195080
         n = 3
         rv = 5202904
#6  0x00044fa0 in ap_invoke_handler (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/server/config.c:406
         handler = 0x4f63d8 ""
         result = 5202904
         old_handler = 0xfdaad9f8 "proxy-server"
#7  0x00056cfc in ap_process_async_request (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/http/http_request.c:316
         i = 502784
         t_h = (const apr_array_header_t *) 0x2
         t_elt = (const apr_table_entry_t *) 0xa
         c = (conn_rec *) 0x4f2680
         access_status = 0
#8  0x00056e60 in ap_process_request (r=0x4f63d8) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/http/http_request.c:361
         bb = (apr_bucket_brigade *) 0xfd4c01d0
         b = (apr_bucket *) 0x4f63d8
         c = (conn_rec *) 0x4f2680
         rv = 502784
#9  0x00053698 in ap_process_http_connection (c=0x4f2680) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/modules/http/http_core.c:186
No locals.
#10 0x0004d58c in ap_run_process_connection (c=0x4f2680) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/server/connection.c:41
         pHook = (ap_LINK_process_connection_t *) 0x5
         n = 4
         rv = 5187200
#11 0xfdd84520 in worker_thread (thd=0x3ead10, dummy=0x1) at 
/shared/build/dev/httpd/sources/httpd/trunk/r1030642/server/mpm/worker/worker.c:561
         process_slot = 0
         thread_slot = 1
         csd = (apr_socket_t *) 0x4f23c8
         bucket_alloc = (apr_bucket_alloc_t *) 0x4f4390
         last_ptrans = (apr_pool_t *) 0x0
         ptrans = (apr_pool_t *) 0x4f2388
         rv = 5187192
         is_idle = 0
#12 0xff34abc0 in dummy_worker (opaque=0x3ead10) at 
/shared/build/dev/httpd/sources/apr/trunk/r1004302/threadproc/unix/thread.c:142


Regards,

Rainer

Mime
View raw message