Long pauses observed in haproxy logs


#1

Hi,
I am trying to investigate a application hang where the communication from our app goes through haproxy to the backend database. I was hoping someone could shed some light on what the debug logging means…

During a normal request, I see this:
Aug 26 17:24:42 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033a:ft_postgresql.accept(0005)=0013 from [169.44.114.101:49006]
Aug 26 17:24:42 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033a:bk_db.srvcls[0013:0014]
Aug 26 17:24:42 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033a:bk_db.clicls[0013:0014]
Aug 26 17:24:42 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033a:bk_db.closed[0013:0014]

But during the 3minute hang, I see this:
Aug 26 17:24:42 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033b:ft_postgresql.accept(0005)=0013 from [169.44.114.101:49060]
Aug 26 17:25:09 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033c:ft_postgresql.accept(0005)=0016 from [169.44.14.147:37628]
Aug 26 17:25:09 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033d:ft_postgresql.accept(0005)=0017 from [169.44.14.147:37629]
Aug 26 17:25:40 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033e:ft_postgresql.accept(0005)=0024 from [169.44.14.147:42686]
Aug 26 17:25:40 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033f:ft_postgresql.accept(0005)=0026 from [169.44.14.147:42688]
Aug 26 17:27:01 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000340:GLOBAL.srvcls[0028:ffffffff]
Aug 26 17:27:01 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000340:GLOBAL.clicls[0028:ffffffff]
Aug 26 17:27:01 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000340:GLOBAL.closed[0028:ffffffff]
Aug 26 17:27:28 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033f:bk_db.srvcls[0026:0027]
Aug 26 17:27:28 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033f:bk_db.clicls[0026:0027]
Aug 26 17:27:28 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033f:bk_db.closed[0026:0027]
Aug 26 17:27:28 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000013:bk_db.srvcls[0029:002b]
Aug 26 17:27:28 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000013:bk_db.clicls[0029:002b]
Aug 26 17:27:28 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000013:bk_db.closed[0029:002b]
Aug 26 17:27:41 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033c:bk_db.srvcls[0016:0020]
Aug 26 17:27:41 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033c:bk_db.clicls[0016:0020]
Aug 26 17:27:41 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033c:bk_db.closed[0016:0020]
Aug 26 17:27:41 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000018:bk_db.srvcls[000a:000b]
Aug 26 17:27:41 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000018:bk_db.clicls[000a:000b]
Aug 26 17:27:41 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m00000018:bk_db.closed[000a:000b]
Aug 26 17:28:20 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033b:bk_db.srvcls[0013:0014]
Aug 26 17:28:20 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033b:bk_db.clicls[0013:0014]
Aug 26 17:28:20 orion-lt-01-ibm-292 haproxy29: e[0;36;1mhaproxy.1 | e[0m0000033b:bk_db.closed[0013:0014]

Can someone interpret this logging and let me know what haproxy is doing during this time?

Thanks!


#2

The debug output is quite useless, please configure http logging instead and provide that output.