Here is a patch to fix the issue reported by Patrick in this thread
(BUG: Tw is negative with lua sleep
https://www.mail-archive.com/haproxy@formilux.org/msg30474.html).
Note that I provide a reg testing file to test both HTTP and TCP LUA
applet callbacks used when registering an HTTP or TCP service.
I dit not manage to reproduce any issue similar to the one reported by
Patrick about HTTP. Note that when we modify struct logs->tv_request
field in src/hlua.c only %TR, %Tq and %Tw timing events may be affected,
and among these three timing events, only %Tw is valid for TCP mode.
Fred.
>From 410ed466774f40c221afb1a8224d64bc21c4407c Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20L=C3=A9caille?= <flecai...@haproxy.com>
Date: Thu, 23 Aug 2018 18:06:35 +0200
Subject: [PATCH 2/2] REGEST/MINOR: Add reg testing files.
Reg testing files for a LUA bug fixed by 7b6cc527 commit.
---
reg-tests/lua/b00001.lua | 8 +++++
reg-tests/lua/b00001.vtc | 80 ++++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 88 insertions(+)
create mode 100644 reg-tests/lua/b00001.lua
create mode 100644 reg-tests/lua/b00001.vtc
diff --git a/reg-tests/lua/b00001.lua b/reg-tests/lua/b00001.lua
new file mode 100644
index 00000000..2c2ab1dc
--- /dev/null
+++ b/reg-tests/lua/b00001.lua
@@ -0,0 +1,8 @@
+core.register_service("foo.http", "http", function(applet)
+ core.msleep(10)
+ applet:start_response()
+end)
+
+core.register_service("foo.tcp", "tcp", function(applet)
+ applet:send("HTTP/1.1 200 OK\r\nTransfer-encoding: chunked\r\n\r\n0\r\n\r\n")
+end)
diff --git a/reg-tests/lua/b00001.vtc b/reg-tests/lua/b00001.vtc
new file mode 100644
index 00000000..a7a2d699
--- /dev/null
+++ b/reg-tests/lua/b00001.vtc
@@ -0,0 +1,80 @@
+# commit 7b6cc52784526c32efda44b873a4258d3ae0b8c7
+# BUG/MINOR: lua: Bad HTTP client request duration.
+#
+# HTTP LUA applet callback should not update the date on which the HTTP client requests
+# arrive. This was done just after the LUA applet has completed its job.
+#
+# This patch simply removes the affected statement. The same fixe has been applied
+# to TCP LUA applet callback.
+#
+# To reproduce this issue, as reported by Patrick Hemmer, implement an HTTP LUA applet
+# which sleeps a bit before replying:
+#
+# core.register_service("foo", "http", function(applet)
+# core.msleep(100)
+# applet:set_status(200)
+# applet:start_response()
+# end)
+#
+# This had as a consequence to log %TR field with approximatively the same value as
+# the LUA sleep time.
+
+varnishtest "LUA bug"
+
+feature ignore_unknown_macro
+
+syslog Slog {
+ recv notice
+ expect ~ "haproxy\\[[0-9]*\\]: Proxy f1 started"
+
+ recv notice
+ expect ~ "haproxy\\[[0-9]*\\]: Proxy f2 started"
+
+ recv info
+ expect ~ "haproxy\\[[0-9]*\\]: Ta=[0-9]* Tc=[0-9]* Td=[0-9]* Th=[0-9]* Ti=[0-9]* Tq=[0-9]* TR=[0-9]* Tr=[0-9]* Tt=[0-9]* Tw=[0-9]*$"
+
+ recv info
+ expect ~ "haproxy\\[[0-9]*\\]: Tc=[0-9]* Td=[0-9]* Th=[0-9]* Tt=[0-9]* Tw=[0-9]*$"
+} -start
+
+haproxy h1 -conf {
+ global
+ lua-load ${testdir}/b00001.lua
+
+ defaults
+ timeout client 1s
+ timeout server 1s
+ timeout connect 1s
+
+ frontend f1
+ mode http
+ bind "fd@${f1}"
+ log ${Slog_addr}:${Slog_port} daemon
+ log-format Ta=%Ta\ Tc=%Tc\ Td=%Td\ Th=%Th\ Ti=%Ti\ Tq=%Tq\ TR=%TR\ Tr=%Tr\ Tt=%Tt\ Tw=%Tw
+ default_backend b1
+
+ backend b1
+ mode http
+ http-request use-service lua.foo.http
+
+ frontend f2
+ mode tcp
+ bind "fd@${f2}"
+ log ${Slog_addr}:${Slog_port} daemon
+ log-format Tc=%Tc\ Td=%Td\ Th=%Th\ Tt=%Tt\ Tw=%Tw
+
+ tcp-request inspect-delay 1s
+ tcp-request content use-service lua.foo.tcp
+} -start
+
+client c1 -connect "${h1_f1_sock}" {
+ txreq
+ rxresp
+} -run
+
+client c2 -connect "${h1_f2_sock}" {
+ txreq
+ rxresp
+} -run
+
+syslog Slog -wait
--
2.11.0
>From 7b6cc52784526c32efda44b873a4258d3ae0b8c7 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20L=C3=A9caille?= <flecai...@haproxy.com>
Date: Wed, 18 Jul 2018 14:25:26 +0200
Subject: [PATCH 1/2] BUG/MINOR: lua: Bad HTTP client request duration.
HTTP LUA applet callback should not update the date on which the HTTP client requests
arrive. This was done just after the LUA applet has completed its job.
This patch simply removes the affected statement. The same fixe has been applied
to TCP LUA applet callback.
To reproduce this issue, as reported by Patrick Hemmer, implement an HTTP LUA applet
which sleeps a bit before replying:
core.register_service("foo", "http", function(applet)
core.msleep(100)
applet:set_status(200)
applet:start_response()
end)
This had as a consequence to log %TR field with approximatively the same value as
the LUA sleep time.
Thank you to Patrick Hemmer for having reported this issue.
Must be backported to 1.8, 1.7 and 1.6.
---
src/hlua.c | 6 +-----
1 file changed, 1 insertion(+), 5 deletions(-)
diff --git a/src/hlua.c b/src/hlua.c
index 65986473..edb4f68c 100644
--- a/src/hlua.c
+++ b/src/hlua.c
@@ -6459,9 +6459,6 @@ static void hlua_applet_tcp_fct(struct appctx *ctx)
case HLUA_E_OK:
ctx->ctx.hlua_apptcp.flags |= APPLET_DONE;
- /* log time */
- strm->logs.tv_request = now;
-
/* eat the whole request */
co_skip(si_oc(si), co_data(si_oc(si)));
res->flags |= CF_READ_NULL;
@@ -6790,9 +6787,8 @@ static void hlua_applet_http_fct(struct appctx *ctx)
/* close the connection. */
- /* status / log */
+ /* status */
strm->txn->status = ctx->ctx.hlua_apphttp.status;
- strm->logs.tv_request = now;
/* eat the whole request */
co_skip(si_oc(si), co_data(si_oc(si)));
--
2.11.0
