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;
}
