Hi all,
Le 12/03/2013 12:38, David Coulson a écrit :
On 3/12/13 7:31 AM, Cyril Bonté wrote:
I'm sorry to say that you've certainly met a bug while combining
http-send-name-header (which is a bit tricky in the code) and ssl
ciphering on servers. This is a case that has not been tested, I think.
I can also reproduce this with the configuration you provided (also
wit the last snapshot). Once I remove ssl ciphering, it works well.
I'm not sure to have time to investigate this before next week, so I
hope Willy or someone at Exceliance can have a look on this.
Do you really need to cipher outgoing connections ? Disabling it could
be a quick fix to your issue.
The appliances being proxied only supports HTTPS, so I can't do plain
HTTP on the backend unfortunately. Fortunately, they're not production
yet so nothing is 'broken'.
OK, i could make some more tests yesterday. SSL ciphering on a backend
server is not the culprit. It is more like an issue in the stream
interface : it depends on when haproxy detects a server close.
I could write a small configuration which reproduces the issue all the
time :
listen debug :8888
mode http
http-send-name-header X-Server
rspirep ^Location: Location:\ foobar
server server.local 127.0.0.1:8889
listen redirector
mode http
bind :8889
redirect location /
Using v1.5-dev17-83-gdad36a3 :
$ curl -i http://localhost:8888/
HTTP/1.1 302 Found
Cache-Control: no-cache
Content-length: 0
Location: /
Connection: close
While using v1.4.22-23-gd978423, I get :
HTTP/1.1 302 Found
Cache-Control: no-cache
Content-length: 0
Location: foobar
Connection: close
For the tests, both were compiled with :
make DEBUG=-DDEBUG_FULL TARGET=linux2628
(no openssl, no zlib)
In attachment, the output of both versions. We can see an early
debug.srvcls with haproxy v1.5, preventing the response to gain the
HTTP_MSG_BODY state.
For now, I don't know where to look but maybe it can be useful to find
and fix the issue.
I also tried with :
v1.5-dev8 : it works
v1.5-dev9 : segfault
v1.5-dev10 : segfault
v1.5-dev11 : couldn't compile
v1.5-dev12 : couldn't compile
v1.5-dev13 : it doesn't work anymore
Maybe we'll have to study the commits between dev8 and dev9 ?
At least I know it wasn't something I did :)
David
--
Cyril Bonté
00000000:debug.accept(0004)=0006 from [127.0.0.1:38721]
stream_sock_read : fd=6, ev=0x01, owner=0x165a1f0
[1670332972] process_session:973: task=0x161c390 s=0x165a190, sfl=0x00000080, rq=0x165aa60, rp=0x165eaf0, exp(r,w)=0,0 rqf=00101002 rpf=00001000 rql=78 rpl=0 cs=7 ss=0, cet=0x0 set=0x0 retr=3
[1670332972] http_wait_for_request: session=0x165a190 b=0x165aa60, exp(r,w)=0,0 bf=00909002 bl=78 analysers=0e
00000000:debug.clireq[0006:ffff]: GET / HTTP/1.1
00000000:debug.clihdr[0006:ffff]: User-Agent: curl/7.29.0
00000000:debug.clihdr[0006:ffff]: Host: localhost:8888
00000000:debug.clihdr[0006:ffff]: Accept: */*
[1670332972] http_process_req_common: session=0x165a190 b=0x165aa60, exp(r,w)=0,0 bf=00909002 bl=78 analysers=08
[1670332972] process_switching_rules: session=0x165a190 b=0x165aa60, exp(r,w)=0,0 bf=04909002 bl=78 analysers=00
[1670332972] http_process_request: session=0x165a190 b=0x165aa60, exp(r,w)=0,0 bf=04909002 bl=78 analysers=20
[1670332972] sess_prepare_conn_req: sess=0x165a190 rq=0x165aa60, rp=0x165eaf0, exp(r,w)=0,0 rqf=05900002 rpf=00001000 rql=78 rpl=0 cs=7 ss=1
assign_server : s=0x165a190
[1670332972] sess_update_stream_int: sess=0x165a190 rq=0x165aa60, rp=0x165eaf0, exp(r,w)=0,0 rqf=05900002 rpf=00001000 rql=78 rpl=0 cs=7 ss=4
assign_server_address : s=0x165a190
[1670332972] stream_sock_data_finish: fd=6 owner=0x165a1f0 ib=0x165aa60, ob=0x165eaf0, exp(r,w)=0,0 ibf=05900002 obf=00001000 ibl=102 obl=0 si=7
[1670332972] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=5
stream_sock_write : fd=7, owner=0x165a278
_do_poll:500: fd=5, ev=0x00000001, e=0x00000001
00000001:redirector.accept(0005)=0008 from [127.0.0.1:52308]
stream_sock_read : fd=8, ev=0x01, owner=0x1662be0
[1670332972] process_session:973: task=0x161c390 s=0x165a190, sfl=0x000004ce, rq=0x165aa60, rp=0x165eaf0, exp(r,w)=0,0 rqf=01901200 rpf=00101000 rql=0 rpl=0 cs=7 ss=7, cet=0x0 set=0x0 retr=3
[1670332972] http_wait_for_response: session=0x165a190 b=0x165eaf0, exp(r,w)=0,0 bf=00109000 bl=0 analysers=60000
[1670332972] stream_sock_data_finish: fd=6 owner=0x165a1f0 ib=0x165aa60, ob=0x165eaf0, exp(r,w)=0,0 ibf=01901200 obf=00101000 ibl=0 obl=0 si=7
[1670332972] stream_sock_data_finish: fd=7 owner=0x165a278 ib=0x165eaf0, ob=0x165aa60, exp(r,w)=0,0 ibf=00101000 obf=01901200 ibl=0 obl=0 si=7
[1670332972] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=7
[1670332972] process_session:973: task=0x1625cd0 s=0x1662b80, sfl=0x00000080, rq=0x1663450, rp=0x16674e0, exp(r,w)=0,0 rqf=00101002 rpf=00001000 rql=102 rpl=0 cs=7 ss=0, cet=0x0 set=0x0 retr=3
[1670332972] http_wait_for_request: session=0x1662b80 b=0x1663450, exp(r,w)=0,0 bf=00909002 bl=102 analysers=0e
00000001:redirector.clireq[0008:ffff]: GET / HTTP/1.1
00000001:redirector.clihdr[0008:ffff]: User-Agent: curl/7.29.0
00000001:redirector.clihdr[0008:ffff]: Host: localhost:8888
00000001:redirector.clihdr[0008:ffff]: Accept: */*
00000001:redirector.clihdr[0008:ffff]: X-Server: server.local
[1670332972] http_process_req_common: session=0x1662b80 b=0x1663450, exp(r,w)=0,0 bf=00909002 bl=102 analysers=08
[1670332972] stream_sock_data_finish: fd=8 owner=0x1662be0 ib=0x1663450, ob=0x16674e0, exp(r,w)=0,0 ibf=0090f022 obf=0000c060 ibl=0 obl=98 si=7
[1670332972] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=9
stream_sock_read : fd=7, ev=0x01, owner=0x165a278
[1670332972] stream_sock_chk_snd: fd=6 owner=0x165a1f0 ib=0x165aa60, ob=0x165eaf0, exp(r,w)=0,0 ibf=01901000 obf=00101000 ibl=0 obl=0 si=7
stream_sock_write : fd=8, owner=0x1662be0
_do_poll:500: fd=7, ev=0x00000000, e=0x00000001
stream_sock_read : fd=7, ev=0x01, owner=0x165a278
[1670332972] process_session:973: task=0x161c390 s=0x165a190, sfl=0x000004ce, rq=0x165aa60, rp=0x165eaf0, exp(r,w)=0,0 rqf=01901000 rpf=00101023 rql=0 rpl=98 cs=7 ss=7, cet=0x0 set=0x0 retr=3
[1670332972] http_wait_for_response: session=0x165a190 b=0x165eaf0, exp(r,w)=0,0 bf=00109023 bl=98 analysers=60000
00000000:debug.srvrep[0006:0007]: HTTP/1.1 302 Found
00000000:debug.srvhdr[0006:0007]: Cache-Control: no-cache
00000000:debug.srvhdr[0006:0007]: Content-length: 0
00000000:debug.srvhdr[0006:0007]: Location: /
00000000:debug.srvhdr[0006:0007]: Connection: close
[1670332972] http_process_res_common: session=0x165a190 b=0x165eaf0, exp(r,w)=0,0 bf=00109023 bl=98 analysers=40000
[1670332972] stream_sock_data_finish: fd=6 owner=0x165a1f0 ib=0x165aa60, ob=0x165eaf0, exp(r,w)=0,0 ibf=08909000 obf=0c10c023 ibl=0 obl=103 si=7
[1670332972] stream_sock_data_finish: fd=7 owner=0x165a278 ib=0x165eaf0, ob=0x165aa60, exp(r,w)=0,0 ibf=0c10c023 obf=08909000 ibl=103 obl=0 si=7
[1670332972] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=7
[1670332972] process_session:973: task=0x1625cd0 s=0x1662b80, sfl=0x00015480, rq=0x1663450, rp=0x16674e0, exp(r,w)=0,0 rqf=0090f020 rpf=0000b260 rql=0 rpl=0 cs=8 ss=9, cet=0x0 set=0x0 retr=3
00000001:redirector.clicls[0008:ffff]
00000001:redirector.closed[0008:ffff]
stream_sock_read : fd=6, ev=0x01, owner=0x165a1f0
[1670332972] stream_sock_chk_snd: fd=7 owner=0x165a278 ib=0x165eaf0, ob=0x165aa60, exp(r,w)=0,0 ibf=0c10c020 obf=08909000 ibl=103 obl=0 si=7
stream_sock_write : fd=6, owner=0x165a1f0
[1670332972] process_session:973: task=0x161c390 s=0x165a190, sfl=0x000004ce, rq=0x165aa60, rp=0x165eaf0, exp(r,w)=0,0 rqf=08909000 rpf=0810b220 rql=0 rpl=0 cs=7 ss=7, cet=0x0 set=0x0 retr=3
[1670332972] stream_sock_data_finish: fd=6 owner=0x165a1f0 ib=0x165aa60, ob=0x165eaf0, exp(r,w)=0,0 ibf=08909000 obf=0810b220 ibl=0 obl=0 si=7
[1670332972] stream_sock_data_finish: fd=7 owner=0x165a278 ib=0x165eaf0, ob=0x165aa60, exp(r,w)=0,0 ibf=0810b220 obf=08909000 ibl=0 obl=0 si=7
[1670332972] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=7
_do_poll:500: fd=6, ev=0x00000000, e=0x00000011
stream_sock_read : fd=6, ev=0x11, owner=0x165a1f0
[1670332972] stream_sock_chk_snd: fd=7 owner=0x165a278 ib=0x165eaf0, ob=0x165aa60, exp(r,w)=0,0 ibf=0810b020 obf=0890d021 ibl=0 obl=0 si=7
[1670332972] process_session:973: task=0x161c390 s=0x165a190, sfl=0x000004ce, rq=0x165aa60, rp=0x165eaf0, exp(r,w)=0,0 rqf=0890d021 rpf=0810b020 rql=0 rpl=0 cs=8 ss=7, cet=0x0 set=0x0 retr=3
[1670332972] process_session:973: task=0x161c390 s=0x165a190, sfl=0x000004ce, rq=0x165aa60, rp=0x165eaf0, exp(r,w)=0,0 rqf=0890b021 rpf=0810b020 rql=0 rpl=0 cs=9 ss=8, cet=0x0 set=0x0 retr=3
00000000:debug.srvcls[0006:0007]
00000000:debug.clicls[0006:0007]
00000000:debug.closed[0006:0007]
00000001:debug.accept(0004)=0006 from [127.0.0.1:38694]
si_conn_wake_cb: si=0x2266cc8, si->state=7 ib->flags=00500002 ob->flags=00000000
[1670177426] process_session:1718: task=0x2267150 s=0x2266a40, sfl=0x00000080, rq=0x22671f0, rp=0x226b280, exp(r,w)=0,0 rqf=00100002 rpf=00000000 rqh=78 rqt=0 rph=0 rpt=0 cs=7 ss=0, cet=0x0 set=0x0 retr=0
[1670177426] http_wait_for_request: session=0x2266a40 b=0x22671f0, exp(r,w)=0,0 bf=00908002 bh=78 analysers=1c
00000001:debug.clireq[0006:ffff]: GET / HTTP/1.1
00000001:debug.clihdr[0006:ffff]: User-Agent: curl/7.29.0
00000001:debug.clihdr[0006:ffff]: Host: localhost:8888
00000001:debug.clihdr[0006:ffff]: Accept: */*
[1670177426] http_process_req_common: session=0x2266a40 b=0x22671f0, exp(r,w)=0,0 bf=00908002 bh=78 analysers=10
[1670177426] process_switching_rules: session=0x2266a40 b=0x22671f0, exp(r,w)=0,0 bf=04908002 bh=78 analysers=00
[1670177426] http_process_request: session=0x2266a40 b=0x22671f0, exp(r,w)=0,0 bf=04908002 bh=78 analysers=100
[1670177426] sess_prepare_conn_req: sess=0x2266a40 rq=0x22671f0, rp=0x226b280, exp(r,w)=0,0 rqf=05908002 rpf=00000000 rqh=0 rqt=78 rph=0 rpt=0 cs=7 ss=1
assign_server : s=0x2266a40
[1670177426] sess_update_stream_int: sess=0x2266a40 rq=0x22671f0, rp=0x226b280, exp(r,w)=0,0 rqf=05908002 rpf=00000000 rqh=0 rqt=78 rph=0 rpt=0 cs=7 ss=4
assign_server_address : s=0x2266a40
[1670177426] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=5
00000002:redirector.accept(0005)=0008 from [127.0.0.1:52281]
si_conn_wake_cb: si=0x226f748, si->state=7 ib->flags=00500000 ob->flags=00000000
si_conn_wake_cb: si=0x2266d60, si->state=5 ib->flags=00000000 ob->flags=01808200
[1670177427] process_session:1718: task=0x226fbd0 s=0x226f4c0, sfl=0x00000080, rq=0x226fc70, rp=0x2273d00, exp(r,w)=0,0 rqf=00500000 rpf=00000000 rqh=0 rqt=0 rph=0 rpt=0 cs=7 ss=0, cet=0x0 set=0x0 retr=0
[1670177427] http_wait_for_request: session=0x226f4c0 b=0x226fc70, exp(r,w)=0,0 bf=00d08000 bh=0 analysers=1c
[1670177427] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=0
[1670177427] process_session:1718: task=0x2267150 s=0x2266a40, sfl=0x000004ce, rq=0x22671f0, rp=0x226b280, exp(r,w)=0,0 rqf=01808300 rpf=00100000 rqh=0 rqt=0 rph=0 rpt=0 cs=7 ss=7, cet=0x0 set=0x0 retr=3
[1670177427] http_wait_for_response: session=0x2266a40 b=0x226b280, exp(r,w)=0,0 bf=00108000 bh=0 analysers=60000
[1670177427] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=7
si_conn_wake_cb: si=0x226f748, si->state=7 ib->flags=00400002 ob->flags=00000000
si_conn_wake_cb: si=0x2266d60, si->state=7 ib->flags=00000000 ob->flags=01808000
[1670177427] process_session:1718: task=0x226fbd0 s=0x226f4c0, sfl=0x00000080, rq=0x226fc70, rp=0x2273d00, exp(r,w)=0,0 rqf=00000002 rpf=00000000 rqh=102 rqt=0 rph=0 rpt=0 cs=7 ss=0, cet=0x0 set=0x0 retr=0
[1670177427] http_wait_for_request: session=0x226f4c0 b=0x226fc70, exp(r,w)=0,0 bf=00808002 bh=102 analysers=1c
00000002:redirector.clireq[0008:ffff]: GET / HTTP/1.1
00000002:redirector.clihdr[0008:ffff]: User-Agent: curl/7.29.0
00000002:redirector.clihdr[0008:ffff]: Host: localhost:8888
00000002:redirector.clihdr[0008:ffff]: Accept: */*
00000002:redirector.clihdr[0008:ffff]: X-Server: server.local
[1670177427] http_process_req_common: session=0x226f4c0 b=0x226fc70, exp(r,w)=0,0 bf=00808002 bh=102 analysers=10
[1670177427] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=9
si_conn_wake_cb: si=0x226f748, si->state=7 ib->flags=0080e020 ob->flags=0000c260
[1670177428] process_session:1718: task=0x226fbd0 s=0x226f4c0, sfl=0x00015480, rq=0x226fc70, rp=0x2273d00, exp(r,w)=0,0 rqf=0080e020 rpf=0000a260 rqh=0 rqt=0 rph=0 rpt=0 cs=8 ss=9, cet=0x0 set=0x0 retr=0
00000002:redirector.clicls[0008:ffff]
00000002:redirector.closed[0008:ffff]
si_conn_wake_cb: si=0x2266d60, si->state=8 ib->flags=00000023 ob->flags=0180a000
[1670177428] process_session:1718: task=0x2267150 s=0x2266a40, sfl=0x000004ce, rq=0x22671f0, rp=0x226b280, exp(r,w)=0,0 rqf=0180a000 rpf=00000023 rqh=0 rqt=0 rph=98 rpt=0 cs=7 ss=8, cet=0x0 set=0x0 retr=3
00000001:debug.srvcls[0006:0007]
[1670177428] queuing with exp=0 req->rex=0 req->wex=0 req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=0, cs=7, ss=9
si_conn_wake_cb: si=0x2266cc8, si->state=7 ib->flags=0080e020 ob->flags=0000c220
[1670177428] process_session:1718: task=0x2267150 s=0x2266a40, sfl=0x0000048e, rq=0x22671f0, rp=0x226b280, exp(r,w)=0,0 rqf=0080e020 rpf=0000a220 rqh=0 rqt=0 rph=0 rpt=0 cs=8 ss=9, cet=0x0 set=0x0 retr=3
00000001:debug.clicls[0006:0007]
00000001:debug.closed[0006:0007]
