made request logger the last middleware

[sio4]

This is a fix for #2300. See the issue for the issue details and initial investigation.

fixes #2300

The current sequence and tasks for each step are the following:

1. RequestLoggerFunc pre-tasks (no condition)
   • set requester_id
   • set request_id
   • set log field for request_id
   • set start time
2. Other middleware tasks and the original handler
3. RequestLoggerFunc defer-tasks (no condition)
   • log
4. PanicHandler defer-tasks (when only panic happens)
   • emit an error event
   • call error handler
5. defaultErrorMiddleware post-tasks (only when error returned)
   • set status
   • emit an error event
   • call error handler

They are mostly orthogonal so the current order could be changed without side effects. Since step 5 sets the missing status for the response, moving step 3 next to step 5 can be the solution (the change of this PR).

The middleware stack will be fixed like:

-> http://127.0.0.1:3000/
        github.com/gobuffalo/buffalo.RequestLoggerFunc
        github.com/gobuffalo/buffalo.*App.defaultErrorMiddleware
        github.com/gobuffalo/buffalo.*App.PanicHandler
        github.com/gobuffalo/mw-forcessl.Middleware.func1
        github.com/gobuffalo/mw-paramlogger.ParameterLogger
        github.com/gobuffalo/mw-csrf.glob..func1
        github.com/gobuffalo/mw-i18n/v2.*Translator.Middleware.func1

As a result of this PR, the logs will be changed as the followings:

when the handler returns a non-nil error without the status code

DEBU[2022-09-29T19:36:02+09:00] --- ROLLBACK Transaction ---
INFO[2022-09-29T19:36:02+09:00] /error/ db=0s duration="872.947µs" human_size="0 B" method=GET params="{}" path=/error/ request_id=39faa49026241a150ddc-068b8fd32563ed5d3a39 size=0 status=0
ERRO[2022-09-29T19:36:02+09:00] error message db=0s duration="872.947µs" human_size="0 B" method=GET params="{}" path=/error/ request_id=39faa49026241a150ddc-068b8fd32563ed5d3a39 size=0 status=500

become

DEBU[2022-09-29T20:03:55+09:00] --- ROLLBACK Transaction ---
ERRO[2022-09-29T20:03:55+09:00] error message db=0s params="{}" request_id=1230fbcfbd29dc2db42f-52552052f7bdd5078988 status=500
INFO[2022-09-29T20:03:55+09:00] /error/ db=0s duration=1.21633ms human_size="33 kB" method=GET params="{}" path=/error/ request_id=1230fbcfbd29dc2db42f-52552052f7bdd5078988 size=33237 status=500

See the size and status in the INFO log. The size represents the size of the error response set by the (default) error handler.

for a similar situation but panic

DEBU[2022-09-29T19:36:30+09:00] --- ROLLBACK Transaction (inner function panic) ---
INFO[2022-09-29T19:36:30+09:00] /panic/ db=0s duration="729.912µs" human_size="0 B" method=GET params="{}" path=/panic/ request_id=f6165b3ef40b5c6f9dd1-2ca323c6021c6312edb7 size=0 status=0
ERRO[2022-09-29T19:36:30+09:00] transaction was rolled back due to inner panic db=0s duration="729.912µs" human_size="0 B" method=GET params="{}" path=/panic/ request_id=f6165b3ef40b5c6f9dd1-2ca323c6021c6312edb7 size=0 status=500

become

DEBU[2022-09-29T20:04:52+09:00] --- ROLLBACK Transaction (inner function panic) ---
ERRO[2022-09-29T20:04:52+09:00] transaction was rolled back due to inner panic db=0s params="{}" request_id=6da003dc284dd63ec0e3-f85852dd00b8b481ee0c status=500
INFO[2022-09-29T20:04:52+09:00] /panic/ db=0s duration=3.044308ms human_size="33 kB" method=GET params="{}" path=/panic/ request_id=6da003dc284dd63ec0e3-f85852dd00b8b481ee0c size=33279 status=500

as the same as above, the INFO line has the real size and status code.
(In this case, pop middleware catch the panic by the recent fix gobuffalo/pop#775)

See the other cases related to this change

when the handler properly renders the result (same for 200, 404, 500,...):

DEBU[2022-09-29T19:35:37+09:00] --- ROLLBACK Transaction ---
INFO[2022-09-29T19:35:37+09:00] /st500/ db=0s duration="845.08µs" human_size="5 B" method=GET params="{}" path=/st500/ render="164.896µs" request_id=0f11c9e00d3854e17643-c4d7f63b41164b598efa size=5 status=500

DEBU[2022-09-29T20:03:39+09:00] --- ROLLBACK Transaction ---
INFO[2022-09-29T20:03:39+09:00] /st500/ db=0s duration="523.998µs" human_size="5 B" method=GET params="{}" path=/st500/ render="118.349µs" request_id=e425ccd21bf787e6ea2f-412075fb1af9ba11eb2d size=5 status=500

when the app does not use pop middleware which catches the inner panic

INFO[2022-09-29T19:43:16+09:00] /panic/ duration="927.039µs" human_size="0 B" method=GET params="{}" path=/panic/ request_id=656808efa63c4a58673d-a5bbbd3a6f01ada91d60 size=0 status=0
ERRO[2022-09-29T19:43:16+09:00] panic message duration="927.039µs" human_size="0 B" method=GET params="{}" path=/panic/ request_id=656808efa63c4a58673d-a5bbbd3a6f01ada91d60 size=0 status=500

ERRO[2022-09-29T20:06:30+09:00] panic message params="{}" request_id=91724c36f9b7270dd929-ff17f850b8473effdf2d status=500
INFO[2022-09-29T20:06:30+09:00] /panic/ duration=2.414179ms human_size="33 kB" method=GET params="{}" path=/panic/ request_id=91724c36f9b7270dd929-ff17f850b8473effdf2d size=33089 status=500

This is the same as error situation.

still problematic (when the handler returns nil but the status code is still not set properly)

See details in gobuffalo/buffalo-pop#19

$ curl -v http://localhost:3000/nil
< HTTP/1.1 200 OK

DEBU[2022-09-29T20:03:15+09:00] --- ROLLBACK Transaction ---
INFO[2022-09-29T20:03:15+09:00] /nil/ db=0s duration="714.435µs" human_size="0 B" method=GET params="{}" path=/nil/ request_id=8be7a1205504406b5565-bbd6a73e06937b175a90 size=0 status=0