Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

🐛 [Bug]: Data race on shutdown #2948

Open
3 tasks done
cherryReptile opened this issue Mar 30, 2024 · 8 comments
Open
3 tasks done

🐛 [Bug]: Data race on shutdown #2948

cherryReptile opened this issue Mar 30, 2024 · 8 comments

Comments

@cherryReptile
Copy link

cherryReptile commented Mar 30, 2024

Bug Description

I have a data race, when I call *fiber.App.Shutdown() methods and have some unprocessed requests , which handlers uses a request ctx

Snippet of data race message:

Previous read at 0x00c00023d1f8 by goroutine 45:
  github.com/valyala/fasthttp.(*RequestCtx).Done()
      ~/go/pkg/mod/github.com/valyala/fasthttp@v1.51.0/server.go:2726 +0x6a
  context.(*cancelCtx).propagateCancel.func2()
      /usr/local/go/src/context/context.go:511 +0x62

How to Reproduce

  1. Handler that uses request ctx for needed funcs
  2. Run app with -race flag
  3. Do some requests to server and start shutdown
  4. See data race by *fiber.RequestCtx

Expected Behavior

I think this data race was not in plan

Fiber Version

2.52.4

Code Snippet (optional)

func (h *Handler) CreateTopic(c *fiber.Ctx) error {
	topic := new(feedback.Topic)

	if err := c.BodyParser(topic); err != nil {
		return err
	}

	id, err := h.feedbackService.CreateTopic(c.Context(), topic)
	if err != nil {
		return err
	}

	return c.Status(fiber.StatusCreated).JSON(map[string]string{"id": id})
}

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

welcome bot commented Mar 30, 2024

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

@cherryReptile cherryReptile changed the title 🐛 [Bug]: 🐛 [Bug]: Data race on shutdown Mar 30, 2024
@H0llyW00dzZ
Copy link
Sponsor

Bug Description

I have a data race, when I call *fiber.App.Shutdown() methods and have some unprocessed requests , which handlers uses a request ctx

Snippet of data race message:

Previous read at 0x00c00023d1f8 by goroutine 45:
  github.com/valyala/fasthttp.(*RequestCtx).Done()
      ~/go/pkg/mod/github.com/valyala/fasthttp@v1.51.0/server.go:2726 +0x6a
  context.(*cancelCtx).propagateCancel.func2()
      /usr/local/go/src/context/context.go:511 +0x62

How to Reproduce

  1. Handler that uses request ctx for needed funcs
  2. Run app with -race flag
  3. Do some requests to server and start shutdown
  4. See data race by *fiber.RequestCtx

Expected Behavior

I think this data race was not in plan

Fiber Version

2.52.4

Code Snippet (optional)

func (h *Handler) CreateTopic(c *fiber.Ctx) error {
	topic := new(feedback.Topic)

	if err := c.BodyParser(topic); err != nil {
		return err
	}

	id, err := h.feedbackService.CreateTopic(c.Context(), topic)
	if err != nil {
		return err
	}

	return c.Status(fiber.StatusCreated).JSON(map[string]string{"id": id})
}

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.

You have to use this method, I think, because it works fine for me, and I'm using Go 1.22.1

example:

// waitForShutdownSignal blocks execution until an OS interrupt or SIGTERM signal is received,
// then it gracefully shuts down the Fiber app within the specified timeout.
func waitForShutdownSignal(shutdownTimeout time.Duration, app *fiber.App, db database.Service) {
	// Setting up signal capturing.
	quit := make(chan os.Signal, 1)
	signal.Notify(quit, os.Interrupt, syscall.SIGTERM)

	// Blocking until a signal is received.
	sig := <-quit
	Logger.LogInfof("Shutting down server... reason: %v", sig)

	// Start graceful shutdown in a separate goroutine.
	go func() {
		// Shutdown the Fiber app
		if err := app.Shutdown(); err != nil {
			Logger.LogErrorf("Server forced to shutdown: %v", err)
		}

		// Clean up resources and close the database connection
		cleanup(db)
	}()

	// Create a timer that will wait for the shutdownTimeout to elapse
	shutdownTimer := time.NewTimer(shutdownTimeout)
	defer shutdownTimer.Stop()

	// Wait for the timeout to elapse
	<-shutdownTimer.C
	Logger.LogInfo("Server exiting")
}

logs:

$ go run cmd/api/main.go
2024/03/31 14:44:15 [H0llyW00dzZ] [INFO] Starting server on :8080

 ┌───────────────────────────────────────────────────┐
 │                    H0llyW00dzZ                    │
 │                   Fiber v2.52.4                   │
 │               http://127.0.0.1:8080               │
 │       (bound on host 0.0.0.0 and port 8080)       │
 │                                                   │
 │ Handlers ............ 534 Processes ........... 1 │
 │ Prefork ....... Disabled  PID .............. 6860 │
 └───────────────────────────────────────────────────┘

2024/03/31 14:44:22 [H0llyW00dzZ] [INFO] Shutting down server... reason: interrupt
2024/03/31 14:44:23 [H0llyW00dzZ] [INFO] Disconnected from database: defaultdb
2024/03/31 14:44:23 [H0llyW00dzZ] [INFO] Database connection closed.
2024/03/31 14:44:27 [H0llyW00dzZ] [INFO] Server exiting

@H0llyW00dzZ
Copy link
Sponsor

with -race flag:

$ go run cmd/api/main.go -race flag
2024/03/31 15:05:12 [H0llyW00dzZ] [INFO] Starting server on :8080

 ┌───────────────────────────────────────────────────┐
 │                    H0llyW00dzZ                    │
 │                   Fiber v2.52.4                   │
 │               http://127.0.0.1:8080               │
 │       (bound on host 0.0.0.0 and port 8080)       │
 │                                                   │
 │ Handlers ............ 534 Processes ........... 1 │
 │ Prefork ....... Disabled  PID ............. 16576 │
 └───────────────────────────────────────────────────┘

2024/03/31 15:05:22 [H0llyW00dzZ] [INFO] Shutting down server... reason: interrupt
2024/03/31 15:05:22 [H0llyW00dzZ] [INFO] Disconnected from database: defaultdb
2024/03/31 15:05:22 [H0llyW00dzZ] [INFO] Database connection closed.
2024/03/31 15:05:27 [H0llyW00dzZ] [INFO] Server exiting

@gaby
Copy link
Member

gaby commented Mar 31, 2024

Doesn't running with -race make your program super slow?

@cherryReptile
Copy link
Author

Doesn't running with -race make your program super slow?

It is only for tests

@cherryReptile
Copy link
Author

cherryReptile commented Mar 31, 2024

with -race flag:

$ go run cmd/api/main.go -race flag
2024/03/31 15:05:12 [H0llyW00dzZ] [INFO] Starting server on :8080

 ┌───────────────────────────────────────────────────┐
 │                    H0llyW00dzZ                    │
 │                   Fiber v2.52.4                   │
 │               http://127.0.0.1:8080               │
 │       (bound on host 0.0.0.0 and port 8080)       │
 │                                                   │
 │ Handlers ............ 534 Processes ........... 1 │
 │ Prefork ....... Disabled  PID ............. 16576 │
 └───────────────────────────────────────────────────┘

2024/03/31 15:05:22 [H0llyW00dzZ] [INFO] Shutting down server... reason: interrupt
2024/03/31 15:05:22 [H0llyW00dzZ] [INFO] Disconnected from database: defaultdb
2024/03/31 15:05:22 [H0llyW00dzZ] [INFO] Database connection closed.
2024/03/31 15:05:27 [H0llyW00dzZ] [INFO] Server exiting

I send about 10 requests to a method that uses the request context for further steps, and immediately run the Shutdown method on the interrupt signal (ShutdownWithContext has similar behavior). I accidentally noticed this when app running with the -race flag.
So I can fix this using context package in handler, but without request ctx as a parent

@JIeJaitt
Copy link

JIeJaitt commented Apr 3, 2024

hi bro, Have you determined this is a bug?

@cherryReptile
Copy link
Author

cherryReptile commented Apr 3, 2024

hi bro, Have you determined this is a bug?

Not entirely sure, but looks like not exactly expected behavior. What do you think?
It’s just that in some places you want to use this request context in case it is interrupted, and a similar problem arises every other time - and only when calling Shutdovn (the case is still the same - about 10 requests or more, then instant strart Shutdovn)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants