We have been using haproxy for a while now and it has been great for getting detailed logs and being able to customize much of the information we want to extract out of our traffic.
However, I have made some layer 8 mistakes by thinking that timestamps on log entries are the time of the request to the server.
Through testing, watching log entries, and studying haproxy documentation it looks like logging takes place at the time of the response and includes information about how long in milliseconds those requests took.
This can be helpful, however when trying to align requests from the haproxy log with application logs it ends up being difficult to align log entries without doing some time math to get as close as possible to the true request time.
Has my own study or experience led me astray in my understanding of when haproxy populates logs and the date/time stamp found in the logs? Or is there a way to configure haproxy to make a log entry at the time of the request as well as at the time of the response?
Server Type: Centos
HAProxy Version: 1.8
Example Log Entries:
Feb 22 03:07:06 unipay-p11 haproxy[2286]: 10.13.6.101:35804 [22/Feb/2022:03:07:06.283] ft-unipay-https~ unipay-api/unipay-p13.zift.io 0/0/6/13/19 200 507 - - ---- 48/48/4/2/0 0/0 {|} "GET /pingdom/index.jsp HTTP/1.1"```
Feb 22 03:07:06 unipay-p11 haproxy[2286]: 10.13.6.103:39836 [22/Feb/2022:03:07:06.285] ft-unipay-https~ unipay-api/unipay-p13.zift.io 0/0/5/12/17 200 507 - - ---- 48/48/3/1/0 0/0 {|} "GET /pingdom/index.jsp HTTP/1.1"
Feb 22 03:07:06 unipay-p11 haproxy[2286]: 10.13.6.103:39836 [22/Feb/2022:03:07:06.285] ft-unipay-https~ unipay-api/unipay-p13.zift.io 0/0/5/12/17 200 507 - - ---- 48/48/3/1/0 0/0 {|} "GET /pingdom/index.jsp HTTP/1.1"
Feb 22 03:07:06 unipay-p11 haproxy[2286]: 10.13.8.102:50888 [22/Feb/2022:03:07:06.260] ft-unipay-https~ unipay-api/unipay-p11.zift.io 0/0/5/47/52 200 507 - - ---- 46/46/2/1/0 0/0 {|} "GET /pingdom/ HTTP/1.1"
Thank you
James Anderson
2
Answers
Unfortunately I don’t have an absolute answer for you but my experience with HAProxy and a couple of documents that I’ve found brings me to believe that the timestamp provided in the logs (between [ and ]) is the time when HAProxy received and began processing the request.
In this doc https://cdn.haproxy.com/wp-content/uploads/2017/07/aloha_load_balancer_memo_log.pdf
they say:
Also, in the official documentation https://cbonte.github.io/haproxy-dconv/1.7/configuration.html
when referring to %t
Additionally, when I need to know when the request ended, I add to this timestamp the value of %Tt (milliseconds). Some info here https://www.haproxy.com/blog/haproxy-log-customization/
I log requests using rsyslog. This first let me to believe haproxy logs chronologically. But then I took a good look, and it was the rsyslog timestamp that shows end of request and the generic haproxy timestamp (between []) that shows the start.
Your question just changed my search from a 4 second network stall into a 4 second application stall.
So if you use (r)syslog, the loglines will log the end of the requests on second granularity, and the haproxy shows the start of the request with ms granularity and the total request time in ms.