Re: log-format & defaults section bug ?

[Willy Tarreau]

On Wed, Jan 18, 2017 at 08:14:24PM +0100, Guillaume de Lafond wrote:
> 
> 
> 
> >> defaults
> >>   log global
> >>   log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ 
> >> h=%Th/i=%Ti/R=%TR/w=%Tw/c=%Tc/r=%Tr/d=%Td/a=%Ta/t=%Tt\ %ST\ %B\ %CC\ %CS\ 
> >> %tsc\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r
> >>   modehttp
> >>   option  httplog
> > 
> > The issue is here, you are mixing "log-format" and "option httplog".
> > At first you set your custom format, but "option httplog" will reset the 
> > default one.
> > Remove "option httplog" and it should work.
> 
> Right, it works :) Thank you!
> 
> The documentation does not say anything about the conflict between the two
> variables. And my feeling while reading it, is that the ???log-format??? wins
> against the "option httplog??? even if they are in the same section.

I think we should update the doc to mention that nowadays, "option httplog"
is just an alias for "log-format something" and that as such it overrides
any previous log-format.

> Maybe we should emit a warning about the conflict as the log-format is
> silently ignored in this case or do not allow at all to have ???option
> httplog??? (or "option tcplog") with ???log-format??? in the same section. 

It's difficult to do this due to the fact that we inherit settings from
the defaults section. We don't want a frontend to emit a warning when
it uses option httplog while it had inherited the log-format from the
defaults section. However I think we could add such a warning when the
defaults section contains both since we know that by definition it does
not inherit the settings from anywhere else.

Are you interested in trying to implement this ? I think it can be done
in cfgparse.c where "httplog" is checked. There are already checks for
a previous logformat_string in order to free it, I think that we can
insert a check before this so that if curproxy ==  and
logformat_string is set, then we warn that a previous log-format was
already specified in this section and will be overridden. The same
test should be added in "tcplog" and in "log-format". In fact you
just need to search "logformat_string", there are not that many.

Thanks,
Willy

Re: Timing out FIN_WAIT_2 connections under 1.5.14

[Willy Tarreau]

Hi Richard,

On Thu, Jan 19, 2017 at 05:36:59PM +1300, Richard Gray wrote:
> $ netstat -an | grep FIN_WA | grep 122.56.198.232:26734
> tcp0  0 10.24.20.104:993122.56.198.232:26734 FIN_WAIT2
> $ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats stdio |
> grep 122.56.198.232:26734
> 0x7f906fdb7050: proto=tcpv4 src=122.56.198.232:26734
> fe=hosting-imaps_proxy-external-vip be=hosting-imaps_proxy-external-vip
> srv=imap1 ts=08 age=25m42s calls=3
> rq[f=848202h,i=0,an=00h,rx=14m45s,wx=,ax=]
> rp[f=04a020h,i=0,an=00h,rx=,wx=,ax=] s0=[7,0h,fd=6684,ex=]
> s1=[7,8h,fd=10039,ex=] exp=14m45s

Here rp.f=04a020h (CF_WROTE_DATA | CF_AUTO_CLOSE | CF_SHUTW | CF_SHUTR).
This means that the response channel was closed. Despite this exp=14m45s
so it seems to ignore timeout.client-fin. Thus I suspect we have an issue
there with the way this timeout is applied.

> >- your idea of a race is interesting. I'm wondering what happens if
> >  the connection spends more than 60s still attached to haproxy and
> >  only then becomes orphaned. It could be possible that the kernel
> >  timeout only strikes when the socket age reaches the timeout while
> >  already being orphaned.
> In my testing, I find that most of the time, 'timeout client-fin' is
> applied. HAProxy sends a FIN to the client, which acks the FIN, but does not
> send a FIN of its own. The HAProxy session moves into the client-fin timeout
> period of 30 seconds. After 30 seconds, the HAProxy session is removed. The
> FIN_WAIT2 connection state is then maintained by the kernel for
> tcp_fin_timeout of 60 seconds, before being removed altogether.

OK. So if there's a bug it's only in haproxy.

> Aha! Testing just now, and I managed to catch one.

great :-)

> To test, I open a connection to the HAProxy VIP with my python test client.
> After 3 minutes, an idle time out on the backend server causes the
> connection to be closed. My client doesn't close its end though, leaving the
> client side connection in FIN_WAIT2.
> 
> Here's the HAProxy session at 2m19s:
> 
> $ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats stdio |
> grep 146.185.142.165
> 0x7f9075ba98c0: proto=tcpv4 src=146.185.142.165:56198
> fe=hosting-imap_proxy-external-vip be=hosting-imap_proxy-external-vip
> srv=imap1 ts=08 age=2m19s calls=2 rq[f=808000h,i=0,an=00h,rx=32m41s,wx=,ax=]
> rp[f=048202h,i=0,an=00h,rx=32m41s,wx=,ax=] s0=[7,8h,fd=14490,ex=]
> s1=[7,8h,fd=14919,ex=] exp=32m41s
> 
> And then again at 3m16s after the backend has closed its side of the
> connection:
> 
> $ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats stdio |
> grep 146.185.142.165
> 0x7f9075ba98c0: proto=tcpv4 src=146.185.142.165:56198
> fe=hosting-imap_proxy-external-vip be=hosting-imap_proxy-external-vip
> srv=imap1 ts=08 age=3m16s calls=3 rq[f=808000h,i=0,an=00h,rx=31m44s,wx=,ax=]
> rp[f=04a020h,i=0,an=00h,rx=,wx=,ax=] s0=[7,0h,fd=14490,ex=]
> s1=[7,8h,fd=14919,ex=] exp=31m44s
> $ netstat -an | grep 146.185.142.165:56198
> tcp0  0 10.24.20.104:143146.185.142.165:56198 FIN_WAIT2
> 
> Note that the exp value is 31m44s, not ~14s as we'd expect if timeout
> client-fin had been applied.

Yes definitely, the same issue as above.

> To compare, here's what usually happens. At age=2m59s just before the server
> disconnection:
> 
>  $ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats stdio |
> grep 146.185.142.165
> 0x7f907f8e1ef0: proto=tcpv4 src=146.185.142.165:56202
> fe=hosting-imap_proxy-external-vip be=hosting-imap_proxy-external-vip
> srv=imap1 ts=08 age=2m59s calls=2 rq[f=808000h,i=0,an=00h,rx=32m,wx=,ax=]
> rp[f=048202h,i=0,an=00h,rx=32m,wx=,ax=] s0=[7,8h,fd=20385,ex=]
> s1=[7,8h,fd=20440,ex=] exp=32m
> 
> And then at 3m:
> 
>  $ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats stdio |
> grep 146.185.142.165
> 0x7f907f8e1ef0: proto=tcpv4 src=146.185.142.165:56202
> fe=hosting-imap_proxy-external-vip be=hosting-imap_proxy-external-vip
> srv=imap1 ts=08 age=3m calls=3 rq[f=808000h,i=0,an=00h,rx=29s,wx=,ax=]
> rp[f=04a020h,i=0,an=00h,rx=,wx=,ax=] s0=[7,0h,fd=20385,ex=]
> s1=[7,8h,fd=20440,ex=] exp=29s
> 
> Here you can see exp=29s, suggesting that the client-fin timeout has kicked
> in.

Yep. And the flags are exactly the same!

> I still don't know what causes the two different behaviours. It's quite
> difficult to trigger the abnormal behaviour in my testing (only happens
> maybe 1 time in 10), but with a session rate of up to 80/s on the production
> service, it occurs frequently.

OK, but 1/10 is already very common even for testing. My difficulties
when reproducing issues usually consists in turning some occurences
from 1/1 billion to 1/1 million so that it can be observed :-)

> I don't have enough data to back this up yet, but I wonder if network
> latency might be involved somehow. For most of today, testing from a machine
> with a 3ms RTT to the service, I was unable to reproduce the 

Re: Timing out FIN_WAIT_2 connections under 1.5.14

[Richard Gray]

On 2017-01-17 19:58, Willy Tarreau wrote:

I'm surprized that it only kicks in "sometimes". That makes me wonder
whether the problem is not here.


I'm starting to wonder if it might be related to network latency between the 
client and HAProxy. More details below.


   - it would be useful to check (using netstat -atnp) if these eternal
 FIN_WAIT2 sockets still belong to haproxy or are real orphans. I
 suspect that most of them are still attached to haproxy given your
 timeouts ; if you manage to find some very old ones still attached
 to haproxy then it would mean the issue is in haproxy.
Yes, in most cases if I select a random socket in FIN_WAIT2 from 
netstat, there will be an HAProxy session associated with that socket. e.g.


$ netstat -an | grep FIN_WA | grep 122.56.198.232:26734
tcp0  0 10.24.20.104:993122.56.198.232:26734 FIN_WAIT2
$ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats 
stdio | grep 122.56.198.232:26734
0x7f906fdb7050: proto=tcpv4 src=122.56.198.232:26734 
fe=hosting-imaps_proxy-external-vip be=hosting-imaps_proxy-external-vip 
srv=imap1 ts=08 age=25m42s calls=3 
rq[f=848202h,i=0,an=00h,rx=14m45s,wx=,ax=] 
rp[f=04a020h,i=0,an=00h,rx=,wx=,ax=] s0=[7,0h,fd=6684,ex=] 
s1=[7,8h,fd=10039,ex=] exp=14m45s



   - your idea of a race is interesting. I'm wondering what happens if
 the connection spends more than 60s still attached to haproxy and
 only then becomes orphaned. It could be possible that the kernel
 timeout only strikes when the socket age reaches the timeout while
 already being orphaned.
In my testing, I find that most of the time, 'timeout client-fin' is 
applied. HAProxy sends a FIN to the client, which acks the FIN, but does 
not send a FIN of its own. The HAProxy session moves into the client-fin 
timeout period of 30 seconds. After 30 seconds, the HAProxy session is 
removed. The FIN_WAIT2 connection state is then maintained by the kernel 
for tcp_fin_timeout of 60 seconds, before being removed altogether.


Aha! Testing just now, and I managed to catch one.

To test, I open a connection to the HAProxy VIP with my python test 
client. After 3 minutes, an idle time out on the backend server causes 
the connection to be closed. My client doesn't close its end though, 
leaving the client side connection in FIN_WAIT2.


Here's the HAProxy session at 2m19s:

$ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats 
stdio | grep 146.185.142.165
0x7f9075ba98c0: proto=tcpv4 src=146.185.142.165:56198 
fe=hosting-imap_proxy-external-vip be=hosting-imap_proxy-external-vip 
srv=imap1 ts=08 age=2m19s calls=2 
rq[f=808000h,i=0,an=00h,rx=32m41s,wx=,ax=] 
rp[f=048202h,i=0,an=00h,rx=32m41s,wx=,ax=] s0=[7,8h,fd=14490,ex=] 
s1=[7,8h,fd=14919,ex=] exp=32m41s


And then again at 3m16s after the backend has closed its side of the 
connection:


$ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats 
stdio | grep 146.185.142.165
0x7f9075ba98c0: proto=tcpv4 src=146.185.142.165:56198 
fe=hosting-imap_proxy-external-vip be=hosting-imap_proxy-external-vip 
srv=imap1 ts=08 age=3m16s calls=3 
rq[f=808000h,i=0,an=00h,rx=31m44s,wx=,ax=] 
rp[f=04a020h,i=0,an=00h,rx=,wx=,ax=] s0=[7,0h,fd=14490,ex=] 
s1=[7,8h,fd=14919,ex=] exp=31m44s

$ netstat -an | grep 146.185.142.165:56198
tcp0  0 10.24.20.104:143146.185.142.165:56198 FIN_WAIT2

Note that the exp value is 31m44s, not ~14s as we'd expect if timeout 
client-fin had been applied.


To compare, here's what usually happens. At age=2m59s just before the 
server disconnection:


 $ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats 
stdio | grep 146.185.142.165
0x7f907f8e1ef0: proto=tcpv4 src=146.185.142.165:56202 
fe=hosting-imap_proxy-external-vip be=hosting-imap_proxy-external-vip 
srv=imap1 ts=08 age=2m59s calls=2 
rq[f=808000h,i=0,an=00h,rx=32m,wx=,ax=] 
rp[f=048202h,i=0,an=00h,rx=32m,wx=,ax=] s0=[7,8h,fd=20385,ex=] 
s1=[7,8h,fd=20440,ex=] exp=32m


And then at 3m:

 $ echo "show sess" | sudo socat unix-connect:/var/lib/haproxy/stats 
stdio | grep 146.185.142.165
0x7f907f8e1ef0: proto=tcpv4 src=146.185.142.165:56202 
fe=hosting-imap_proxy-external-vip be=hosting-imap_proxy-external-vip 
srv=imap1 ts=08 age=3m calls=3 rq[f=808000h,i=0,an=00h,rx=29s,wx=,ax=] 
rp[f=04a020h,i=0,an=00h,rx=,wx=,ax=] s0=[7,0h,fd=20385,ex=] 
s1=[7,8h,fd=20440,ex=] exp=29s


Here you can see exp=29s, suggesting that the client-fin timeout has 
kicked in.


I still don't know what causes the two different behaviours. It's quite 
difficult to trigger the abnormal behaviour in my testing (only happens 
maybe 1 time in 10), but with a session rate of up to 80/s on the 
production service, it occurs frequently.


I don't have enough data to back this up yet, but I wonder if network 
latency might be involved somehow. For most of today, testing from a 
machine with a 3ms RTT to the service, I was unable to reproduce the 
problem. Just now though, I've tested 

Re: Status code "-1" in logs

[Skarbek, John]

Hey Andrew,


On January 18, 2017 at 16:11:55, Andrew Smalley 
(asmal...@loadbalancer.org) wrote:

Hello John

The problem is you are getting a 503 error or no servers available.


   503  when no server was available to handle the request, or in response to
monitoring requests which match the "monitor fail" condition


Just for clarification here, the position of 503 is in the spot where the size 
of the data transfer is.  So unless there's some awkward parsing, this 503 is 
not the error code in this case.  I don't have custom log configurations, so 
I'm sitting here assuming that the -1 is where the status code ought to be.  5 
positions of timing sperated by a '/', all of which look kinda legit 
considering the termination state.  Followed by a status code, in my case -1, 
followed by 'bytes read', in my case 503.



And the CDNN is actually two errors CD and NN


  CD   The client unexpectedly aborted during data transfer. This can be
  caused by a browser crash, by an intermediate equipment between the
  client and haproxy which decided to actively break the connection,
  by network routing issues between the client and haproxy, or by a
  keep-alive session between the server and the client terminated first
  by the client.

   NN   No cookie was provided by the client, none was inserted in the
  response. For instance, this can be in insert mode with "postonly"
  set on a GET request.


More information could be provided with a valid configuration


I hope this helps?

I took the information from the Documents available here 
http://www.haproxy.org/download/1.8/doc/configuration.txt

Regards

Andrew Smalley

Loadbalancer.org
 Ltd.



On 18 January 2017 at 21:04, Skarbek, John 
> wrote:

Good Morning,

I was spying on my logs and something out of the ordinary popped out at me. We 
are getting a status code of -1. The status CDNN is odd enough as it is… Why 
would this be?

Jan 18 13:47:18 
example.com
 Jan 18 20:47:18 haproxy[23541]: 
10.0.0.1:24550
 [18/Jan/2017:20:47:16.412] fe~ 
be/10.1.0.1:3001
 282/0/1490/-1/1824 -1 503 - - CDNN 2296/96/12/4/0 0/0 "GET /healthcheck 
HTTP/1.1"
Jan 18 13:44:01 
example.com
 Jan 18 20:44:01 haproxy[23445]: 
10.0.0.1:2650
 [18/Jan/2017:20:43:59.295] fe~ 
be/10.1.0.1:3001
 501/0/1349/-1/2079 -1 503 - - CDNN 2249/86/6/1/0 0/0 "GET /healthcheck 
HTTP/1.1"

Re: Status code "-1" in logs

[Michael Ezzell]

On Jan 18, 2017 4:06 PM, "Skarbek, John"  wrote:

Good Morning,

I was spying on my logs and something out of the ordinary popped out at me.
We are getting a status code of -1.


This (-1) is the marker for a null/nil/NaN/non-existent/inapplicable
values.  The associated timer is not applicable to this request because of
the session state at disconnect (CD).  It would be improper to log these as
0 since "0 milliseconds elapsed" is not actually true.

If you were loading the logs into a database for analyis, you'd actually
store a -1 from the log as NULL in the database so that aggregate functions
like AVG() and COUNT() will correctly exclude them.  In SQL, the AVG() of
(5, NULL, 10) is actually 7.5... while the average of (5, 0, 10) is of
course 5... so you can perhaps see the importance of having a distinct
marker for absent values.

Re: Status code "-1" in logs

[Andrew Smalley]

Hello John

The problem is you are getting a 503 error or no servers available.

   503  when no server was available to handle the request, or in response to
monitoring requests which match the "monitor fail" condition

And the CDNN is actually two errors CD and NN

  CD   The client unexpectedly aborted during data transfer. This can be
  caused by a browser crash, by an intermediate equipment between the
  client and haproxy which decided to actively break the connection,
  by network routing issues between the client and haproxy, or by a
  keep-alive session between the server and the client terminated first
  by the client.

   NN   No cookie was provided by the client, none was inserted in the
  response. For instance, this can be in insert mode with "postonly"
  set on a GET request.

More information could be provided with a valid configuration

I hope this helps?

I took the information from the Documents available here
http://www.haproxy.org/download/1.8/doc/configuration.txt

Regards

Andrew Smalley

Loadbalancer.org Ltd.



On 18 January 2017 at 21:04, Skarbek, John  wrote:

> Good Morning,
>
> I was spying on my logs and something out of the ordinary popped out at
> me. We are getting a status code of -1. The status CDNN is odd enough as
> it is… Why would this be?
>
> Jan 18 13:47:18 example.com Jan 18 20:47:18 haproxy[23541]: 10.0.0.1:24550 
> [18/Jan/2017:20:47:16.412] fe~ be/10.1.0.1:3001 282/0/1490/-1/1824 -1 503 - - 
> CDNN 2296/96/12/4/0 0/0 "GET /healthcheck HTTP/1.1"
> Jan 18 13:44:01 example.com Jan 18 20:44:01 haproxy[23445]: 10.0.0.1:2650 
> [18/Jan/2017:20:43:59.295] fe~ be/10.1.0.1:3001 501/0/1349/-1/2079 -1 503 - - 
> CDNN 2249/86/6/1/0 0/0 "GET /healthcheck HTTP/1.1"
>
>

Status code "-1" in logs

[Skarbek, John]

Good Morning,

I was spying on my logs and something out of the ordinary popped out at me. We 
are getting a status code of -1. The status CDNN is odd enough as it is… Why 
would this be?

Jan 18 13:47:18 example.com Jan 18 20:47:18 haproxy[23541]: 10.0.0.1:24550 
[18/Jan/2017:20:47:16.412] fe~ be/10.1.0.1:3001 282/0/1490/-1/1824 -1 503 - - 
CDNN 2296/96/12/4/0 0/0 "GET /healthcheck HTTP/1.1"
Jan 18 13:44:01 example.com Jan 18 20:44:01 haproxy[23445]: 10.0.0.1:2650 
[18/Jan/2017:20:43:59.295] fe~ be/10.1.0.1:3001 501/0/1349/-1/2079 -1 503 - - 
CDNN 2249/86/6/1/0 0/0 "GET /healthcheck HTTP/1.1"

Re: log-format & defaults section bug ?

[Guillaume de Lafond]

>> defaults
>>   log global
>>   log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ 
>> h=%Th/i=%Ti/R=%TR/w=%Tw/c=%Tc/r=%Tr/d=%Td/a=%Ta/t=%Tt\ %ST\ %B\ %CC\ %CS\ 
>> %tsc\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r
>>   modehttp
>>   option  httplog
> 
> The issue is here, you are mixing "log-format" and "option httplog".
> At first you set your custom format, but "option httplog" will reset the 
> default one.
> Remove "option httplog" and it should work.

Right, it works :) Thank you!

The documentation does not say anything about the conflict between the two 
variables. And my feeling while reading it, is that the “log-format” wins 
against the "option httplog” even if they are in the same section.

Maybe we should emit a warning about the conflict as the log-format is silently 
ignored in this case or do not allow at all to have “option httplog” (or 
"option tcplog") with “log-format” in the same section. 
Any thought on this ?

-- 
de Lafond Guillaume

Re: log-format & defaults section bug ?

[Cyril Bonté]

Hi Guillaume,

Le 18/01/2017 à 15:02, de Lafond Guillaume a écrit :

Hello,

It seems that the log-format defined in the “defaults” section is ignored.

==
global
   log /dev/loglocal0
   chroot /var/lib/haproxy
   stats socket /run/haproxy/admin.sock mode 660 level admin
   stats timeout 30s
   user haproxy
   group haproxy
   daemon

defaults
   log global
   log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ 
h=%Th/i=%Ti/R=%TR/w=%Tw/c=%Tc/r=%Tr/d=%Td/a=%Ta/t=%Tt\ %ST\ %B\ %CC\ %CS\ %tsc\ 
%ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r
   modehttp
   option  httplog


The issue is here, you are mixing "log-format" and "option httplog".
At first you set your custom format, but "option httplog" will reset the 
default one.

Remove "option httplog" and it should work.


   option  dontlognull
   timeout connect 5000
   timeout client  5
   timeout server  5

frontend ft
   bind *:80
   default_backend bk
backend bk
   server web1 127.0.0.1:81
==
This config does not use my log-format for the "listen" section
=> Jan 18 14:25:56 nb-ha2 haproxy[31956]: :61226 [18/Jan/2017:14:25:53.484] ft 
ft/web1 0/0/-1/-1/3003 503 212 - - SC-- 0/0/0/0/3 0/0 "GET / HTTP/1.1"


==
global
   log /dev/loglocal0
   chroot /var/lib/haproxy
   stats socket /run/haproxy/admin.sock mode 660 level admin
   stats timeout 30s
   user haproxy
   group haproxy
   daemon

defaults
   log global
   modehttp
   option  httplog
   option  dontlognull
   timeout connect 5000
   timeout client  5
   timeout server  5

frontend ft
   bind *:80
   default_backend bk
   log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ 
h=%Th/i=%Ti/R=%TR/w=%Tw/c=%Tc/r=%Tr/d=%Td/a=%Ta/t=%Tt\ %ST\ %B\ %CC\ %CS\ %tsc\ 
%ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r


Here, it was working because, first "option httplog" set the default log 
format, then you specify the custom one.



backend bk
   server web1 127.0.0.1:81
==
But of course, this one works.
Jan 18 14:26:16 nb-ha2 haproxy[31984]: XXX:61248 [18/Jan/2017:14:26:13.449] ft 
ft/web1 h=0/i=1/R=0/w=0/c=-1/r=-1/d=-1/a=3003/t=3004 503 212 - - SC-- 0/0/0/0/3 0/0 
"GET / HTTP/1.1"

Is there a mistake in my config ? or it is a bug with log-format in defaults ?
I get the same problem if I use a “listen” section instead of a 
“frontend/backend” sections.

I tried the debian jessie-backports version and the latest git version :
==
ha1:~# haproxy -vvv
HA-Proxy version 1.7.1-1~bpo8+1 2016/12/17
Copyright 2000-2016 Willy Tarreau 

Build options :
 TARGET  = linux2628
 CPU = generic
 CC  = gcc
 CFLAGS  = -g -O2 -fPIE -fstack-protector-strong -Wformat 
-Werror=format-security -D_FORTIFY_SOURCE=2
 OPTIONS = USE_ZLIB=1 USE_REGPARM=1 USE_OPENSSL=1 USE_LUA=1 USE_PCRE=1 USE_NS=1

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

Encrypted password support via crypt(3): yes
Built with zlib version : 1.2.8
Running on zlib version : 1.2.8
Compression algorithms supported : identity("identity"), deflate("deflate"), 
raw-deflate("deflate"), gzip("gzip")
Built with OpenSSL version : OpenSSL 1.0.2j  26 Sep 2016
Running on OpenSSL version : OpenSSL 1.0.2j  26 Sep 2016
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports prefer-server-ciphers : yes
Built with PCRE version : 8.35 2014-04-04
Running on PCRE version : 8.35 2014-04-04
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Built with Lua version : Lua 5.3.1
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT 
IP_FREEBIND
Built with network namespace support

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.

Available filters :
[COMP] compression
[TRACE] trace
[SPOE] spoe
==
HA-Proxy version 1.8-dev0-439729-165 2017/01/16
Copyright 2000-2016 Willy Tarreau 

Build options :
  TARGET  = generic
  CPU = generic
  CC  = gcc
  CFLAGS  = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement
  OPTIONS =

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

Built with transparent proxy support using: IP_TRANSPARENT IP_FREEBIND
Built with network namespace support.
Built without compression support (neither USE_ZLIB nor USE_SLZ are set).
Compression algorithms supported : identity("identity")
Encrypted password support via crypt(3): yes
Built without PCRE or PCRE2 

log-format & defaults section bug ?

[de Lafond Guillaume]

Hello,

It seems that the log-format defined in the “defaults” section is ignored.

==
global
   log /dev/loglocal0
   chroot /var/lib/haproxy
   stats socket /run/haproxy/admin.sock mode 660 level admin
   stats timeout 30s
   user haproxy
   group haproxy
   daemon

defaults
   log global
   log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ 
h=%Th/i=%Ti/R=%TR/w=%Tw/c=%Tc/r=%Tr/d=%Td/a=%Ta/t=%Tt\ %ST\ %B\ %CC\ %CS\ %tsc\ 
%ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r
   modehttp
   option  httplog
   option  dontlognull
   timeout connect 5000
   timeout client  5
   timeout server  5

frontend ft
   bind *:80
   default_backend bk
backend bk
   server web1 127.0.0.1:81
==
This config does not use my log-format for the "listen" section
=> Jan 18 14:25:56 nb-ha2 haproxy[31956]: :61226 
[18/Jan/2017:14:25:53.484] ft ft/web1 0/0/-1/-1/3003 503 212 - - SC-- 0/0/0/0/3 
0/0 "GET / HTTP/1.1"


==
global
   log /dev/loglocal0
   chroot /var/lib/haproxy
   stats socket /run/haproxy/admin.sock mode 660 level admin
   stats timeout 30s
   user haproxy
   group haproxy
   daemon

defaults
   log global
   modehttp
   option  httplog
   option  dontlognull
   timeout connect 5000
   timeout client  5
   timeout server  5

frontend ft
   bind *:80
   default_backend bk
   log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ 
h=%Th/i=%Ti/R=%TR/w=%Tw/c=%Tc/r=%Tr/d=%Td/a=%Ta/t=%Tt\ %ST\ %B\ %CC\ %CS\ %tsc\ 
%ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r
backend bk
   server web1 127.0.0.1:81
==
But of course, this one works.
Jan 18 14:26:16 nb-ha2 haproxy[31984]: XXX:61248 [18/Jan/2017:14:26:13.449] 
ft ft/web1 h=0/i=1/R=0/w=0/c=-1/r=-1/d=-1/a=3003/t=3004 503 212 - - SC-- 
0/0/0/0/3 0/0 "GET / HTTP/1.1"

Is there a mistake in my config ? or it is a bug with log-format in defaults ?
I get the same problem if I use a “listen” section instead of a 
“frontend/backend” sections.

I tried the debian jessie-backports version and the latest git version : 
==
ha1:~# haproxy -vvv
HA-Proxy version 1.7.1-1~bpo8+1 2016/12/17
Copyright 2000-2016 Willy Tarreau 

Build options :
 TARGET  = linux2628
 CPU = generic
 CC  = gcc
 CFLAGS  = -g -O2 -fPIE -fstack-protector-strong -Wformat 
-Werror=format-security -D_FORTIFY_SOURCE=2
 OPTIONS = USE_ZLIB=1 USE_REGPARM=1 USE_OPENSSL=1 USE_LUA=1 USE_PCRE=1 USE_NS=1

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

Encrypted password support via crypt(3): yes
Built with zlib version : 1.2.8
Running on zlib version : 1.2.8
Compression algorithms supported : identity("identity"), deflate("deflate"), 
raw-deflate("deflate"), gzip("gzip")
Built with OpenSSL version : OpenSSL 1.0.2j  26 Sep 2016
Running on OpenSSL version : OpenSSL 1.0.2j  26 Sep 2016
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports prefer-server-ciphers : yes
Built with PCRE version : 8.35 2014-04-04
Running on PCRE version : 8.35 2014-04-04
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Built with Lua version : Lua 5.3.1
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT 
IP_FREEBIND
Built with network namespace support

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.

Available filters :
[COMP] compression
[TRACE] trace
[SPOE] spoe
==
HA-Proxy version 1.8-dev0-439729-165 2017/01/16
Copyright 2000-2016 Willy Tarreau 

Build options :
  TARGET  = generic
  CPU = generic
  CC  = gcc
  CFLAGS  = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement
  OPTIONS = 

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

Built with transparent proxy support using: IP_TRANSPARENT IP_FREEBIND
Built with network namespace support.
Built without compression support (neither USE_ZLIB nor USE_SLZ are set).
Compression algorithms supported : identity("identity")
Encrypted password support via crypt(3): yes
Built without PCRE or PCRE2 support (using libc's regex instead)

Available polling systems :
   poll : pref=200,  test result OK
 select : pref=150,  test result OK
Total: 2 (2 usable), will use poll.

Available filters :
[SPOE] spoe
[COMP] compression
[TRACE] trace
==




Thank you.

Re: Getting Client IP to backend instance application

[Aaron West]

Hi Viranga,

Can I check if you've configured your backend web servers to use either the
X-Forwarded-For or X-Client-IP header in your logging?

Normally you would need to do something like the following:

http://www.loadbalancer.org/blog/iis-and-x-forwarded-for-header
http://www.loadbalancer.org/blog/apache-and-x-forwarded-for-headers

Otherwise without understanding your traffic flow it would appear correct,
it's worth bearing in mind that XFF headers will usually contain the client
IP followed by each successive proxy the connection went through so check
it if contains multiple addresses.

Aaron West

Loadbalancer.org Limited
+44 (0)330 380 1064
www.loadbalancer.org

On 18 January 2017 at 03:38, Jayalath, Viranga  wrote:

> Hi Haproxy team ,
>
> I have a question. I have a backed instance which attached to haproxy
> instance. I have requirement to get client  IP in my nodejs application
> logs . But how ever im getting the haproxy IP. I refer all your x forwarder
> options can use to get client ip but still im getting the haproxy server ip
> in my logs. Can you advice any thing i can do .  Below you i will mentioned
> configuration changes i used.
>
> # add X-FORWARDED-FOR
> option forwardfor
> # add X-CLIENT-IP
> http-request add-header X-CLIENT-IP %[src]
>
>
> --
> Best Regards,
>
> Viranga Jayalath
> DevOps and Application Engineering,Cloud Services Technology Operations
>
> Pearson Lanka (Pvt) Ltd.
> Technology Operations
> Orion City, Alnitak Building
> No. 752, Dr. Danister De Silva Mawatha
> Sri Lanka
>
>
> *M*  +94 (0) 714 672980 <+94%2071%20467%202980>
>
> Learn more at *pearson.com *
>
> *ALWAYS LEARNING*
>