Introduction to HAProxy Logging

blog20190207-01.sh

sudo apt install -y rsyslog

blog20190207-02.rsyslog.conf

# Collect log with UDP
$ModLoad imudp
$UDPServerAddress 127.0.0.1
$UDPServerRun 514

# Creating separate log files based on the severity
local0.* /var/log/haproxy-traffic.log
local0.notice /var/log/haproxy-admin.log

blog20190207-03.cfg

local0.* ...
local0.notice ...

blog20190207-04.cfg

global
    log 127.0.0.1:514  local0 

blog20190207-05.cfg

log 127.0.0.1:514  local0  info

blog20190207-06.cfg

defaults
    log global
    option httplog

blog20190207-07.cfg

frontend website
    http-request set-log-level silent unless { rand(100) lt 5 }

blog20190207-08.cfg

http-request set-log-level silent unless { rand(100) lt 5 } OR <SOME_CONDITION>

blog20190207-09.cfg

global
    log stdout  format raw  local0  info

blog20190207-10.cfg

global
    log 127.0.0.1:514 local0
    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
    mode http
    option httplog
    timeout connect 5s
    timeout client  50s
    timeout server  50s

blog20190207-11.cfg

frontend fe_site1
    log 127.0.0.1 local0 notice
    # other configuration

frontend fe_site2
    log 127.0.0.2 local0 warning
    # other configuration

blog20190207-12.cfg

log /dev/log  local0 

blog20190207-13.rsyslog.conf

$ModLoad imuxsock
$AddUnixListenSocket /var/lib/haproxy/dev/log

blog20190207-14.sh

mkdir /var/lib/haproxy/dev/
touch /var/lib/haproxy/dev/log
mount --bind /dev/log /var/lib/haproxy/dev/log

blog20190207-15.cfg

log-format "%ci:%cp [%t] %ft %b/%s %Tw/%Tc/%Tt %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq"

blog20190207-16.cfg

log-format "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"

blog20190207-17.cfg

frontend http-in
  bind :80
  default_backend static

backend static
  server srv1 192.168.1.10:80 check
  server srv2 192.168.1.11:80 check

blog20190207-18.cfg

frontend website
    bind :80
    http-request capture req.hdr(Host) len 10
    http-request capture req.hdr(User-Agent) len 100
    default_backend webservers

blog20190207-19.sh

192.168.160.1:57190 [20/Dec/2018:22:20:00.899] website~ webservers/server1 0/0/1/0/1 200 462 - - ---- 1/1/0/0/0 0/0 {mywebsite.com|Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/71.0.3578.80 } "GET / HTTP/1.1"

blog20190207-20.cfg

frontend website
    bind :80
    
    declare capture response len 20
    http-response capture res.hdr(Server) id 0
    
    declare capture response len 20
    http-response capture res.hdr(Content-Type) id 1

    default_backend webservers

blog20190207-21.cfg

frontend website
    bind :80
    http-request capture req.cook(MyCookie) len 20
    default_backend webservers

blog20190207-22.cfg

frontend website
    bind :80
    stick-table type ip size 1m expire 10s store http_req_rate(10s)
    http-request track-sc0 src
    http-request capture sc_http_req_rate(0) len 4
    default_backend webservers

blog20190207-23.sh

192.168.160.1:49972 [20/Dec/2018:21:58:00.129] website~ webservers/server1 0/0/3/1/4 200 462 - - ---- 2/2/0/0/0 0/0 {1} "GET / HTTP/1.1"
192.168.160.1:49972 [20/Dec/2018:21:58:00.175] website~ webservers/server1 0/0/0/3/68 200 1000182 - - ---- 2/2/1/1/0 0/0 {2} "GET /img1.jpg HTTP/1.1"
192.168.160.1:49972 [20/Dec/2018:21:58:00.175] website~ webservers/server1 0/0/0/3/68 200 1000182 - - ---- 2/2/0/0/0 0/0 {3} "GET /img2.jpg HTTP/1.1"

blog20190207-24.cfg

# logs 'TLSv1.2'
http-request capture ssl_fc_protocol len 10

blog20190207-25.cfg

frontend website
    bind :80
    http-request set-var(req.MyVariable) str("My Value") if SOME_CONDITION
    http-request capture var(req.MyVariable) len 10

blog20190207-26.cfg

acl is_api path_beg /api
http-request set-var(req.is_api) str("Not API")
http-request set-var(req.is_api) str("Is API") if is_api
http-request capture var(req.is_api) len 10

blog20190207-27.cfg

global
    profiling.tasks on

blog20190207-28.cfg

log-format "%{+Q}r cpu_calls:%[cpu_calls] cpu_ns_tot:%[cpu_ns_tot] cpu_ns_avg:%[cpu_ns_avg] lat_ns_tot:%[lat_ns_tot] lat_ns_avg:%[lat_ns_avg]"
# Outputs: "GET / HTTP/1.1" cpu_calls:2 cpu_ns_tot:7928946 cpu_ns_avg:3964473 lat_ns_tot:49814 lat_ns_avg:24907

blog20190207-29.sh

$ halog -srv -H < haproxy.log | column -t
190000 lines in, 10 lines out, 0 parsing errors
#srv_name       1xx  2xx    3xx  4xx  5xx  other  tot_req  req_ok  pct_ok  avg_ct  avg_rt
api/web5        0    12969  163  851  0    1      13984    13983   100.0   0       60
api/web6        0    12976  149  854  5    0      13984    13979   100.0   1       150
httpd/<NOSRV>   0    0      8    0    0    0      8        0       0.0     0       0
httpd/web1      84   534    0    6    2    0      626      626     100.0   0       342
httpd/web2      72   3096   0    9    10   0      3187     3183    99.9    1       1509
static/static1  0    74491  171  17   1    0      74680    74679   100.0   0       2
static/static2  0    72989  155  11   0    0      73155    73155   100.0   1       4
stats/<STATS>   0    465    0    0    0    0      465      458     98.5    0       0	 	

blog20190207-30.sh

$ halog -ut -H < haproxy.log | column -t 
190000 lines in, 1057 lines out, 0 parsing errors
#req   err  ttot      tavg   oktot     okavg  bavg    btot       src
9591   18   13988347  1458   13529888  1413   19383   185905503  /socket.io/
5849   1    429608    73     369605    63     3383    19791913   /api/items
201    1    243619    1212   243412    1217   342     68800      /genius/ws/log
52     0    110684    2128   110684    2128   702     36538      /api/items/
122    0    103800    850    103800    850    67781   8269340    /api/events/14782/items 	 	

blog20190207-31.cfg

listen stats
    bind *:8404
    stats enable
    stats uri /
    stats refresh 5s