Skip to content

🐛 [Bug]: Very rare panics in ctx.BodyParser or in fasthttp under unknown conditions #2757

Closed
#2812
Closed
🐛 [Bug]: Very rare panics in ctx.BodyParser or in fasthttp under unknown conditions#2757
#2812
Labels
☢️ Bug♻ Wait for Response👍 Accepting PR
@everanium

Description

@everanium
everanium
opened on Dec 9, 2023

Bug Description

Immutable: true

Application receives 1000rps+ requests with POST data. In 6 months of continuous operation of the application, I encountered these two panics only 2 times. I do not understand, how can be nil pointers with immutable true...I don't even know what to guess.

It seems to me that this can only happen if some kind of premature interruption of a request in fasthttp and there comes a moment when my code in the application is already running and was not interrupted for some reason and in a rare case a call to the nil pointer occurs. But this is just a guess.

Fiber settings:

        app := fiber.New(fiber.Config{
                Prefork:                      false,
                Network:                      "tcp4",
                Immutable:                    true,
                Concurrency:                  256 * 1024,
                BodyLimit:                    128 * 1024 * 1024,
                ReadBufferSize:               16384,
                WriteBufferSize:              16384,
                ReduceMemoryUsage:            false,
                ReadTimeout:                  5,
                WriteTimeout:                 5,
                IdleTimeout:                  5,
                ProxyHeader:                  "X-Real-IP",
                DisableKeepalive:             true,
                DisableDefaultDate:           false,
                DisableDefaultContentType:    false,
                DisablePreParseMultipartForm: false,
                DisableHeaderNormalizing:     false,
                DisableStartupMessage:        false,
                StreamRequestBody:            false,
                //RedirectFixedPath:            false,
                UnescapePath:      false,
                CaseSensitive:     false,
                StrictRouting:     false,
                GETOnly:           false,
                ETag:              false,
                ErrorHandler:      DefaultErrorHandler,
                EnablePrintRoutes: true,
                ServerHeader:      "",
                AppName:           "uSD",
        })

This panics from 1 server:

Dec  8 10:34:50 ppcl-2 usd[3051260]: panic: runtime error: invalid memory address or nil pointer dereference
Dec  8 10:34:50 ppcl-2 usd[3051260]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x71ef67]
Dec  8 10:34:50 ppcl-2 usd[3051260]: goroutine 877662868 [running]:
Dec  8 10:34:50 ppcl-2 usd[3051260]: github.com/gofiber/fiber/v2.(*Ctx).Request(0x0?)
Dec  8 10:34:50 ppcl-2 usd[3051260]: #011/home/gitlab-runner/go/pkg/mod/github.com/gofiber/fiber/v2@v2.50.0/ctx.go:560 +0x7
Dec  8 10:34:50 ppcl-2 usd[3051260]: main.main.UsdPost.func10.2(0xc010130ea0?)
Dec  8 10:34:50 ppcl-2 usd[3051260]: #011/home/gitlab-runner/builds/fZhdTMZw/0/system/source/usd/post.go:1040 +0x409
Dec  8 10:34:50 ppcl-2 usd[3051260]: created by main.main.UsdPost.func10 in goroutine 877660318
Dec  8 10:34:50 ppcl-2 usd[3051260]: #011/home/gitlab-runner/builds/fZhdTMZw/0/system/source/usd/post.go:976 +0x14a9
Dec  8 10:34:50 ppcl-2 systemd[1]: usd.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Dec  8 10:34:50 ppcl-2 systemd[1]: usd.service: Failed with result 'exit-code'.
Dec  8 10:34:50 ppcl-2 systemd[1]: usd.service: Consumed 2w 1d 5h 28min 19.829s CPU time.
Dec  8 10:39:50 ppcl-2 systemd[1]: usd.service: Scheduled restart job, restart counter is at 2.
Dec  8 10:39:50 ppcl-2 systemd[1]: usd.service: Consumed 2w 1d 5h 28min 19.829s CPU time.
Dec  8 10:39:52 ppcl-2 usd[1470745]:  ┌───────────────────────────────────────────────────┐
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │                        uSD                        │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │                   Fiber v2.50.0                   │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │              https://127.0.0.1:9991               │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │       (bound on host 0.0.0.0 and port 9991)       │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │                                                   │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │ Handlers ............. 4  Processes ........... 1 │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │ Prefork ....... Disabled  PID ........... 1470745 │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  └───────────────────────────────────────────────────┘
Dec  8 10:39:52 ppcl-2 usd[1470745]: method  | path | name | handlers
Dec  8 10:39:52 ppcl-2 usd[1470745]: ------  | ---- | ---- | --------
Dec  8 10:39:52 ppcl-2 usd[1470745]: GET     | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: HEAD    | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: POST    | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: PUT     | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: DELETE  | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: CONNECT | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: OPTIONS | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: TRACE   | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: PATCH   | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: GET     | /*   |      | main.main.UsdGet.func9
Dec  8 10:39:52 ppcl-2 usd[1470745]: HEAD    | /*   |      | main.main.UsdGet.func9
Dec  8 10:39:52 ppcl-2 usd[1470745]: POST    | /*   |      | main.main.UsdPost.func10
Dec  8 10:39:52 ppcl-2 usd[1470745]:  ┌───────────────────────────────────────────────────┐
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │                        uSD                        │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │                   Fiber v2.50.0                   │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │               http://127.0.0.1:9891               │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │       (bound on host 0.0.0.0 and port 9891)       │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │                                                   │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │ Handlers ............. 4  Processes ........... 1 │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  │ Prefork ....... Disabled  PID ........... 1470745 │
Dec  8 10:39:52 ppcl-2 usd[1470745]:  └───────────────────────────────────────────────────┘
Dec  8 10:39:52 ppcl-2 usd[1470745]: method  | path | name | handlers
Dec  8 10:39:52 ppcl-2 usd[1470745]: ------  | ---- | ---- | --------
Dec  8 10:39:52 ppcl-2 usd[1470745]: GET     | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: HEAD    | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: POST    | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: PUT     | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: DELETE  | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: CONNECT | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: OPTIONS | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: TRACE   | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: PATCH   | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:52 ppcl-2 usd[1470745]: GET     | /*   |      | main.main.UsdGet.func9
Dec  8 10:39:52 ppcl-2 usd[1470745]: HEAD    | /*   |      | main.main.UsdGet.func9
Dec  8 10:39:52 ppcl-2 usd[1470745]: POST    | /*   |      | main.main.UsdPost.func10
Dec  8 10:57:36 ppcl-2 usd[1470745]: panic: runtime error: invalid memory address or nil pointer dereference
Dec  8 10:57:36 ppcl-2 usd[1470745]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x4 pc=0x71e51c]
Dec  8 10:57:36 ppcl-2 usd[1470745]: goroutine 804033 [running]:
Dec  8 10:57:36 ppcl-2 usd[1470745]: github.com/gofiber/fiber/v2.(*Ctx).BodyParser(0xc0297ec000, {0x7c4820, 0xc0385050f8})
Dec  8 10:57:36 ppcl-2 usd[1470745]: #011/home/gitlab-runner/go/pkg/mod/github.com/gofiber/fiber/v2@v2.50.0/ctx.go:376 +0x3c
Dec  8 10:57:36 ppcl-2 usd[1470745]: main.main.UsdPost.func10.2(0xc03525d7a0?)
Dec  8 10:57:36 ppcl-2 usd[1470745]: #011/home/gitlab-runner/builds/fZhdTMZw/0/system/source/usd/post.go:1033 +0x38e
Dec  8 10:57:36 ppcl-2 usd[1470745]: created by main.main.UsdPost.func10 in goroutine 795322
Dec  8 10:57:36 ppcl-2 usd[1470745]: #011/home/gitlab-runner/builds/fZhdTMZw/0/system/source/usd/post.go:976 +0x14a9
Dec  8 10:57:36 ppcl-2 systemd[1]: usd.service: Main process exited, code=exited, status=2/INVALIDARGUMENT

Requests with 499 HTTP CODE (client closed request) from nginx:

0
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:43" | grep "\"status\": 499" | wc -l
0
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:44" | grep "\"status\": 499" | wc -l
0
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:45" | grep "\"status\": 499" | wc -l
1
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:46" | grep "\"status\": 499" | wc -l
1
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:47" | grep "\"status\": 499" | wc -l
4
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:48" | grep "\"status\": 499" | wc -l
4
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:49" | grep "\"status\": 499" | wc -l
8
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:50" | grep "\"status\": 499" | wc -l
22
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:34:51" | grep "\"status\": 499" | wc -l
0

-----------------------------------------------------------------------------------------------------

root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:27" | grep "\"status\": 499" | wc -l
0
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:28" | grep "\"status\": 499" | wc -l
4
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:29" | grep "\"status\": 499" | wc -l
0
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:30" | grep "\"status\": 499" | wc -l
0
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:31" | grep "\"status\": 499" | wc -l
0
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:32" | grep "\"status\": 499" | wc -l
0
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:33" | grep "\"status\": 499" | wc -l
52
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:34" | grep "\"status\": 499" | wc -l
65
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:35" | grep "\"status\": 499" | wc -l
13
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:36" | grep "\"status\": 499" | wc -l
66
root@ppcl-2:/var/log/nginx# cat access.log.1 | grep "10:57:37" | grep "\"status\": 499" | wc -l
0

This panics from 2 server:

Dec  8 10:34:43 ppcl-3 usd[2778378]: panic: runtime error: index out of range [290] with length 290
Dec  8 10:34:43 ppcl-3 usd[2778378]: goroutine 2173524629 [running]:
Dec  8 10:34:43 ppcl-3 usd[2778378]: encoding/json.(*decodeState).skip(0xc01b703050)
Dec  8 10:34:43 ppcl-3 usd[2778378]: #011/usr/local/go/src/encoding/json/decode.go:269 +0xa5
Dec  8 10:34:43 ppcl-3 usd[2778378]: encoding/json.(*decodeState).object(0xc01b703050, {0x7c4820?, 0xc018786720?, 0x7?})
Dec  8 10:34:43 ppcl-3 usd[2778378]: #011/usr/local/go/src/encoding/json/decode.go:650 +0x396
Dec  8 10:34:43 ppcl-3 usd[2778378]: encoding/json.(*decodeState).value(0xc01b703050, {0x7c4820?, 0xc018786720?, 0x7f7301285268?})
Dec  8 10:34:43 ppcl-3 usd[2778378]: #011/usr/local/go/src/encoding/json/decode.go:374 +0x3e
Dec  8 10:34:43 ppcl-3 usd[2778378]: encoding/json.(*decodeState).unmarshal(0xc01b703050, {0x7c4820?, 0xc018786720?})
Dec  8 10:34:43 ppcl-3 usd[2778378]: #011/usr/local/go/src/encoding/json/decode.go:181 +0x133
Dec  8 10:34:43 ppcl-3 usd[2778378]: encoding/json.Unmarshal({0xc020d0bc00, 0x122, 0x400}, {0x7c4820, 0xc018786720})
Dec  8 10:34:43 ppcl-3 usd[2778378]: #011/usr/local/go/src/encoding/json/decode.go:108 +0x111
Dec  8 10:34:43 ppcl-3 usd[2778378]: github.com/gofiber/fiber/v2.(*Ctx).BodyParser(0xc01885a000, {0x7c4820, 0xc018786720})
Dec  8 10:34:43 ppcl-3 usd[2778378]: #011/home/gitlab-runner/go/pkg/mod/github.com/gofiber/fiber/v2@v2.50.0/ctx.go:382 +0x497
Dec  8 10:34:43 ppcl-3 usd[2778378]: main.main.UsdPost.func10.2(0xc016fd1560?)
Dec  8 10:34:43 ppcl-3 usd[2778378]: #011/home/gitlab-runner/builds/fZhdTMZw/0/system/source/usd/post.go:1033 +0x38e
Dec  8 10:34:43 ppcl-3 usd[2778378]: created by main.main.UsdPost.func10 in goroutine 2173406117
Dec  8 10:34:43 ppcl-3 usd[2778378]: #011/home/gitlab-runner/builds/fZhdTMZw/0/system/source/usd/post.go:976 +0x14a9
Dec  8 10:34:43 ppcl-3 systemd[1]: usd.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Dec  8 10:34:43 ppcl-3 systemd[1]: usd.service: Failed with result 'exit-code'.
Dec  8 10:34:43 ppcl-3 systemd[1]: usd.service: Consumed 2month 1w 5d 12h 21min 8.911s CPU time.
Dec  8 10:39:44 ppcl-3 systemd[1]: usd.service: Scheduled restart job, restart counter is at 1.
Dec  8 10:39:44 ppcl-3 systemd[1]: usd.service: Consumed 2month 1w 5d 12h 21min 8.911s CPU time.
Dec  8 10:39:45 ppcl-3 usd[2267086]:  ┌───────────────────────────────────────────────────┐
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │                        uSD                        │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │                   Fiber v2.50.0                   │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │               http://127.0.0.1:9891               │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │       (bound on host 0.0.0.0 and port 9891)       │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │                                                   │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │ Handlers ............. 4  Processes ........... 1 │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │ Prefork ....... Disabled  PID ........... 2267086 │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  └───────────────────────────────────────────────────┘
Dec  8 10:39:45 ppcl-3 usd[2267086]:  ┌───────────────────────────────────────────────────┐
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │                        uSD                        │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │                   Fiber v2.50.0                   │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │              https://127.0.0.1:9991               │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │       (bound on host 0.0.0.0 and port 9991)       │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │                                                   │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │ Handlers ............. 4  Processes ........... 1 │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  │ Prefork ....... Disabled  PID ........... 2267086 │
Dec  8 10:39:45 ppcl-3 usd[2267086]:  └───────────────────────────────────────────────────┘
Dec  8 10:39:45 ppcl-3 usd[2267086]: method  | pathmethod  | path |  | name | handlers
Dec  8 10:39:45 ppcl-3 usd[2267086]: name | handlers
Dec  8 10:39:45 ppcl-3 usd[2267086]: ------  | ---- | ---- | --------
Dec  8 10:39:45 ppcl-3 usd[2267086]: GET     | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: HEAD    | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: POST    | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: PUT------  | ---- | ----     | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: DELETE  | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: CONNECT | /    |       | --------| github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: OPTIONS | /
Dec  8 10:39:45 ppcl-3 usd[2267086]: GET     | /    |     |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: TRACE        | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: HEAD    | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: POST    | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: PUT     | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: DELETE  | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: CONNECT | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: OPTIONS | /    |      | /| github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: TRACE   | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: PATCH   | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: GET     | /*   |      | main.main.UsdGet.func9
Dec  8 10:39:45 ppcl-3 usd[2267086]: HEAD    | /*   |      | main.main.UsdGet.func9
Dec  8 10:39:45 ppcl-3 usd[2267086]: POST    | /*   |      | main.main.UsdPost.func10
Dec  8 10:39:45 ppcl-3 usd[2267086]:     |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: PATCH   | /    |      | github.com/gofiber/fiber/v2/middleware/recover.New.func1
Dec  8 10:39:45 ppcl-3 usd[2267086]: GET     | /*   |      | main.main.UsdGet.func9
Dec  8 10:39:45 ppcl-3 usd[2267086]: HEAD    | /*   |      | main.main.UsdGet.func9
Dec  8 10:39:45 ppcl-3 usd[2267086]: POST    | /*   |      | main.main.UsdPost.func10
Dec  8 10:44:26 ppcl-3 usd[2267086]: panic: runtime error: invalid memory address or nil pointer dereference
Dec  8 10:44:26 ppcl-3 usd[2267086]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x4 pc=0x71e51c]
Dec  8 10:44:26 ppcl-3 usd[2267086]: goroutine 258893 [running]:
Dec  8 10:44:26 ppcl-3 usd[2267086]: github.com/gofiber/fiber/v2.(*Ctx).BodyParser(0xc0247fa900, {0x7c4820, 0xc016431cc8})
Dec  8 10:44:26 ppcl-3 usd[2267086]: #011/home/gitlab-runner/go/pkg/mod/github.com/gofiber/fiber/v2@v2.50.0/ctx.go:376 +0x3c
Dec  8 10:44:26 ppcl-3 usd[2267086]: main.main.UsdPost.func10.2(0xc017a936e0?)
Dec  8 10:44:26 ppcl-3 usd[2267086]: #011/home/gitlab-runner/builds/fZhdTMZw/0/system/source/usd/post.go:1033 +0x38e
Dec  8 10:44:26 ppcl-3 usd[2267086]: created by main.main.UsdPost.func10 in goroutine 148438
Dec  8 10:44:26 ppcl-3 usd[2267086]: #011/home/gitlab-runner/builds/fZhdTMZw/0/system/source/usd/post.go:976 +0x14a9
Dec  8 10:44:26 ppcl-3 systemd[1]: usd.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Dec  8 10:44:26 ppcl-3 systemd[1]: usd.service: Failed with result 'exit-code'.
Dec  8 10:44:26 ppcl-3 systemd[1]: usd.service: Consumed 11min 21.567s CPU time.
Dec  8 10:49:27 ppcl-3 systemd[1]: usd.service: Scheduled restart job, restart counter is at 2.
Dec  8 10:49:27 ppcl-3 systemd[1]: usd.service: Consumed 11min 21.567s CPU time.

Requests with 499 HTTP CODE (client closed request) from nginx:

root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:37" | grep "\"status\": 499" | wc -l
0
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:38" | grep "\"status\": 499" | wc -l
4
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:39" | grep "\"status\": 499" | wc -l
3
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:40" | grep "\"status\": 499" | wc -l
5
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:41" | grep "\"status\": 499" | wc -l
0
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:42" | grep "\"status\": 499" | wc -l
37
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:43" | grep "\"status\": 499" | wc -l
33
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:44" | grep "\"status\": 499" | wc -l
1
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:34:45" | grep "\"status\": 499" | wc -l
0

-----------------------------------------------------------------------------------------------------

root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:44:20" | grep "\"status\": 499" | wc -l
0
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:44:21" | grep "\"status\": 499" | wc -l
0
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:44:22" | grep "\"status\": 499" | wc -l
0
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:44:23" | grep "\"status\": 499" | wc -l
3
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:44:24" | grep "\"status\": 499" | wc -l
2
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:44:25" | grep "\"status\": 499" | wc -l
15
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:44:26" | grep "\"status\": 499" | wc -l
16
root@ppcl-3:/var/log/nginx# cat access.log.1 | grep "10:44:27" | grep "\"status\": 499" | wc -l
0

How to Reproduce

I do not know how to reproduce, I guess this sometimes happens with 499 (client closed request).
Maybe I missed something when writing an application to process POST requests. Maybe need to write code using OnClose? In case the client closes the connection ahead of time. But just how to do this, I don’t know at what point in time the client will break the connection, in my code anywhere there can be access to headers, body, request parameters, this is not an atomic operation.

v2@v2.50.0/ctx.go:376

fiber/ctx.go

Line 376 in af39998

ctype := utils.ToLower(c.app.getString(c.fasthttp.Request.Header.ContentType()))

v2@v2.50.0/ctx.go:382

fiber/ctx.go

Line 382 in af39998

return c.app.config.JSONDecoder(c.Body(), out)

v2@v2.50.0/ctx.go:560

fiber/ctx.go

Line 560 in af39998

return &c.fasthttp.Request

Expected Behavior

Usually everything works without problems, serves a lot of requests, never panics for months.

Below in my code you can see that panic occurs not only when the body is processed for the first time, but also when it is processed again, also on line 1040 of my code. That is, imagine that there was a body in fasthttp and there was no panic on line 1033, and then it disappeared somewhere in fasthttp and a panic happened on line 1040. Yes, and the first processing of a POST body request can also cause panic right away.

More precisely, the entire fasthttp.Request disappears somewhere or does not have time to be copied when client closing connection, but my code is executed and essentially accesses fasthttp.Request via fiber. But interesting case, when on line 1033 fasthttp.Request have data, but little later on line 1040 fasthttp.Request is no have data, how data on request with immutability enabled, which should have already been copied and successufully accessed on line 1033, suddenly disappeared somewhere and on line 1040 i get a nil pointer.

Fiber Version

v2.50.0 and below

Code Snippet (optional)

When processing POST requests, I made an additional context with a timeout and placed the request processing in the go func(), this was done just in case, so that if anything happens, the processing of the POST request is guaranteed to complete. But I can definitely say that if panic occurs, the timeout of 3 seconds does not occur.

Partly my code:

func UsdPost(rdb *Redis, rdp *RedisProxy, rdi *RedisInternal, wg *sync.WaitGroup) fiber.Handler {
        return func(ctx *fiber.Ctx) error {
                // Wait Group
                wg.Add(1)
                defer wg.Done()

..........................

ctxTimeOut, cancel := context.WithTimeout(context.Background(), 3*time.Second)
defer cancel()

cerr := make(chan error)
go func(cerr chan error) { // Line 940 from panic log

     var body []PostStat

..........................

err = ctx.BodyParser(&body) // Line 1033 from panic log, panic may be here
       if err != nil {
             var bbody []byte
             bbody = append(bbody, []byte("[")...)
             rbody := ctx.Request().Body() // Line 1040 from panic log, panic may be here
             bbody = append(bbody, rbody...)
             bbody = append(bbody, []byte("]")...)

             uerr := json.Unmarshal(bbody, &body)
                  if uerr != nil {

..........................

     }
     cerr <- nil
     }(cerr) //End of go func()

select { // awaiting processing of POST request data
      case <-ctxTimeOut.Done():
            ctx.Status(fiber.StatusInternalServerError)
            return nil
      case err = <-cerr:
            return err
}

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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    ☢️ Bug♻ Wait for Response👍 Accepting PR

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions