Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure

From: SZEDER Gábor <szeder.dev@gmail.com>
Date: Jun 14, 2018, 16:39 UTC
Message-ID: <CAM0VKjkfLiEoTOfkC=jXx5TVmbbVvHRDB6KEPinW6Gb98p0vgA@mail.gmail.com>
In-Reply-To: <20180614123107.11608-5-szeder.dev@gmail.com>

On Thu, Jun 14, 2018 at 2:31 PM, SZEDER Gábor <szeder.dev@gmail.com> wrote:

Show 29 quoted lines

> When a test sends a HTTP request, it can continue execution after
> 'git-http-backend' fulfilled that request, but Apache writes the
> corresponding access log entry only after 'git-http-backend' exited.
> Some time inevitably passes between fulfilling the request and writing
> the log entry, and, under unfavourable circumstances, enough time
> might pass for the subsequent request to be sent and fulfilled, and
> then Apache writes access log entries racily.
>
> This effect can be exacerbated by adding a bit of variable delay after
> the request is fulfilled but before 'git-http-backend' exits, e.g.
> like this:
>
>   diff --git a/http-backend.c b/http-backend.c
>   index f3dc218b2..bbf4c125b 100644
>   --- a/http-backend.c
>   +++ b/http-backend.c
>   @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)
>                                            max_request_buffer);
>
>         cmd->imp(&hdr, cmd_arg);
>   +     if (getpid() % 2)
>   +             sleep(1);
>         return 0;
>    }
>
> This delay considerably increases the chances of log entries being
> written out of order, and in turn makes t5561's last test fail almost
> every time.  Alas, it doesn't seem to be enough to trigger a similar
> failure in t5541 and t5551.

A bit of addendum here:

There are basically two "kinds" of requests:

  1. requests asking for regular files, e.g.:

     GET  /smart/repo.git/HEAD HTTP/1.1 200
     GET  /smart/repo.git/info/refs HTTP/1.1 200
     GET  /smart/repo.git/objects/info/packs HTTP/1.1 200

  2. requests asking for 'git-receive-pack' or 'git-upload-pack',
     e.g.:

     GET  /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
     POST /smart/repo.git/git-receive-pack HTTP/1.1 200 -

This artificial variable delay shuffles only the access log entries written for the first kind of requests, but doesn't appear to have any effect on the order of log entries written for the second kind of requests.

t5561 sends both kinds of requests, so this variable delay is sufficient to make the test fail most of the time.

t5541 and t5551, however, send only requests of the second kind, so that's why this variable delay can't trigger a similar failure in these test scripts.

I haven't investigated any further what else would be necessary to trigger a failure in t5541 and t5551.