custom gin logging middleware truncating logs

Question

Intermittently, I see truncated json objects being written to loggly through my custom logging middleware. I've confirmed the outgoing records are in fact being truncated in my code.

Logs are formatted with zerolog and then T'd out between stdout and loggly.

The loggly package I'm using is pretty old, but appears to just implement an io.Writer with a buffer https://github.com/segmentio/go-loggly.

My concern is gin is terminating the context before the logs are written to the buffer, the write is cut short? But in examples provided by gin docs I don't see anything wildly different. I've removed as much extraneous code that still experiences the issue.

The logs that are written to STDOUT are complete, but the logs being sent out through the loggly package are being truncated.

package main

import (
    "io"
    "os"

    "github.com/gin-gonic/gin"
    "github.com/rs/zerolog"
    "github.com/segmentio/go-loggly"
)

var logglyClient *loggly.Client

func init() {
    logglyToken := "potato"
    logglyClient = loggly.New(logglyToken)
}

func NewLogger() zerolog.Logger {
    writers := []io.Writer{zerolog.ConsoleWriter{Out: os.Stdout}}
    writers = append(writers, logglyClient)
    multiWriter := zerolog.MultiLevelWriter(writers...)
    logger := zerolog.New(multiWriter).With().Timestamp().Logger()

    return logger
}

func GinMiddleware() gin.HandlerFunc {
    return func(gctx *gin.Context) {
        logger := NewLogger()
        logger.Info().Msg("API request")

        gctx.Next()
    }
}

func main() {
    router := gin.New()
    router.Use(GinMiddleware())
    logger := NewLogger()
    router.GET("/ping", func(c *gin.Context) {
        c.JSON(200, gin.H{
            "message": "pong",
        })
    })
    logger.Info().Msg("Server Listening!")
    router.Run(":8080")
}

with the following packages in use

github.com/gin-gonic/gin v1.7.7
github.com/rs/zerolog v1.26.0
github.com/segmentio/go-loggly v0.5.0

please share [MWE](https://stackoverflow.com/help/minimal-reproducible-example). — Chandan, Feb 16 '22 at 07:21
I can't reproduce the problem. I see `{"message":"pong"}` in the browser when calling `localhost:8080/ping`. I also see `INF API request` in the terminal on every call. Could you help us reproduce it? What exactly is failing? — EmmanuelB, Feb 19 '22 at 11:16
instead of writing a custom logging middleware, better to use uber zap package for logging. — Prateek Gupta, Feb 19 '22 at 14:31
This line worries me the most but in general the code is not really good. https://github.com/segmentio/go-loggly/blob/3e0cec4266ddf583aecef51bb8e9badc3cca5314/loggly.go#L237 — Nikifor, Feb 20 '22 at 11:15

score 0 · Answer 1 · answered Feb 22 '22 at 12:18

Flushing the loggly client before exiting the program should do it.

https://github.com/segmentio/go-loggly/blob/7a70408c3650c37ba8e58a934f686d0c44cb9b58/loggly.go#L216


func main() {
    defer logglyClient.Flush()

    router := gin.New()
    router.Use(GinMiddleware())
    logger := NewLogger()
    router.GET("/ping", func(c *gin.Context) {
        c.JSON(200, gin.H{
            "message": "pong",
        })
    })
    logger.Info().Msg("Server Listening!")
    router.Run(":8080")
}

On top of that you have to implement graceful-shutdown of the server to prevent abrupt exit sequence of the program.

The Gin documentation has an example just for that

https://chenyitian.gitbooks.io/gin-web-framework/content/docs/38.html

func main() {
    router := gin.Default()
    router.GET("/", func(c *gin.Context) {
        time.Sleep(5 * time.Second)
        c.String(http.StatusOK, "Welcome Gin Server")
    })

    srv := &http.Server{
        Addr:    ":8080",
        Handler: router,
    }

    go func() {
        // service connections
        if err := srv.ListenAndServe(); err != nil {
            log.Printf("listen: %s\n", err)
        }
    }()

    // Wait for interrupt signal to gracefully shutdown the server with
    // a timeout of 5 seconds.
    quit := make(chan os.Signal)
    signal.Notify(quit, os.Interrupt)
    <-quit
    log.Println("Shutdown Server ...")

    ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
    defer cancel()
    if err := srv.Shutdown(ctx); err != nil {
        log.Fatal("Server Shutdown:", err)
    }
    log.Println("Server exiting")
}

custom gin logging middleware truncating logs

1 Answers1