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

["SZEDER Gábor" <szeder.dev@gmail.com>]

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

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