Fiber: 🚀 Logger coloration

[YuilTripathee]

Is your feature request related to a problem?

My feature request is related to logger. Could there be solution for coloration?

Describe the solution you'd like

Same solution is being provided in Gin. Using colored logger, debugging looks easier and fancier to be precise 😋. This feature is not desired with the cost of performance.

Describe alternatives you've considered

Apart from coloration, saving the logger to a log file could be fruitful than this features. Alternative to this by saving logs using external gateway.

Additional context

But, if both coloration and saving to file is attained without losing performance at micro-level, the logger will be useful than ever.

[welcome[bot]]

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

[Fenny]

Hey @YuilTripathee, awesome idea. We have to think about how to customize colors by maybe implementing additional color variables ${red}${method} - ${green}${path}.

PS: Our current Logger accepts an io.Writer as input, writing to a file should be no problem.

package main

import (
    "bufio"
    "log"
    "os"
    "time"

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

func main() {
    // Create file
    f, _ := os.Create("./logs.txt")
    defer f.Close()

    // Create io.Writer
    w := bufio.NewWriter(f)

    // Flush to file every second
    go func() {
        for {
            w.Flush()
            time.Sleep(1 * time.Second)
        }
    }()

    app := fiber.New()

    // Pass io.Writer to logger
    app.Use(middleware.Logger(w))

    app.Get("/", func(c *fiber.Ctx) {
        c.Send("Hello, World!")
    })

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

[YuilTripathee]

Working on template now!!!

[YuilTripathee]

Will there arise an issue while saving log with coloration?
For this we got two options:

1. Use coloration while printing on screen only.
2. Use some sort of slicing during Flush.
3. Different format for flushing and printing.

[Fenny]

I think the best way would be to enable colors by default if a custom io.Writer is not given. The we can use our own colorable writer and provide colored variables for method, statuscode and path variables like you showed in your first comment.

[YuilTripathee]

And with the current implemetation, this is the far i can go.

With the changes in Fiber's logger.go

package custom

import (
    "bytes"
    "fmt"
    "io"
    "log"
    "net/http"
    "os"
    "strconv"
    "strings"
    "sync"
    "time"

    fiber "github.com/gofiber/fiber"
    utils "github.com/gofiber/utils"
    bytebufferpool "github.com/valyala/bytebufferpool"
)

// Middleware types
type (
    // LoggerConfig defines the config for Logger middleware.
    LoggerConfig struct {
        // Next defines a function to skip this middleware if returned true.
        Next func(*fiber.Ctx) bool

        // Format defines the logging tags
        //
        // - time
        // - ip
        // - ips
        // - url
        // - host
        // - method
        // - path
        // - protocol
        // - route
        // - referer
        // - ua
        // - latency
        // - status
        // - body
        // - error
        // - bytesSent
        // - bytesReceived
        // - header:<key>
        // - query:<key>
        // - form:<key>
        // - cookie:<key>
        //
        // Optional. Default: ${time} ${method} ${path} - ${ip} - ${status} - ${latency}\n
        Format string

        // TimeFormat https://programming.guide/go/format-parse-string-time-date-example.html
        //
        // Optional. Default: 15:04:05
        TimeFormat string

        // Output is a writter where logs are written
        //
        // Default: os.Stderr
        Output io.Writer
    }
)

// Logger variables
const (
    LoggerTagTime          = "time"
    LoggerTagReferer       = "referer"
    LoggerTagProtocol      = "protocol"
    LoggerTagIP            = "ip"
    LoggerTagIPs           = "ips"
    LoggerTagHost          = "host"
    LoggerTagMethod        = "method"
    LoggerTagPath          = "path"
    LoggerTagURL           = "url"
    LoggerTagUA            = "ua"
    LoggerTagLatency       = "latency"
    LoggerTagStatus        = "status"
    LoggerTagBody          = "body"
    LoggerTagBytesSent     = "bytesSent"
    LoggerTagBytesReceived = "bytesReceived"
    LoggerTagRoute         = "route"
    LoggerTagError         = "error"
    LoggerTagHeader        = "header:"
    LoggerTagQuery         = "query:"
    LoggerTagForm          = "form:"
    LoggerTagCookie        = "cookie:"
    LoggerTagStatusColored = "statusColored"
    LoggerTagMethodColored = "methodColored"
)

// NEW : Color variables
const (
    cBlack   = "\u001b[90m"
    cRed     = "\u001b[91m"
    cGreen   = "\u001b[92m"
    cYellow  = "\u001b[93m"
    cBlue    = "\u001b[94m"
    cMagenta = "\u001b[95m"
    cCyan    = "\u001b[96m"
    cWhite   = "\u001b[97m"
    cReset   = "\u001b[0m"
)

// for colorizing response status and request method
var (
    statusColor    string
    responseStatus int
    methodColor    string
    requestMethod  string
)

// LoggerConfigDefault is the default config
var LoggerConfigDefault = LoggerConfig{
    Next:       nil,
    Format:     "${time} ${method} ${path} - ${ip} - ${status} - ${latency}\n",
    TimeFormat: "15:04:05",
    Output:     os.Stdout,
}

/*
Logger allows the following config arguments in any order:
    - Logger()
    - Logger(next func(*fiber.Ctx) bool)
    - Logger(output io.Writer)
    - Logger(format string)
    - Logger(timeFormat string)
    - Logger(config LoggerConfig)
*/
func Logger(options ...interface{}) fiber.Handler {
    // Create default config
    var config = LoggerConfigDefault
    // Assert options if provided to adjust the config
    if len(options) > 0 {
        for i := range options {
            switch opt := options[i].(type) {
            case func(*fiber.Ctx) bool:
                config.Next = opt
            case string:
                if strings.Contains(opt, "${") {
                    config.Format = opt
                } else {
                    config.TimeFormat = opt
                }
            case io.Writer:
                config.Output = opt
            case LoggerConfig:
                config = opt
            default:
                log.Fatal("Logger: the following option types are allowed: string, io.Writer, LoggerConfig")
            }
        }
    }
    // Return logger
    return logger(config)
}

// LoggerWithConfig is deprecated, please use Logger instead
func LoggerWithConfig(config LoggerConfig) fiber.Handler {
    fmt.Println("logger: `LoggerWithConfig()` is deprecated since v1.12.4, please use `Logger()`")
    return logger(config)
}

func logger(config LoggerConfig) fiber.Handler {
    // Set config default values
    if config.Format == "" {
        config.Format = LoggerConfigDefault.Format
    }
    if config.TimeFormat == "" {
        config.TimeFormat = LoggerConfigDefault.TimeFormat
    }
    if config.Output == nil {
        config.Output = LoggerConfigDefault.Output
    }
    // Middleware settings
    var mutex sync.RWMutex

    var tmpl loggerTemplate
    tmpl.new(config.Format, "${", "}")

    timestamp := time.Now().Format(config.TimeFormat)
    // Update date/time every second in a separate go routine
    if strings.Contains(config.Format, "${time}") {
        go func() {
            for {
                mutex.Lock()
                timestamp = time.Now().Format(config.TimeFormat)
                mutex.Unlock()
                time.Sleep(500 * time.Millisecond)
            }
        }()
    }
    // Return handler
    return func(c *fiber.Ctx) {
        // Don't execute the middleware if Next returns true
        if config.Next != nil && config.Next(c) {
            c.Next()
            return
        }
        // Middleware logic...
        start := time.Now()
        // handle request
        c.Next()
        // build log
        stop := time.Now()
        // Get new buffer
        buf := bytebufferpool.Get()
        _, err := tmpl.executeFunc(buf, func(w io.Writer, tag string) (int, error) {
            switch tag {
            case LoggerTagTime:
                mutex.RLock()
                defer mutex.RUnlock()
                return buf.WriteString(timestamp)
            case LoggerTagReferer:
                return buf.WriteString(c.Get(fiber.HeaderReferer))
            case LoggerTagProtocol:
                return buf.WriteString(c.Protocol())
            case LoggerTagIP:
                return buf.WriteString(c.IP())
            case LoggerTagIPs:
                return buf.WriteString(c.Get(fiber.HeaderXForwardedFor))
            case LoggerTagHost:
                return buf.WriteString(c.Hostname())
            case LoggerTagMethod:
                return buf.WriteString(c.Method())
            case LoggerTagPath:
                return buf.WriteString(c.Path())
            case LoggerTagURL:
                return buf.WriteString(c.OriginalURL())
            case LoggerTagUA:
                return buf.WriteString(c.Get(fiber.HeaderUserAgent))
            case LoggerTagLatency:
                return buf.WriteString(stop.Sub(start).String())
            case LoggerTagStatus:
                return buf.WriteString(strconv.Itoa(c.Fasthttp.Response.StatusCode()))
            case LoggerTagBody:
                return buf.WriteString(c.Body())
            case LoggerTagBytesReceived:
                return buf.WriteString(strconv.Itoa(len(c.Fasthttp.Request.Body())))
            case LoggerTagBytesSent:
                return buf.WriteString(strconv.Itoa(len(c.Fasthttp.Response.Body())))
            case LoggerTagRoute:
                return buf.WriteString(c.Route().Path)
            case LoggerTagError:
                if c.Error() != nil {
                    return buf.WriteString(c.Error().Error())
                }
            case LoggerTagStatusColored:
                responseStatus = c.Fasthttp.Response.StatusCode()
                switch {
                case responseStatus >= http.StatusOK && responseStatus < http.StatusMultipleChoices:
                    statusColor = cGreen
                case responseStatus >= http.StatusMultipleChoices && responseStatus < http.StatusBadRequest:
                    statusColor = cWhite
                case responseStatus >= http.StatusBadRequest && responseStatus < http.StatusInternalServerError:
                    statusColor = cYellow
                default:
                    statusColor = cRed
                }
                return buf.WriteString(statusColor + strconv.Itoa(responseStatus) + cReset)
            case LoggerTagMethodColored:
                requestMethod = c.Method()
                switch requestMethod {
                case "GET":
                    methodColor = cBlue
                case "POST":
                    methodColor = cCyan
                case "PUT":
                    methodColor = cYellow
                case "DELETE":
                    methodColor = cRed
                case "PATCH":
                    methodColor = cGreen
                case "HEAD":
                    methodColor = cMagenta
                case "OPTIONS":
                    methodColor = cWhite
                default:
                    methodColor = cReset
                }
                return buf.WriteString(methodColor + requestMethod + cReset)
            default:
                switch {
                case strings.HasPrefix(tag, LoggerTagHeader):
                    return buf.WriteString(c.Get(tag[7:]))
                case strings.HasPrefix(tag, LoggerTagQuery):
                    return buf.WriteString(c.Query(tag[6:]))
                case strings.HasPrefix(tag, LoggerTagForm):
                    return buf.WriteString(c.FormValue(tag[5:]))
                case strings.HasPrefix(tag, LoggerTagCookie):
                    return buf.WriteString(c.Cookies(tag[7:]))
                }
            }
            return 0, nil
        })
        if err != nil {
            _, _ = buf.WriteString(err.Error())
        }
        if _, err := config.Output.Write(buf.Bytes()); err != nil {
            fmt.Println(err)
        }
        bytebufferpool.Put(buf)
    }
}

// MIT License fasttemplate
// Copyright (c) 2015 Aliaksandr Valialkin
// https://github.com/valyala/fasttemplate/blob/master/LICENSE

type (
    loggerTemplate struct {
        template string
        startTag string
        endTag   string
        texts    [][]byte
        tags     []string
    }
    loggerTagFunc func(w io.Writer, tag string) (int, error)
)

func (t *loggerTemplate) new(template, startTag, endTag string) {
    t.template = template
    t.startTag = startTag
    t.endTag = endTag
    t.texts = t.texts[:0]
    t.tags = t.tags[:0]

    if len(startTag) == 0 {
        panic("startTag cannot be empty")
    }
    if len(endTag) == 0 {
        panic("endTag cannot be empty")
    }

    s := utils.GetBytes(template)
    a := utils.GetBytes(startTag)
    b := utils.GetBytes(endTag)

    tagsCount := bytes.Count(s, a)
    if tagsCount == 0 {
        return
    }

    if tagsCount+1 > cap(t.texts) {
        t.texts = make([][]byte, 0, tagsCount+1)
    }
    if tagsCount > cap(t.tags) {
        t.tags = make([]string, 0, tagsCount)
    }

    for {
        n := bytes.Index(s, a)
        if n < 0 {
            t.texts = append(t.texts, s)
            break
        }
        t.texts = append(t.texts, s[:n])

        s = s[n+len(a):]
        n = bytes.Index(s, b)
        if n < 0 {
            panic(fmt.Errorf("cannot find end tag=%q in the template=%q starting from %q", endTag, template, s))
        }

        t.tags = append(t.tags, utils.GetString(s[:n]))
        s = s[n+len(b):]
    }
}

func (t *loggerTemplate) executeFunc(w io.Writer, f loggerTagFunc) (int64, error) {
    var nn int64

    n := len(t.texts) - 1
    if n == -1 {
        ni, err := w.Write(utils.GetBytes(t.template))
        return int64(ni), err
    }

    for i := 0; i < n; i++ {
        ni, err := w.Write(t.texts[i])
        nn += int64(ni)
        if err != nil {
            return nn, err
        }

        ni, err = f(w, t.tags[i])
        nn += int64(ni)
        if err != nil {
            return nn, err
        }
    }
    ni, err := w.Write(t.texts[n])
    nn += int64(ni)
    return nn, err
}

Hey @Fenny , the solution you suggested with templating was far from my reach for now. So, this could by my temporary solution. I prefer coloration mostly during development and does not make much sense during deployment.

[YuilTripathee]

I got to check the coloration in Fiber's banner. Its much better than random highlighting I've used. But I'll have a long way to go to make a PR using colorable writer. I still have no idea for the efficient way to determine if terminal supports ANSI coloring and respond.

The proposed solution was separate color scheme for different request method and response status codes. Colored text is preferred over highlighted one!

package main

import (
    "bufio"
    "log"
    "os"
    "time"

    "github.com/mattn/go-colorable"

    "github.com/gofiber/fiber"
    "github.com/gofiber/fiber/middleware"
    "github.com/yuil-arsenal/test/custom"
)

func main() {
    // Create file
    f, _ := os.OpenFile("server.log", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
    defer f.Close()

    // Create io.Writer
    w := bufio.NewWriter(colorable.NewNonColorable(f)) // no coloration necessary when dumping to file

    // // Flush to file every second
    go func() {
        for {
            w.Flush()
            time.Sleep(5 * time.Second)
        }
    }()

    // mw := io.MultiWriter(os.Stdout, f) // for real-time writing
    // log.SetOutput(w)

    app := fiber.New(&fiber.Settings{
        Prefork:       true,
        CaseSensitive: true,
        StrictRouting: true,
        ServerHeader:  "Fiber",
    })

    // Provide a custom compression level
    app.Use(middleware.Compress(middleware.CompressLevelBestSpeed))

    // Pass a favicon file that will be cached in memory
    app.Use(middleware.Favicon("./favicon.ico"))

    // Default Logger
    app.Use(custom.Logger("[DEBUG] - ${time} - ${statusColored} - ${methodColored} - ${latency} - ${path}\n", "2006/01/02 15:04:05"))

    app.Get("/", func(c *fiber.Ctx) {
        c.Send("Hello, World 👋!")
    })

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

This is my server setup to do the coloration as in above picture. Seems almost done!

[renanbastos93]

And with the current implemetation, this is the far i can go.

so I liked it but I believe that we should define colors by status don't by the verb HTTP

e.g
All verbs the same color blue on Fiber and status code use other colors.

in the rest seems good to me

[YuilTripathee]

@renanbastos93 I would be thankful if you elaborate!
Thanks for suggesting your idea, I generously started liking it.

[renanbastos93]

@YuilTripathee,

Right, I'll try again.

First, I don't like methods (POST, GET, ...) using different colors, to me we should use the same colors as equal logo fiber. Even so, I believe that we use different colors to the status code.

Well, I will put on the print screen below to show an example.

However, I believe strongly that is more important you show colors based on status code than by methods.

My English is not so good, I hope that you understand me.

[YuilTripathee]

Thank you very much @renanbastos93 , I got your suggestion quite clear.
I agree with you on using uniform color with methods. I came up with this solution since my friends on frontend hits the server with wrong method ironically with GET and POST mostly.

Therefore, I've set coloration to both of them as optional, mostly used in development process only.

[YuilTripathee]

I think the best way would be to enable colors by default if a custom io.Writer is not given. The we can use our own colorable writer and provide colored variables for method, statuscode and path variables like you showed in your first comment.

@Fenny getting close to it. I think I can put it in template literals as you initially suggested. This way developers can put their desired format than a strict default one (as in my current PR). e.g. ${blue}${status}${resetColor}

Sample usecase here:

app.Use(custom.Logger(os.Stdout, "[DEBUG] - ${time} - ${statusColor}${status}${resetColor} - ${methodColor}${method}${resetColor} - ${latency} - ${path}\n", "2006/01/02 15:04:05"))

I suppose it is available now.

[Fenny]

@YuilTripathee, looks promising. I'm currently really busy with a personal project, when I have time I will do some testing and overlook the functionality 👍

[Fenny]

@YuilTripathee I made some small changes, I added the ${pid} tag which is handy when Prefork is enabled.

• I removed methodColor & statusColor see last point
• I gave status, method & pid a fixed width
• Colors are disabled if the terminal does not support it
• Colorization for method & status is enabled by default unless a custom Output io.Writer is given

[YuilTripathee]

Thank you so much 🙂

I'm feeling this feature complete but also eager together to know what else can we bring into this!!!

Can't wait to use it 🤝

[Fenny]

Enjoy 🎨🖌🖼 https://github.com/gofiber/fiber/releases/tag/v1.13.0