Request Context Deadline Exceeded

I am working on request contexts in Go. I am working on this endpoint for updating user accounts. When I send multiple incoming requests (POSTMAN) to the same endpoint consecutively, it returns the error context deadline exceeded. I am not sure why it only happens when I send the same request to the same endpoint continuously. The context deadline exceeded error appears around the 9th request and will appear 1 second later. After which, it blocks all requests to other endpoints as well.

routes.go [Every request will have a request Context - requestMiddleware]

func Routes(app repository.DatabaseRepo) http.Handler {

	r := chi.NewRouter()

    // Creates request context here with requestID
	r.Use(appMiddleware.RequestMiddleware)

	updateUserH := admin.New(app)
	r.Route("/admin", func(r chi.Router) {
		r.Patch("/update-user", utils.MakeHTTPHandler(updateUserH.UpdateUser))
	})

    return r
}

requestMiddleware.go [Creates a context with requestID]

type RequestIDKey string
const RequestID RequestIDKey = "request_id"

func RequestMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
		requestIDUuid := uuid.New().String()
		ctx := context.WithValue(req.Context(), RequestID, requestIDUuid)
		next.ServeHTTP(w, req.WithContext(ctx))
	})
}

UpdateUser.go [Uses the request context and sets a timeout]

func (app application) UpdateUser(w http.ResponseWriter, req *http.Request) error {

    ....

	ctx := req.Context()
	ctx, cancel := context.WithTimeout(ctx, 5*time.Second)
	defer cancel()

	utilsApp := utils.Application{DB: app.DB}
	err := utils.InjectUG(utilsApp, ctx, w.Header().Get("username"), "Admin")
	if err != nil {
		return err
	}

	return utils.WriteJSON(w, http.StatusOK, utils.ApiSuccess{Success: "[Admin] Successfully updated '" + updateUser.Username + "' user!", Status: http.StatusOK})

}

UPDATE
utils.InjectUG function is calling this database query. This query is causing the entire context to exceed the deadline upon firing multiple incoming requests. When I commented out utils.InjectUG, it works perfectly. I need this database query to check if a user belongs to a user group to access particular resources.

type Application struct {
	DB repository.DatabaseRepo
}

func InjectUG(app Application, ctx context.Context, username string, userGroups ...string) error {
	return app.CheckUserGroup(ctx, username, userGroups...)
}

// Determines if a user has been assigned that usergroup
func (app Application) CheckUserGroup(ctx context.Context, username string, userGroups ...string) error {

	isAuthorizedUser, err := app.DB.GetUserGroupsByUsername(ctx, username, userGroups...)
	if err != nil {
		return ApiError{Err: "Internal Server Error", Status: http.StatusInternalServerError}
	}
	if isAuthorizedUser {
		return nil
	}

	return ApiError{Err: "Access Denied: User does not have permission to access this resource", Status: http.StatusForbidden}
}

var SQL_GET_USERGROUPS_BY_USERNAME = `SELECT ug.user_group FROM user_groups ug
	LEFT JOIN user_group_mapping ugm 
	ON ugm.user_group_id = ug.user_group_id 
	WHERE ugm.user_id = (SELECT user_id FROM users WHERE username = $1);`

func (m *PostgresDBRepo) GetUserGroupsByUsername(ctx context.Context, username string, userGroups ...string) (bool, error) {
    // IT FAILS ON THIS QUERY: context deadline exceeded
	rows, err := m.DB.Query(ctx, SQL_GET_USERGROUPS_BY_USERNAME, username)
	if err != nil {
		log.Println("Query failed at GetUserGroupsByUsername:", err)
		return false, err
	}

	var userGroup string
	if rows != nil {
		for rows.Next() {
			if err = rows.Scan(&userGroup); err != nil {
				return false, err
			}

			if utils.Contains(userGroups, userGroup) {
				return true, nil
			}
		}
	}
	return true, nil
}

[It's weird that I can not find a duplicate question]

The rows should be closed explicitly.

The fix is to add defer rows.Close() after the error check:

  rows, err := m.DB.Query(ctx, SQL_GET_USERGROUPS_BY_USERNAME, username)
  if err != nil {
  	log.Println("Query failed at GetUserGroupsByUsername:", err)
  	return false, err
  }
+ defer rows.Close()

References:

• Querying for multiple rows

  > Looping all the way through the rows also closes it implicitly, but it is better to use defer to make sure rows is closed no matter what.

• https://pkg.go.dev/github.com/jackc/pgx/v5#Conn.Query

  > The returned Rows must be closed before the connection can be used again.

Here is a simple demo that reproduces the issue:

package main

import (
	"context"
	"log"
	"time"

	"github.com/jackc/pgx/v5/pgxpool"
	"golang.org/x/exp/slices"
)

func GetUserGroupsByUsername(ctx context.Context, db *pgxpool.Pool, userGroups ...string) (bool, error) {
	rows, err := db.Query(ctx, "values ('g1'),('g2')")
	if err != nil {
		log.Println("Query failed at GetUserGroupsByUsername:", err)
		return false, err
	}

	// uncomment the next line to address the issue.
	// defer rows.Close()

	var userGroup string
	for rows.Next() {
		if err = rows.Scan(&userGroup); err != nil {
			return false, err
		}

		if slices.Contains(userGroups, userGroup) {
			return true, nil
		}
	}
	log.Println("error:", rows.Err())
	return true, nil
}

func main() {
	connString := "postgres://username:password@localhost:5432/dbname"
	pool, err := pgxpool.New(context.Background(), connString)
	if err != nil {
		log.Fatalf("Unable to connect to database: %v\n", err)
	}
	defer pool.Close()

	ctx, cancel := context.WithTimeout(context.Background(), time.Second)
	defer cancel()

	for i := 0; i < 10; i++ {
		log.Println(GetUserGroupsByUsername(ctx, pool, "g1"))
	}
}

The output:

2023/05/08 09:10:33 true <nil>
2023/05/08 09:10:33 true <nil>
2023/05/08 09:10:33 true <nil>
2023/05/08 09:10:33 true <nil>
2023/05/08 09:10:33 true <nil>
2023/05/08 09:10:33 true <nil>
2023/05/08 09:10:33 true <nil>
2023/05/08 09:10:33 true <nil>
2023/05/08 09:10:34 Query failed at GetUserGroupsByUsername: context deadline exceeded
2023/05/08 09:10:34 false context deadline exceeded
2023/05/08 09:10:34 Query failed at GetUserGroupsByUsername: context deadline exceeded
2023/05/08 09:10:34 false context deadline exceeded
^Csignal: interrupt