🐛 [Bug]: Logger module causes OOM with ${bytesSent} and ${bytesReceived}

[shell-skrimp]

Bug Description

When download large files the process can be OOM'd. I have tried serving ~2GB ISOs and I've noticed that memory is not reclaimed.

How to Reproduce

Steps to reproduce the behavior:

1. Setup a go-fiber app using static being sure to add a large file (such as an ISO) to the static directory, for example:

    app.Static("/", "./mydir", fiber.Static{
        Download: true,
    })

2. Download with curl multiple times (until memory is exhausted): curl localhost/isos/some.iso
3. This will result in a large amount of memory being used. Under normal circumstances about 33MB RSS is used. Once I've downloaded a 2GB iso, the process is now using 4128M. If I download the file again, this amount of memory increases. Eventually the process is OOM'd.
4. I have tried tweaking some functionality such as disabling keep-alives as well as setting Download: true (in static) and CacheDuration: -1

pprof (if it helps):

(-inuse_space)

Showing nodes accounting for 2GB, 99.92% of 2GB total
Dropped 8 nodes (cum <= 0.01GB)
Showing top 10 nodes out of 11
      flat  flat%   sum%        cum   cum%
       2GB 99.92% 99.92%        2GB 99.92%  github.com/valyala/bytebufferpool.(*ByteBuffer).ReadFrom
         0     0% 99.92%        2GB 99.92%  github.com/gofiber/fiber/v2.(*App).handler
         0     0% 99.92%        2GB 99.92%  github.com/gofiber/fiber/v2.(*App).next
         0     0% 99.92%        2GB 99.92%  github.com/gofiber/fiber/v2/middleware/logger.New.func3
         0     0% 99.92%        2GB 99.92%  github.com/gofiber/fiber/v2/middleware/logger.createTagMap.func12
         0     0% 99.92%        2GB 99.92%  github.com/valyala/fasthttp.(*Response).Body
         0     0% 99.92%        2GB 99.92%  github.com/valyala/fasthttp.(*Server).serveConn
         0     0% 99.92%        2GB 99.92%  github.com/valyala/fasthttp.(*bigFileReader).WriteTo
         0     0% 99.92%        2GB 99.92%  github.com/valyala/fasthttp.(*workerPool).getCh.func1
         0     0% 99.92%        2GB 99.92%  github.com/valyala/fasthttp.(*workerPool).workerFunc

(-alloc_space)

Showing top 10 nodes out of 11
      flat  flat%   sum%        cum   cum%
      12GB   100%   100%       12GB   100%  github.com/valyala/bytebufferpool.(*ByteBuffer).ReadFrom
         0     0%   100%       12GB   100%  github.com/gofiber/fiber/v2.(*App).handler
         0     0%   100%       12GB   100%  github.com/gofiber/fiber/v2.(*App).next

Expected Behavior

File should be served without OOMing.

Fiber Version

v2.52.4

Code Snippet (optional)

package main

import (
    "log"
    "os"

    "github.com/gofiber/fiber/v2"
    "github.com/gofiber/fiber/v2/middleware/logger"
)

func main() {
    app := fiber.New()

    // comment out to "fix" bug
    app.Use(logger.New(logger.Config{
        TimeZone:   "UTC",
        TimeFormat: "02/Jan/2006:15:04:05 -0700",
        Format:     "${ip} - - [${time}] \"${method} ${path}${queryParams} HTTP/1.1\" ${status} ${bytesSent} \"${referer}\" \"${ua}\"\n",
        Output:     os.Stdout,
    }))

    app.Static("/", "./static", fiber.Static{
        Browse:        true,
        CacheDuration: -1,
    })

    v1 := app.Group("/api/v1")

    v1.Get("/start", func(c *fiber.Ctx) error {
        return nil
    })
    v1.Get("/start2", func(c *fiber.Ctx) error {
        return nil
    })

    v1.Get("/start3", func(c *fiber.Ctx) error {
        return nil
    })
    v1.Get("/start4", func(c *fiber.Ctx) error {
        return nil
    })

    log.Fatal(app.Listen(":3000"))
}

Checklist:

• [X] I agree to follow Fiber's Code of Conduct.
• [X] I have checked for existing issues that describe my problem prior to opening this one.
• [X] I understand that improperly formatted bug reports may be closed without explanation.

[gaby]

@shell-skrimp Your example code says "fber/v3", but the errors say "fiber/v2". Which one is it?

[shell-skrimp]

@gaby I've updated the sample to show the bug. The bug occurs when app.Use(logger.New(logger.Config{ is enabled. If you comment out that block of code there is no bug.

[efectn]

@gaby I've updated the sample to show the bug. The bug occurs when app.Use(logger.New(logger.Config{ is enabled. If you comment out that block of code there is no bug.

Does this issue still occur if you remove ${bytesSent} from logger format?

[shell-skrimp]

@efectn if I set that to - there is no bug

[ReneWerner87]

ok then it is related to this line https://github.com/gofiber/fiber/blob/6968d51d0dc990f60541536423cc7898b387bae4/middleware/logger/tags.go#L94

[shell-skrimp]

I can confirm on main program when I omit or change ${bytesSent} to - there is no bug; I will just do that for now.

[shell-skrimp]

@ReneWerner87 I believe that's the bug because it reads from the body without closing?

[ReneWerner87]

Close is not really needed there. Its something else We need to debug

[gaby]

This also happens with {bytesReceived} tag.

[gaby]

@shell-skrimp Fix has been submitted for both Fiber/v2 and Fiber/v3

[shell-skrimp]

Unsure on the release cadence, but do you guys know when a new release will be cut with the fix?

[gaby]

@ReneWerner87 We may need a new v2 release to backport this.

[shell-skrimp]

@ReneWerner87 can we get this backported to v2? I have some services in prod where I had to do some builds with the bytesRecv/bytesSent disabled, would be nice to enable that functionality again

[gaby]

@shell-skrimp It's backported, we just need to do a new v2 release. It was backported in https://github.com/gofiber/fiber/pull/3067