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

asyslinux · 2023-12-09T07:11:32Z

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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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.

[email protected]/ctx.go:376

fiber/ctx.go

Line 376 in af39998

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

[email protected]/ctx.go:382

fiber/ctx.go

Line 382 in af39998

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

[email protected]/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.

The text was updated successfully, but these errors were encountered:

welcome · 2023-12-09T07:11:35Z

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

asyslinux · 2023-12-09T10:39:30Z

Additionally, maybe there is no bug, can my additional context with Timeout affect when go func() and the second call to ctx.Body -> fasthttp.Request is executed after my context is canceled by timeout, and fiber.Handler has already returned - fiber.Handler {
return func(ctx *fiber.Ctx) error {

?

I can remove my extra context with timeout and go func() too, because I don't really need it anymore.

sancar · 2023-12-15T12:32:44Z

I recently came across a similar problem. It seems that Immutable option is not used for ctx.Body() even tough the documentation says so.

ReneWerner87 · 2023-12-15T13:31:21Z

can confirm it, no copy is made with the body method, even if immutable is true, if necessary we could correct this

another comment is that in a concurrent function, after the end of the run (timeout), an attempt is made to fetch the content of body is also critical
we can't fix this, fasthttp is so fast because the request and response capsules are reused in the next run (no matter if immutable is on or not)
if an attempt is made to take something from the response after the timeout, even though it is already integrated into another process, this can certainly lead to problems
a copy would have to be created shortly beforehand

asyslinux · 2023-12-15T13:40:44Z

can confirm it, no copy is made with the body method, even if immutable is true, if necessary we could correct this

It would be great if there was an additional option in Fiber or a fix.

asyslinux · 2023-12-20T20:43:50Z

The problem in panic when &c.fasthttp.Request is nil pointer.

What should be done to prevent the application from panic? Since fasthttp clearly states that there is no recover in fasthttp itself:

	// Take into account that no `panic` recovery is done by `fasthttp` (thus any `panic` will take down the entire server).
	// Instead the user should use `recover` to handle these situations

I already configured my app to use app.Use(recover.New()), but when &c.fasthttp.Request disappeared, in this case my application does not recovering.

Below I will write what can be improved in fiber by adding a new option. But nevertheless, even if you start working with the body at the very beginning, some kind of edge case may still arise and &c.fasthttp.Request will be nil pointer, even at the very beginning. Of course, in paragraph 3 below I can suggest improvements in fiber.

It’s not entirely clear how to make it not crash in a panic so that recover works, because app.Use(recover.New()) doesn’t help me.

About PR with immutability for body:

I figured out that there are 3 methods in fiber:

ctx.Body() - does not respect the immutable option in relation to the body.

ctx.BodyRaw() - does not respect the immutable option in relation to the body.

ctx.BodyParser(&mybody) - respects the immutable option in relation to the body, since all data there enters the structure through c.app.getString(), which in turn will be a function depending on the Immutbale option.

And it is clear that there is another option ctx.Request().Body() - you can get the body directly from &c.fasthttp.Request and this can not be immutable, because this is direct access to fasthttp body.

The simplest option without modifying the fiber is to simply copy the body in the written application at the very beginning of the incoming post request:

myimmutablepostbody := utils.CopyBytes(ctx.Body())
myimmutablepostbody := utils.CopyBytes(ctx.BodyRaw())
myimmutablepostbody := utils.CopyBytes(ctx.Request().Body())

And then work with the already copied body. Also can work with copied body in additional context with custom go func().

If we want to make fiber functions ctx.Body() and ctx.BodyRaw() respects immutability (but only through additional option "StrictImmutableBody"), then I or any another man, can make PR, like this PR is be acceptable in this manner (add c.app.getBody() like c.app.getString())?:

https://go.dev/play/p/NBFC_NLT3lV

And also will do modify ctx.Body() and ctx.BodyRaw() methods for using new function:

c.app.getBody(c.fasthttp.Request.Body())

Thanks.

ReneWerner87 · 2023-12-22T12:41:33Z

@asyslinux thanks for the analysis
exactly,ctx.Body() and ctx.BodyRaw() should respect the Immutable setting and make a copy with utils.CopyBytes

an additional setting is not necessary, only the query of the setting in the respective methods and the making of the copy at the end shortly before the return

ReneWerner87 · 2023-12-22T14:08:14Z

@asyslinux could you support us with a PR ?

asyslinux · 2023-12-22T15:13:55Z

@asyslinux could you support us with a PR ?

@ReneWerner87, yes, I will make a PR on next week, with addons to documentation(wiki) and I need a little time to test edge cases when a nil pointer error occurs in fasthttp, since for some reason app.Use(recover.New()) does not help me, even with the ctx.BodyParser() function. Since I have a high load application, I can now reproduce and test. Then I will write a full explain in the documentation, how correctly use body with fiber and fasthttp. Also I will add example of mutex-free parallel high-throughput app for POST requests processing, may be for some people this example can help write high efficient POST request processing apps.

asyslinux · 2023-12-22T21:10:40Z

and the making of the copy at the end shortly before the return

@ReneWerner87 I don't quite understand which code option is preferable:

Direct check through "if" immutable option in ctx.Body() and ctx.BodyRaw() and the make a copy, if Immutable: true
Create c.app.getBody() function []byte []byte like in this example (https://go.dev/play/p/NBFC_NLT3lV) and use this function like c.app.getBody(c.fasthttp.Request.Body()), same another functions c.app.getString() / c.app.getBytes()

Which method is better in the case of the body?

ReneWerner87 · 2023-12-22T21:17:53Z

I prefer 1.
@gaby @efectn what do you think?

asyslinux · 2023-12-22T23:57:25Z

@ReneWerner87, I checked what will happen in both cases, firstly, Go by default does not inline the getBody() function from the 2nd case inside the App. Additionally, the state of the immutable variable at compile time is unknown. Therefore, in case 2 there will always be a function call, and it is more expensive than simple "if".

Even such a simple example with the getBody() function is not inlined by default, but here the state of the variable is known in advance at the compilation stage. https://godbolt.org/z/ddjGMnW6x

I prefer 1 too. Let's wait what others say.

ReneWerner87 · 2024-01-04T08:54:18Z

@asyslinux you are welcome to start, further comments may be made in the review, otherwise it looks ok for solution 1

asyslinux · 2024-01-26T11:25:59Z

@ReneWerner87, please review PR when you have a time. I will add a little later the results of practice tests that cause panic(I'm still dealing with this problem) and an example of a high-performance application for receiving and processing a large number of POST requests.

asyslinux added the ☢️ Bug label Dec 9, 2023

ReneWerner87 added the 👍 Accepting PR label Dec 15, 2023

ReneWerner87 added the ♻ Wait for Response label Dec 22, 2023

asyslinux mentioned this issue Jan 26, 2024

🩹[Fix]: Added respects body immutability to ctx.Body() and ctx.BodyRaw() functions. #2812

Merged

11 tasks

ReneWerner87 linked a pull request Jan 28, 2024 that will close this issue

🩹[Fix]: Added respects body immutability to ctx.Body() and ctx.BodyRaw() functions. #2812

Merged

11 tasks

ReneWerner87 closed this as completed in #2812 Feb 2, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

asyslinux commented Dec 9, 2023 •

edited

Loading

welcome bot commented Dec 9, 2023

asyslinux commented Dec 9, 2023

sancar commented Dec 15, 2023

ReneWerner87 commented Dec 15, 2023

asyslinux commented Dec 15, 2023 •

edited

Loading

asyslinux commented Dec 20, 2023 •

edited

Loading

ReneWerner87 commented Dec 22, 2023

ReneWerner87 commented Dec 22, 2023

asyslinux commented Dec 22, 2023 •

edited

Loading

asyslinux commented Dec 22, 2023 •

edited

Loading

ReneWerner87 commented Dec 22, 2023

asyslinux commented Dec 22, 2023 •

edited

Loading

ReneWerner87 commented Jan 4, 2024

asyslinux commented Jan 26, 2024

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

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

Comments

asyslinux commented Dec 9, 2023 • edited Loading

Bug Description

How to Reproduce

Expected Behavior

Fiber Version

Code Snippet (optional)

Checklist:

welcome bot commented Dec 9, 2023

asyslinux commented Dec 9, 2023

sancar commented Dec 15, 2023

ReneWerner87 commented Dec 15, 2023

asyslinux commented Dec 15, 2023 • edited Loading

asyslinux commented Dec 20, 2023 • edited Loading

ReneWerner87 commented Dec 22, 2023

ReneWerner87 commented Dec 22, 2023

asyslinux commented Dec 22, 2023 • edited Loading

asyslinux commented Dec 22, 2023 • edited Loading

ReneWerner87 commented Dec 22, 2023

asyslinux commented Dec 22, 2023 • edited Loading

ReneWerner87 commented Jan 4, 2024

asyslinux commented Jan 26, 2024

asyslinux commented Dec 9, 2023 •

edited

Loading

asyslinux commented Dec 15, 2023 •

edited

Loading

asyslinux commented Dec 20, 2023 •

edited

Loading

asyslinux commented Dec 22, 2023 •

edited

Loading

asyslinux commented Dec 22, 2023 •

edited

Loading

asyslinux commented Dec 22, 2023 •

edited

Loading