Re: Debug mode not working?!

2015-11-09 Thread Willy Tarreau
On Mon, Nov 09, 2015 at 10:15:46PM +0100, Aleksandar Lazic wrote:
> 
> ...
> epoll_wait(3, {}, 200, 1000)= 0
> epoll_wait(3, {{EPOLLIN, {u32=5, u64=5}}}, 200, 1000) = 1
> accept4(5, {sa_family=AF_INET, sin_port=htons(52310), 
> sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 7
> setsockopt(7, SOL_TCP, TCP_NODELAY, [1], 4) = 0
> accept4(5, 0x7ffca18022c0, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource 
> temporarily unavailable)
> recvfrom(7, "GET / HTTP/1.1\r\nUser-Agent: curl/7.22.0 
> (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 
> libidn/1.23 librtmp/2.3\r\nHost: 127.0.0.1:7992\r\nAccept: */*\r\n\r\n", 
> 16384, MSG_PEEK, NULL, NULL) = 166
> close(7)= 0
> epoll_wait(3, {}, 200, 1000)= 0
> ...
> 

It was aborted very early, I think it even didn't become a session,
though I could be wrong. You need a session for a minimum of debugging
to work.

(...)
> Other terminal.
> 
> 
> curl -vk http://127.0.0.1:7992/
> * About to connect() to 127.0.0.1 port 7992 (#0)
> *   Trying 127.0.0.1... connected
> >GET / HTTP/1.1
> >User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 
> >OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> >Host: 127.0.0.1:7992
> >Accept: */*
> >
> * Recv failure: Connection reset by peer
> * Closing connection #0
> curl: (56) Recv failure: Connection reset by peer
> 

Confirmed here.

Willy




Re: Debug mode not working?!

2015-11-09 Thread Aleksandar Lazic



Am 09-11-2015 11:34, schrieb Willy Tarreau:

Hi Aleks,

On Sun, Nov 08, 2015 at 04:24:29PM +0100, Aleksandar Lazic wrote:

Hi.

Today I have tried to debug haproxy as in the old days ;-), I was not
able to see the communication on stderr.

I'm sure I have something missed in the past on the list to be able to
see the output.


I use it every day and I just retested, it still works for me. Are you
sure you don't have another instance still listening to the same port
and receiving the traffic ? It already happened to me a few times,
reason why I'm asking :-)


Thanks. I also tough like this but no the request reaches the right 
instanze.


export MONITOR_BIND_PORT=7991 && export HTTP_BIND_PORT=7992  && export 
HTTPS_BIND_PORT=7993 && strace -fveall -s1024 haproxy-1.6.2/haproxy -f 
haproxy.conf -d -V



...
epoll_wait(3, {}, 200, 1000)= 0
epoll_wait(3, {{EPOLLIN, {u32=5, u64=5}}}, 200, 1000) = 1
accept4(5, {sa_family=AF_INET, sin_port=htons(52310), 
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 7

setsockopt(7, SOL_TCP, TCP_NODELAY, [1], 4) = 0
accept4(5, 0x7ffca18022c0, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource 
temporarily unavailable)
recvfrom(7, "GET / HTTP/1.1\r\nUser-Agent: curl/7.22.0 
(x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 
libidn/1.23 librtmp/2.3\r\nHost: 127.0.0.1:7992\r\nAccept: */*\r\n\r\n", 
16384, MSG_PEEK, NULL, NULL) = 166

close(7)= 0
epoll_wait(3, {}, 200, 1000)= 0
...


Other terminal.


curl -vk http://127.0.0.1:7992/
* About to connect() to 127.0.0.1 port 7992 (#0)
*   Trying 127.0.0.1... connected

GET / HTTP/1.1
User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 
OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3

Host: 127.0.0.1:7992
Accept: */*


* Recv failure: Connection reset by peer
* Closing connection #0
curl: (56) Recv failure: Connection reset by peer


gcc --version
gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3
Copyright (C) 2011 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is 
NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR 
PURPOSE.



Willy




Re: Debug mode not working?!

2015-11-09 Thread Aleksandar Lazic



Am 09-11-2015 22:21, schrieb Willy Tarreau:

On Mon, Nov 09, 2015 at 10:15:46PM +0100, Aleksandar Lazic wrote:


...
epoll_wait(3, {}, 200, 1000)= 0
epoll_wait(3, {{EPOLLIN, {u32=5, u64=5}}}, 200, 1000) = 1
accept4(5, {sa_family=AF_INET, sin_port=htons(52310),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 7
setsockopt(7, SOL_TCP, TCP_NODELAY, [1], 4) = 0
accept4(5, 0x7ffca18022c0, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource
temporarily unavailable)
recvfrom(7, "GET / HTTP/1.1\r\nUser-Agent: curl/7.22.0
(x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4
libidn/1.23 librtmp/2.3\r\nHost: 127.0.0.1:7992\r\nAccept: 
*/*\r\n\r\n",

16384, MSG_PEEK, NULL, NULL) = 166
close(7)= 0
epoll_wait(3, {}, 200, 1000)= 0
...



It was aborted very early, I think it even didn't become a session,
though I could be wrong. You need a session for a minimum of debugging
to work.

(...)

Other terminal.


curl -vk http://127.0.0.1:7992/
* About to connect() to 127.0.0.1 port 7992 (#0)
*   Trying 127.0.0.1... connected
>GET / HTTP/1.1
>User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0
>OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
>Host: 127.0.0.1:7992
>Accept: */*
>
* Recv failure: Connection reset by peer
* Closing connection #0
curl: (56) Recv failure: Connection reset by peer



Confirmed here.


Okay after removing accept-proxy from

bind *:${HTTP_BIND_PORT} accept-proxy tfo

It comes what expected.

Using epoll() as the polling mechanism.
:http-in.accept(0005)=0007 from [127.0.0.1:53420]
[3995514114] process_stream:1662: task=0xa27410 s=0xa59600, 
sfl=0x0080, rq=0xa59610, rp=0xa59650, exp(r,w)=0,0 rqf=00908002 
rpf=8000 rqh=166 rqt=0 rph=0 rpt=0 cs=7 ss=0, cet=0x0 set=0x0 retr=0
[3995514114] tcp_inspect_request: stream=0xa59600 b=0xa59610, 
exp(r,w)=0,0 bf=00908002 bh=166 analysers=36
[3995514114] http_wait_for_request: stream=0xa59600 b=0xa59610, 
exp(r,w)=0,0 bf=00908002 bh=166 analysers=34

:http-in.clireq[0007:]: GET / HTTP/1.1
:http-in.clihdr[0007:]: User-Agent: curl/7.22.0 
(x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 
libidn/1.23 librtmp/2.3

:http-in.clihdr[0007:]: Host: 127.0.0.1:7992
:http-in.clihdr[0007:]: Accept: */*
[3995514114] http_process_req_common: stream=0xa59600 b=0xa59610, 
exp(r,w)=0,0 bf=00908002 bh=166 analysers=30
[3995514114] process_switching_rules: stream=0xa59600 b=0xa59610, 
exp(r,w)=0,0 bf=04908002 bh=166 analysers=00
[3995514114] http_process_req_common: stream=0xa59600 b=0xa59610, 
exp(r,w)=0,0 bf=04908002 bh=166 analysers=280
[3995514114] http_process_request: stream=0xa59600 b=0xa59610, 
exp(r,w)=0,0 bf=04908002 bh=166 analysers=200
[3995514114] sess_prepare_conn_req: sess=0xa59600 rq=0xa59610, 
rp=0xa59650, exp(r,w)=0,0 rqf=0492 rpf=8000 rqh=0 rqt=194 rph=0 
rpt=0 cs=7 ss=1

assign_server : s=0xa59600
[3995514114] sess_update_stream_int: sess=0xa59600 rq=0xa59610, 
rp=0xa59650, exp(r,w)=0,0 rqf=0492 rpf=8000 rqh=0 rqt=194 rph=0 
rpt=0 cs=7 ss=4

assign_server_address : s=0xa59600
[3995514114] queuing with exp=3995519114 req->rex=3995544114 req->wex=0 
req->ana_exp=0 rep->rex=0 rep->wex=0, si[0].exp=0, si[1].exp=3995519114, 
cs=7, ss=5
[3995514115] process_stream:1662: task=0xa27410 s=0xa59600, 
sfl=0x04ce, rq=0xa59610, rp=0xa59650, exp(r,w)=3995544114,0 
rqf=00840300 rpf=8050 rqh=0 rqt=0 rph=0 rpt=0 cs=7 ss=7, cet=0x0 
set=0x0 retr=3
[3995514115] http_wait_for_response: stream=0xa59600 b=0xa59650, 
exp(r,w)=0,0 bf=80508000 bh=0 analysers=6
[3995514115] queuing with exp=3995544115 req->rex=0 req->wex=0 
req->ana_exp=0 rep->rex=3995544115 rep->wex=0, si[0].exp=0, si[1].exp=0, 
cs=7, ss=7
[3995514115] process_stream:1662: task=0xa27410 s=0xa59600, 
sfl=0x04ce, rq=0xa59610, rp=0xa59650, exp(r,w)=0,0 rqf=0084 
rpf=8002 rqh=0 rqt=0 rph= rpt=0 cs=7 ss=7, cet=0x0 set=0x0 
retr=3
[3995514115] http_wait_for_response: stream=0xa59600 b=0xa59650, 
exp(r,w)=0,0 bf=80008002 bh= analysers=6

:.srvrep[0007:0008]: HTTP/1.1 200 OK
:.srvhdr[0007:0008]: Server: nginx/1.9.6
:.srvhdr[0007:0008]: Date: Mon, 09 Nov 2015 21:28:45 GMT
:.srvhdr[0007:0008]: Content-Type: text/html
:.srvhdr[0007:0008]: Content-Length: 3095
:.srvhdr[0007:0008]: Last-Modified: Wed, 18 Jan 2012 
10:17:45 GMT

:.srvhdr[0007:0008]: Connection: keep-alive
:.srvhdr[0007:0008]: ETag: "4f169c49-c17"
:.srvhdr[0007:0008]: Accept-Ranges: bytes
[3995514115] http_process_res_common: stream=0xa59600 b=0xa59650, 
exp(r,w)=0,0 bf=80008002 bh=3309 analysers=4
[3995514115] tcp_inspect_request: stream=0xa59600 b=0xa59610, 
exp(r,w)=0,0 bf=00c08000 bh=0 analysers=36
[3995514115] queuing with exp=3995519115 req->rex=3995544115 req->wex=0 
req->ana_exp=3995519115 rep->rex=0 rep->wex=3995544115, 

Re: Debug mode not working?!

2015-11-09 Thread Nenad Merdanovic
Hello Aleksandar,

> Okay after removing accept-proxy from
> 
> bind *:${HTTP_BIND_PORT} accept-proxy tfo
> 
> It comes what expected.

If you are using 'accept-proxy', HAproxy expects the payload to start
with a PROXY protocol header.

http://www.haproxy.org/download/1.6/doc/proxy-protocol.txt

Regards,
Nenad



Re: Debug mode not working?!

2015-11-09 Thread Aleksandar Lazic

Hi Nenad,

Am 09-11-2015 22:52, schrieb Nenad Merdanovic:

Hello Aleksandar,


Okay after removing accept-proxy from

bind *:${HTTP_BIND_PORT} accept-proxy tfo

It comes what expected.


If you are using 'accept-proxy', HAproxy expects the payload to start
with a PROXY protocol header.

http://www.haproxy.org/download/1.6/doc/proxy-protocol.txt


Full Ack.

maybe it would be helpfull to write out something like.

PROXY protocol expected but not found

in src/connection.c:conn_recv_proxy() or in conn_fd_handler() if no 
proxy protocol comes.


BR Aleks




Re: Debug mode not working?!

2015-11-09 Thread Willy Tarreau
Hi Aleks,

On Sun, Nov 08, 2015 at 04:24:29PM +0100, Aleksandar Lazic wrote:
> Hi.
> 
> Today I have tried to debug haproxy as in the old days ;-), I was not 
> able to see the communication on stderr.
> 
> I'm sure I have something missed in the past on the list to be able to 
> see the output.

I use it every day and I just retested, it still works for me. Are you
sure you don't have another instance still listening to the same port
and receiving the traffic ? It already happened to me a few times,
reason why I'm asking :-)

Willy