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 "[email protected]",
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
