Re: Debug mode not working?!

[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?!

[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?!

[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?!

[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?!

[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?!

[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

Debug mode not working?!

[Aleksandar Lazic]

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.


My steps.

curl -vO http://www.haproxy.org/download/1.6/src/haproxy-1.6.2.tar.gz
tar xfvz haproxy-1.6.2.tar.gz
cd haproxy-1.6.2/
make TARGET=linux2628 DEBUG=-DDEBUG_FULL USE_PCRE=1 USE_OPENSSL=1 
USE_ZLIB=1 USE_LINUX_SPLICE=1 USE_TFO=1 all

cd ../

export MONITOR_BIND_PORT=7991
export HTTP_BIND_PORT=7992
export HTTPS_BIND_PORT=7993

#
haproxy-1.6.2/haproxy -f haproxy.conf -d -V
Sharing sig_handlers with pipe
Sharing pendconn with pipe
Sharing uniqueid with session
Sharing capture with vars
Available polling systems :
  epoll : pref=300,  test result OK
   poll : pref=200,  test result OK
 select : pref=150,  test result OK
Total: 3 (3 usable), will use epoll.
Using epoll() as the polling mechanism.
[NO MORE OUTPUT AFTER CURL CALL]
#

I connected from another Terminal to this haproxy with curl.

##
LANG=C curl -vk http://xx.xx.xx.xx:7992/
*   Trying xx.xx.xx.xx...
* Connected to xx.xx.xx.xx5 (xx.xx.xx.xx) port 7992 (#0)

GET / HTTP/1.1
Host: xx.xx.xx.xx:7992
User-Agent: curl/7.45.0
Accept: */*


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

Please can anyone tell me what I have missed, thanks.

#

haproxy-1.6.2/haproxy -vv
Sharing sig_handlers with pipe
Sharing pendconn with pipe
Sharing uniqueid with session
HA-Proxy version 1.6.2 2015/11/03
Copyright 2000-2015 Willy Tarreau 

Build options :
  TARGET  = linux2628
  CPU = generic
  CC  = gcc
  CFLAGS  = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement
  OPTIONS = USE_LINUX_SPLICE=1 USE_ZLIB=1 USE_OPENSSL=1 USE_PCRE=1 
USE_TFO=1


Default settings :
  maxconn = 2000, bufsize = 16384, maxrewrite = 1024, maxpollevents = 
200


Encrypted password support via crypt(3): yes
Built with zlib version : 1.2.3.4
Compression algorithms supported : identity("identity"), 
deflate("deflate"), raw-deflate("deflate"), gzip("gzip")

Built with OpenSSL version : OpenSSL 1.0.2d 9 Jul 2015
Running on OpenSSL version : OpenSSL 1.0.2d 9 Jul 2015
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports prefer-server-ciphers : yes
Built with PCRE version : 8.12 2011-01-15
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Built without Lua support
Built with transparent proxy support using: IP_TRANSPARENT 
IPV6_TRANSPARENT IP_FREEBIND


Available polling systems :
  epoll : pref=300,  test result OK
   poll : pref=200,  test result OK
 select : pref=150,  test result OK
Total: 3 (3 usable), will use epoll.
Using epoll() as the polling mechanism.

cat haproxy.conf
#
# please read the manual
# http://www.haproxy.org/#docs

global


  debug
  # no daemon!
  # don't use gid, uid, group or user on openshift

  ca-base .
  crt-base .

  # in docker or openshift?
  # log

  # Name of the POD or Service or ...
  # log-send-hostname
  # log-tag
  # node

  # it's magic ;-)
  ssl-default-bind-ciphers 
EECDH+ECDSA+AESGCM:EECDH+ECDSA+SHA384::EECDH+ECDSA+SHA256:EECDH+aRSA+SHA384:EECDH+aRSA+SHA256:EECDH:EDH+aRSA:!SHA-1:!RC4:!aNULL:!eNULL:!MEDIUM:!LOW:!3DES:!MD5:!EXP:!PSK:!SRP:!DSS:@STRENGTH


  ssl-default-bind-options no-sslv3

  ssl-default-server-ciphers 
EECDH+ECDSA+AESGCM:EECDH+ECDSA+SHA384::EECDH+ECDSA+SHA256:EECDH+aRSA+SHA384:EECDH+aRSA+SHA256:EECDH:EDH+aRSA:!SHA-1:!RC4:!aNULL:!eNULL:!MEDIUM:!LOW:!3DES:!MD5:!EXP:!PSK:!SRP:!DSS:@STRENGTH


  ssl-default-server-options no-sslv3

  # this file is created at build time!
  # openssl dhparam -out /usr/local/etc/haproxy/ssl/dh-param_4096 4096
  ssl-dh-param-file dh-param_4096

  # ssl-server-verify default is required

  # perf tun
  # I think this values should be carefully changed, in case you need to 
change it!


  maxconn 100
  # maxconnrate
  # maxpipes
  # maxsessrate
  # maxsslconn
  # maxsslrate

  # defaults to 2
  # tune.ssl.cachesize

  # default defaults to 300 (5 min)
  # tune.ssl.lifetime

  # greater than  1024 bits are not supported
  # by Java 7 and earlier clients
  # tune.ssl.default-dh-param 4096

# peers !!
# peers ssl-sessions
#   Service disovering for the other haproxies in the cloud
#   peer  :

listen haproxy-monitor
  bind *:${MONITOR_BIND_PORT}
  mode health
  option httpchk

defaults
  timeout connect 5s
  timeout client 30s
  timeout server 30s

  # Long timeout for WebSocket connections.
  timeout tunnel 1h

  # balance ?
  # rate-limit sessions
  option forwardfor
  option http-ignore-probes
  option splice-auto
  option log-separate-errors
  option ssl-hello-chk

frontend http-in
  bind *:${HTTP_BIND_PORT} accept-proxy tfo
  mode http

  tcp-request inspect-delay 5s
  tcp-request content accept if HTTP

  use_backend test01

frontend https-in