🐛 [Bug]: Partial config cause race condition

[lpongetti]

Bug Description

This works

app.Use(
  logger.New(),
)

while this cause race condition:

app.Use(
  logger.New(logger.Config{
	  Format: "${time} | ${pid} | ${locals:requestid} | ${status} | ${latency} | ${method} | ${path}\n",
  }),
)

WARNING: DATA RACE
Read at 0x00c000091230 by goroutine 14:
  github.com/gofiber/fiber/v2/middleware/logger.New.func3()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/gofiber/fiber/[email protected]/middleware/logger/logger.go:183 +0x1504
  github.com/gofiber/fiber/v2.(*App).next()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/gofiber/fiber/[email protected]/router.go:134 +0x4b6
  github.com/gofiber/fiber/v2.(*App).handler()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/gofiber/fiber/[email protected]/router.go:160 +0xf2
  github.com/gofiber/fiber/v2.(*App).handler-fm()
      <autogenerated>:1 +0x44
  github.com/valyala/fasthttp.(*Server).serveConn()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/server.go:2371 +0x1b4a
  github.com/valyala/fasthttp.(*Server).serveConn-fm()
      <autogenerated>:1 +0x4d
  github.com/valyala/fasthttp.(*workerPool).workerFunc()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/workerpool.go:224 +0xee
  github.com/valyala/fasthttp.(*workerPool).getCh.func1()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/workerpool.go:196 +0x53

Previous write at 0x00c000091230 by goroutine 13:
  github.com/gofiber/fiber/v2/middleware/logger.New.func3()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/gofiber/fiber/[email protected]/middleware/logger/logger.go:179 +0x1364
  github.com/gofiber/fiber/v2.(*App).next()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/gofiber/fiber/[email protected]/router.go:134 +0x4b6
  github.com/gofiber/fiber/v2.(*App).handler()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/gofiber/fiber/[email protected]/router.go:160 +0xf2
  github.com/gofiber/fiber/v2.(*App).handler-fm()
      <autogenerated>:1 +0x44
  github.com/valyala/fasthttp.(*Server).serveConn()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/server.go:2371 +0x1b4a
  github.com/valyala/fasthttp.(*Server).serveConn-fm()
      <autogenerated>:1 +0x4d
  github.com/valyala/fasthttp.(*workerPool).workerFunc()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/workerpool.go:224 +0xee
  github.com/valyala/fasthttp.(*workerPool).getCh.func1()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/workerpool.go:196 +0x53

Goroutine 14 (running) created at:
  github.com/valyala/fasthttp.(*workerPool).getCh()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/workerpool.go:195 +0x364
  github.com/valyala/fasthttp.(*workerPool).Serve()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/workerpool.go:148 +0x7f1
  github.com/valyala/fasthttp.(*Server).Serve()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/server.go:1832 +0x850
  github.com/gofiber/fiber/v2.(*App).Listen()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/gofiber/fiber/[email protected]/listen.go:82 +0x1d6
  main.main()
      C:/Users/LorenzoPongetti/Desktop/work/lorenzo/proji/test.go:23 +0x16c

Goroutine 13 (running) created at:
  github.com/valyala/fasthttp.(*workerPool).getCh()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/workerpool.go:195 +0x364
  github.com/valyala/fasthttp.(*workerPool).Serve()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/workerpool.go:148 +0x7f1
  github.com/valyala/fasthttp.(*Server).Serve()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/valyala/[email protected]/server.go:1832 +0x850
  github.com/gofiber/fiber/v2.(*App).Listen()
      C:/Users/LorenzoPongetti/go/pkg/mod/github.com/gofiber/fiber/[email protected]/listen.go:82 +0x1d6
  main.main()
      C:/Users/LorenzoPongetti/Desktop/work/lorenzo/proji/test.go:23 +0x16c
==================

How to Reproduce

func main() {
	app := fiber.New()

	// add middlewares
	app.Use(
		logger.New(logger.Config{
			Format: "${time} | ${pid} | ${locals:requestid} | ${status} | ${latency} | ${method} | ${path}\n",
		}),
	)

	api := app.Group("api/v1")
	api.Get("/test", func(c *fiber.Ctx) error {
		return c.SendString("Hello, World 👋!")
	})

	app.Listen(":3000")
}

and do
seq 1 200 | xargs -n1 -P20 curl "http://172.31.240.1:3000/api/v1/test"

Expected Behavior

 ┌───────────────────────────────────────────────────┐
 │                   Fiber v2.42.0                   │
 │               http://127.0.0.1:3000               │
 │       (bound on host 0.0.0.0 and port 3000)       │
 │                                                   │
 │ Handlers ............. 3  Processes ........... 1 │
 │ Prefork ....... Disabled  PID ............. 10724 │
 └───────────────────────────────────────────────────┘

13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test    
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test    
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test
13:06:48 | 200 |      0s |  172.31.249.205 | GET     | /api/v1/test

Fiber Version

2.42.2

Checklist:

• I agree to follow Fiber's Code of Conduct.
• I have checked for existing issues that describe my problem prior to opening this one.
• I understand that improperly formatted bug reports may be closed without explanation.

[welcome]

Thanks for opening your first issue here! 🎉 Be sure to follow the issue template! If you need help or want to chat with us, join us on Discord https://gofiber.io/discord

[ReneWerner87]

Thx for the report

[leonklingele]

What might fix the problem:
Add a var err error in front of this for line: https:/gofiber/fiber/blob/v2.42.0/middleware/logger/logger.go#L174

Reason: The err variable currently in use is shared across all requests for this middleware.

[ReneWerner87]

thx that works, will create a pr for this fix

[leonklingele]

I wonder why this wasn't caught by our race-tests (for example in CI). We might also want to add a testcase for this specific case.

[leonklingele]

In order to avoid the problem we should start and switch to never returning anonymous functions (closures) but return non-anonymous functions instead so no data is shared — never. For middlewares this might look as follows:

// New creates a new middleware handler
func New(config ...Config) fiber.Handler {
	// Setup, etc.

	// Return new handler
	return newMiddlewareHandler(list, shared, data, here)
}