samber / slog-fiber

🚨 Fiber middleware for slog logger
https://pkg.go.dev/github.com/samber/slog-fiber
MIT License
57 stars 9 forks source link

AddCustomAttributes doesn't work in the app.ErrorHandler #13

Closed daenney closed 7 months ago

daenney commented 1 year ago

I have a custom error handler. In it I do a simple slogfiber.AddCustomAttributes() so I can hopefully add the error itself to the log message. However, none of the attributes added in the error handler ever make it into the output.

func apiErrorHandler(ctx *fiber.Ctx, err error) error {
    slogfiber.AddCustomAttributes(ctx, slog.String("hi", "there"))

    var e *fiber.Error
    code := fiber.StatusInternalServerError
    if errors.As(err, &e) {
        code = e.Code
    }

    return ctx.Status(code).JSON(...)
}

The hi key with value there is always missing, and so is any other attribute added in the error handler.

samber commented 1 year ago

It works when i test with this function. Can you please create a small repository with a short example?

daenney commented 12 months ago

Sorry for the delay in response, life took a busy turn. I suspect I've misunderstood something about setting up the error handler really.

I've tried to recreate a small sample: https://gist.github.com/daenney/19faee34bc7bee79a5569b8604022fad

When doing a request against /found I get:

$ curl http://127.0.0.1:46229/found
found it
time=2023-11-13T17:40:06.712+01:00 level=INFO msg="Incoming request" time=2023-11-13T17:40:06.712+01:00 latency=10.41µs method=GET host=127.0.0.1:46229 path=/found route=/found status=200 ip=127.0.0.1 user-agent=curl/8.4.0 referer=""
$ curl http://127.0.0.1:46229/not-a-route
error handler
time=2023-11-13T17:40:15.528+01:00 level=INFO msg="Incoming request" time=2023-11-13T17:40:15.528+01:00 latency=13.827µs method=GET host=127.0.0.1:46229 path=/not-a-route route=/ status=200 ip=127.0.0.1 user-agent=curl/8.4.0 referer=""
in the api error handler

The go.mod has the following versions:

github.com/gofiber/fiber/v2 v2.50.0
github.com/samber/slog-fiber v1.8.0
daenney commented 12 months ago

Also, on closer inspection the status in the log line isn't correct either. If I print the value of code in the handler, I get a 404. But I consistently get status=200 in the log line.

The HTTP status code returned is a 404 though:

> GET /not-a-route HTTP/1.1
> Host: 127.0.0.1:35109
> User-Agent: curl/8.4.0
> Accept: */*
> 
< HTTP/1.1 404 Not Found
< Date: Mon, 13 Nov 2023 17:13:35 GMT
< Content-Type: text/plain; charset=utf-8
< Content-Length: 13
< 
* Connection #0 to host 127.0.0.1 left intact
error handler⏎    
samber commented 12 months ago

About the 404 error, you should add a "catch-all" handler:

        // ...

    app.Use(slogfiber.NewWithConfig(logger, config))
    app.Use("/found", func(ctx *fiber.Ctx) error {
        return ctx.SendString("found it")
    })

    // Last handler
    app.Use(func(c *fiber.Ctx) error {
        return c.SendStatus(fiber.StatusNotFound)
    })

    app.Listen(":1111")

The logger is executed before error handler, so your custom attribute won't be registred into log record attributes

daenney commented 12 months ago

So custom attributes don't work in the ErrorHandler after all?

For the 404, the error handler does get executed, since the output from the error handler gets returned to the client.

samber commented 12 months ago

We might think about doing both a middleware and error handler.

samber commented 11 months ago

hi @daenney

I just made a proposal here: #14

daenney commented 11 months ago

Ah brilliant, I will take a look!

samber commented 7 months ago

After the merge of #19 this should be fixed.

Can you check and return it to me if it's not working well?