Request Context Deadline Exceeded

Question

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
}

Answer 1

[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