Hello Patrick,

On 07/17/2018 03:59 PM, Patrick Hemmer wrote:
Ping?

-Patrick

On 2018/6/22 15:10, Patrick Hemmer wrote:
When using core.msleep in lua, the %Tw metric is a negative value.

For example with the following config:
haproxy.cfg:
        global
            lua-load /tmp/haproxy.lua

        frontend f1
            mode http
            bind :8000
            default_backend b1
            log 127.0.0.1:1234 daemon
            log-format Ta=%Ta\ Tc=%Tc\ Td=%Td\ Th=%Th\ Ti=%Ti\ Tq=%Tq\ TR=%TR\ Tr=%Tr\ Tt=%Tt\ Tw=%Tw

        backend b1
            mode http
            http-request use-service lua.foo

haproxy.lua:
        core.register_service("foo", "http", function(applet)
            core.msleep(100)
            applet:set_status(200)
            applet:start_response()
        end)

The log contains:
    Ta=104 Tc=0 Td=0 Th=0 Ti=0 Tq=104 TR=104 Tr=104 Tt=104 Tw=-104

^ TR also looks wrong, as it did not take 104ms to receive the full request.

This is built from the commit before current master: d8fd2af

-Patrick


The patch attached to this mail fixes this issue at least for %TR field.

But I am not sure at all it is correct or if there is no remaining issues. For instance the LUA tcp callback also updates the tv_request log field.

So, let's wait for Thierry's validation.

Regards.






>From e9866316cec76430a7b1f1b637e4a680406ec43b 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] BUG/MINOR: lua: Bad HTTP client request duration.

HTTP LUA 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.

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 | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/src/hlua.c b/src/hlua.c
index 4715639..f456cd9 100644
--- a/src/hlua.c
+++ b/src/hlua.c
@@ -6750,9 +6750,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), si_ob(si)->o);
-- 
2.1.4

Reply via email to