Instructions to reproduce are below. When HTTP keepalives are used in conjunction with HTX, the Ti timer reports the elapsed time since the beginning of the connection instead of the end of the previous request as stated in the documentation. Tq and Tt also report incorrectly as a result.
So, when creating a new h1s, check if it is the first request on the connection. If not, set the session create times to the current timestamp rather than the initial session accept timestamp. This makes the logged timers behave as stated in the documentation. I hope this is useful, and feedback is welcome if there is a more correct strategy. Thanks! Cheers, Dave To reproduce, start up haproxy >= 1.9.0 with this configuration: ``` global log stdout format raw local0 defaults mode http timeout connect 2s timeout client 2s timeout server 2s log global log-format "%ci:%cp [%tr] %ft Th:%Th Ti:%Ti TR:%TR Tw:%Tw Tc:%Tc Tr:%Tr Td:%Td Tq:%Tq Tt:%Tt Ta:%Ta" listen htx bind :10080 option http-use-htx server app localhost:8080 # endpoint that sleeps for 1000ms and returns 200 OK listen nohtx bind :10081 no option http-use-htx server app localhost:8080 # endpoint that sleeps for 1000ms and returns 200 OK ``` ...and then make some keepalive requests with something like Apache Bench and note that Ti (and Tq/Tt) are counting from the initial connection: ``` 127.0.0.1:33716 [10/Jul/2019:02:18:18.984] htx Th:0 *Ti:0* TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:33716 [10/Jul/2019:02:18:19.984] htx Th:0 *Ti:1000* TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:1000 Tt:2000 Ta:1000 127.0.0.1:33716 [10/Jul/2019:02:18:20.984] htx Th:0 *Ti:2000* TR:0 Tw:0 Tc:0 Tr:1001 Td:0 Tq:2000 Tt:3001 Ta:1001 127.0.0.1:53264 [10/Jul/2019:02:18:21.989] nohtx Th:0 Ti:0 TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:53264 [10/Jul/2019:02:18:22.989] nohtx Th:0 Ti:0 TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:53264 [10/Jul/2019:02:18:23.989] nohtx Th:0 Ti:0 TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 ``` After applying this patch to master/2.1-dev and re-running Apache Bench test, the logs look as you would expect: ``` # Same ab command w/ the patch. 127.0.0.1:35860 [10/Jul/2019:05:43:59.858] HTTP/1.0 htx Th:0 *Ti:0* TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:35860 [10/Jul/2019:05:44:00.859] HTTP/1.0 htx Th:0 *Ti:0* TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:35860 [10/Jul/2019:05:44:01.859] HTTP/1.0 htx Th:0 *Ti:0* TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:55408 [10/Jul/2019:05:44:02.863] HTTP/1.0 nohtx Th:0 Ti:0 TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:55408 [10/Jul/2019:05:44:03.864] HTTP/1.0 nohtx Th:0 Ti:0 TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:55408 [10/Jul/2019:05:44:04.864] HTTP/1.0 nohtx Th:0 Ti:0 TR:0 Tw:0 Tc:0 Tr:1001 Td:0 Tq:0 Tt:1001 Ta:1001 # And from a ruby script that adds 300ms of delay between requests on a persistent connection 127.0.0.1:35870 [10/Jul/2019:05:44:45.323] HTTP/1.1 htx Th:0 *Ti:0* TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:35870 [10/Jul/2019:05:44:46.624] HTTP/1.1 htx Th:0 *Ti:301* TR:0 Tw:0 Tc:0 Tr:1001 Td:0 Tq:301 Tt:1302 Ta:1001 127.0.0.1:35870 [10/Jul/2019:05:44:47.927] HTTP/1.1 htx Th:0 *Ti:301* TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:301 Tt:1301 Ta:1000 127.0.0.1:55420 [10/Jul/2019:05:44:49.230] HTTP/1.1 nohtx Th:0 Ti:0 TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:0 Tt:1000 Ta:1000 127.0.0.1:55420 [10/Jul/2019:05:44:50.531] HTTP/1.1 nohtx Th:0 Ti:301 TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:301 Tt:1301 Ta:1000 127.0.0.1:55420 [10/Jul/2019:05:44:51.833] HTTP/1.1 nohtx Th:0 Ti:301 TR:0 Tw:0 Tc:0 Tr:1000 Td:0 Tq:301 Tt:1301 Ta:1000 ``` --- src/mux_h1.c | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/src/mux_h1.c b/src/mux_h1.c index 8712d2a0..7309734a 100644 --- a/src/mux_h1.c +++ b/src/mux_h1.c @@ -306,8 +306,16 @@ static struct h1s *h1s_create(struct h1c *h1c, struct conn_stream *cs, struct se if (!sess) sess = h1c->conn->owner; - h1s->csinfo.create_date = sess->accept_date; - h1s->csinfo.tv_create = sess->tv_accept; + /* Timers for subsequent sessions on the same HTTP 1.x connection + * measure from `now`, not from the connection accept time */ + if (h1s->flags & H1S_F_NOT_FIRST) { + h1s->csinfo.create_date = date; + h1s->csinfo.tv_create = now; + } + else { + h1s->csinfo.create_date = sess->accept_date; + h1s->csinfo.tv_create = sess->tv_accept; + } h1s->csinfo.t_handshake = sess->t_handshake; h1s->csinfo.t_idle = -1; }