HAProxy not logging all requests

Question

I've setup a HAProxy on Ubuntu 14.04 running a seperate backend server also on Ubuntu 14.04 and Apache2.

When performing requests not all those requests are logged. Even when running HAProxy in debug mode it does not show all requests on the terminal.

I have an index.html which includes an image. When requesting the page with Google Chrome I can see in the inspector that in total 3 files are requested (index.html, header.gif and favicon.ico).

HAProxy however will only log the actual request for index.html and if I reload the page very fast it will not even log all requests for index.html.

I did try to debug using socat but there were no errors logged via that way. I did try to set the log format to tcplog but that didn't help either, not all requests were logged.

What am I doing wrong?

rsyslogd configuration:

$ModLoad imudp
$UDPServerAddress 127.0.0.1
$UDPServerRun 514

local0.* -/var/log/haproxy/haproxy.log

& ~

HAProxy configuration:

global
  log 127.0.0.1 local0
  log-send-hostname
  daemon
  maxconn 256
  stats socket    /tmp/haproxy

defaults
  log global
  timeout connect 5000ms
  timeout client 50000ms
  timeout server 50000ms

frontend http-in
  mode http
  option httplog
  # bind to all ip's port 9200
  bind 0.0.0.0:80
  default_backend http-out

backend http-out
  mode http
  balance leastconn
  server web2 xxx.xxx.xxx.xxx:80

haproxy log

  Sep 17 14:38:16 front2.xxx.net haproxy[5436]: xxx.xxx.xxx.xxx:61745 [17/Sep/2015:14:38:06.771] http-in http-in/ -1/-1/-1/-1/10000 400 187 - - CR-- 2/2/0/0/0 0/0 ""
  Sep 17 14:38:16 front2.xxx.net haproxy[5436]: xxx.xxx.xxx.xxx:61744 [17/Sep/2015:14:38:06.771] http-in http-out/web2 0/0/1/2/10001 200 23198 - - ---- 1/1/0/0/0 0/0 "GET /index.html HTTP/1.1"
  Sep 17 14:38:26 front2.xxx.net haproxy[5436]: xxx.xxx.xxx.xxx:61746 [17/Sep/2015:14:38:06.772] http-in http-in/ -1/-1/-1/-1/20000 400 187 - - CR-- 0/0/0/0/0 0/0 ""

apache2 log

  registered.xxx.net:80 185.92.61.11 - - [17/Sep/2015:14:38:06 +0200] "GET /index.html HTTP/1.1" 200 1192 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/45.0.2454.93 Safari/537.36"
  registered.xxx.net:80 185.92.61.11 - - [17/Sep/2015:14:38:06 +0200] "GET /header.gif HTTP/1.1" 200 4145 "http://xxx.xxx.xxx.xxx/index.html" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/45.0.2454.93 Safari/537.36"
  registered.xxx.net:80 185.92.61.11 - - [17/Sep/2015:14:38:06 +0200] "GET /favicon.ico HTTP/1.1" 200 17861 "http://xxx.xxx.xxx.xxx/index.html" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/45.0.2454.93 Safari/537.36"

Answer 1

With all HAProxy versions prior to 1.5-dev22, when used in mode http, it worked in the tunnel "sub-mode" if no other "sub-mode" was specified. I realize there's not actually such a thing as a "sub-mode" in HAProxy, but I'm not sure what else to call it. The docs just use the word 'mode', but I find that even more confusing...

In any event, in tunnel "sub-mode" only the first request and response are processed, and everything else is forwarded with no analysis at all. This mode should not be used as it creates lots of trouble with logging and HTTP processing.

As of 1.5-dev22, the default "sub-mode" was changed from tunnel to keep alive, meaning that all requests and responses are processed, and connections remain open but idle between responses and new requests.

This can be changed by using the option http-keep-alive, option http-tunnel, option httpclose, option http-server-close and option forceclose keywords in frontends and backends, with the effective mode (or "sub-mode" if you will) being outlined in the docs. Under section 4, there's a table that shows the effective "sub-mode" based on which options are set in the frontend and backed used for a particular connection.

For completeness, here's the relevant section of the docs, including the table and it's various "sub-modes", as it exists at the time of this writing (1.5.14):

In HTTP mode, the processing applied to requests and responses flowing over
a connection depends in the combination of the frontend's HTTP options and
the backend's. HAProxy supports 5 connection modes :

  - KAL : keep alive ("option http-keep-alive") which is the default mode : all
    requests and responses are processed, and connections remain open but idle
    between responses and new requests.

  - TUN: tunnel ("option http-tunnel") : this was the default mode for versions
    1.0 to 1.5-dev21 : only the first request and response are processed, and
    everything else is forwarded with no analysis at all. This mode should not
    be used as it creates lots of trouble with logging and HTTP processing.

  - PCL: passive close ("option httpclose") : exactly the same as tunnel mode,
    but with "Connection: close" appended in both directions to try to make
    both ends close after the first request/response exchange.

  - SCL: server close ("option http-server-close") : the server-facing
    connection is closed after the end of the response is received, but the
    client-facing connection remains open.

  - FCL: forced close ("option forceclose") : the connection is actively closed
    after the end of the response.

The effective mode that will be applied to a connection passing through a
frontend and a backend can be determined by both proxy modes according to the
following matrix, but in short, the modes are symmetric, keep-alive is the
weakest option and force close is the strongest.

                          Backend mode

                | KAL | TUN | PCL | SCL | FCL
            ----+-----+-----+-----+-----+----
            KAL | KAL | TUN | PCL | SCL | FCL
            ----+-----+-----+-----+-----+----
            TUN | TUN | TUN | PCL | SCL | FCL
 Frontend   ----+-----+-----+-----+-----+----
   mode     PCL | PCL | PCL | PCL | FCL | FCL
            ----+-----+-----+-----+-----+----
            SCL | SCL | SCL | FCL | SCL | FCL
            ----+-----+-----+-----+-----+----
            FCL | FCL | FCL | FCL | FCL | FCL