[Suggestion] Improve how log messages are formatted

[cmoulliard]

Issue

Some of the messages logged cannot be read very easily when they appear within the console/terminal

1.69692044577438e+09    INFO    controller.gitserver    Docker build output     {"reconciler group": "idpbuilder.cnoe.io", "reconciler kind": "GitServer", "name": "embedded", "namespace": "idpbuilder-localdev", "output": "
{\"stream\":\"\\u001b[91m[WARNING]: Empty continuation line found in: RUN set -x \\u0026\\u0026   apt-get -y update                                     
\\u0026\\u0026    apt-get install -y git fcgiwrap spawn-fcgi wget       \\u0026\\u0026    adduser git --home /var/lib/git                       
\\u0026\\u0026    adduser nginx git                                     \\u0026\\u0026    git config --system http.receivepack true             
\\u0026\\u0026    git config --system http.uploadpack true              \\u0026\\u0026    git config --system user.email 
\\\"gitserver@git.com\\\"    \\u0026\\u0026    git config --system user.name \\\"Git Server\\\"            \\u0026\\u0026    ln -sf 
/dev/stdout /var/log/nginx/access.log          \\u0026\\u0026    ln -sf /dev/stderr 
/var/log/nginx/error.log\\n\\u001b[0m\"}\r\n\n{\"stream\":\"\\u001b[91m[WARNING]: Empty continuation lines will become errors in a 
future release.\\n\\u001b[0m\"}\r\n\n{\"stream\":\"Step 1/9 : FROM nginx:stable\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" ---
\\u003e 7a57d753be2d\\n\"}\r\n\n{\"stream\":\"Step 2/9 : RUN set -x \\u0026\\u0026   apt-get -y update                                     
\\u0026\\u0026    apt-get install -y git fcgiwrap spawn-fcgi wget       \\u0026\\u0026    adduser git --home /var/lib/git                       
\\u0026\\u0026    adduser nginx git                                     \\u0026\\u0026    git config --system http.receivepack true             
\\u0026\\u0026    git config --system http.uploadpack true              \\u0026\\u0026    git config --system user.email 
\\\"gitserver@git.com\\\"    \\u0026\\u0026    git config --system user.name \\\"Git Server\\\"            \\u0026\\u0026    ln -sf 
/dev/stdout /var/log/nginx/access.log          \\u0026\\u0026    ln -sf /dev/stderr 
/var/log/nginx/error.log\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" ---\\u003e Using cache\\n\"}\r\n\n{\"stream\":\" ---\\u003e 
cfb91d550eec\\n\"}\r\n\n{\"stream\":\"Step 3/9 : ADD nginx.conf /etc/nginx/nginx.conf\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" 
---\\u003e Using cache\\n\"}\r\n\n{\"stream\":\" ---\\u003e 2d67fe760e7f\\n\"}\r\n\n{\"stream\":\"Step 4/9 : ADD ./entrypoint.sh 
/usr/local/bin/entrypoint\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" ---\\u003e Using cache\\n\"}\r\n\n{\"stream\":\" ---\\u003e 
c8949b58893f\\n\"}\r\n\n{\"stream\":\"Step 5/9 : RUN chmod 755 
/usr/local/bin/entrypoint\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" ---\\u003e Using cache\\n\"}\r\n\n{\"stream\":\" ---\\u003e 
085923140d1b\\n\"}\r\n\n{\"stream\":\"Step 6/9 : ENTRYPOINT [ \\\"/usr/local/bin/entrypoint\\\" 
]\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" ---\\u003e Using cache\\n\"}\r\n\n{\"stream\":\" ---\\u003e 
b737e7e2e951\\n\"}\r\n\n{\"stream\":\"Step 7/9 : CMD [ \\\"-start\\\" ]\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" ---\\u003e Using 
cache\\n\"}\r\n\n{\"stream\":\" ---\\u003e f71b921577b6\\n\"}\r\n\n{\"stream\":\"Step 8/9 : COPY srv /var/lib/initial/idpbuilder-
resources\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" ---\\u003e Using cache\\n\"}\r\n\n{\"stream\":\" ---\\u003e 
91a53c610a8e\\n\"}\r\n\n{\"stream\":\"Step 9/9 : LABEL idpbuilder-
gitserver=embedded\"}\r\n\n{\"stream\":\"\\n\"}\r\n\n{\"stream\":\" ---\\u003e Using cache\\n\"}\r\n\n{\"stream\":\" ---\\u003e ...

TODO

• [ ] Improve how JSON messages returned by the controller are formatted to make them more user friendly
• [ ] Consolidate how we log messages as currently we use fmt.print and zap logger
• [ ] Review the command parameters to configure the logger; level, format (json, text), time, etc
• [ ] Adopt a more advanced Logger as new go slog (see comment hereafter)

@greghaynes @nabuskey

[jessesanford]

I absolutely agree with this.

[cmoulliard]

I discovered another issue as we cannot change the time format of the zap logger We are still getting milliSeconds even if we request to show the time using iso8601

 ./idpbuilder create --buildName local --recreate --zap-encoder console --kubeVersion v1.27.3 --zap-time-encoding iso8601
1.6983354005798452e+09  INFO    setup   Creating kind cluster
Creating kind cluster local
...

This is a bit better if I set myself the format:

root.go
...
    zapfs := flag.NewFlagSet("zap", flag.ExitOnError)
    opts := zap.Options{
        Development: true,
        TimeEncoder: zapcore.TimeEncoder(zapcore.ISO8601TimeEncoder),
    }
...
make
./idpbuilder create --buildName local --recreate --zap-encoder console --kubeVersion v1.27.3 --zap-time-encoding iso8601
2023-10-26T17:53:08.796+0200    INFO    setup   Creating kind cluster
Creating kind cluster local
...

Some improvements propositions -->

    opts := zap.Options{
        Development: true,
        TimeEncoder: zapcore.TimeEncoder(func(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
            // enc.AppendString(t.UTC().Format("2006-01-02T15:04"))
            // 2019-08-13T04:39:11Z
            enc.AppendString(t.Format(time.Stamp))
            // Oct 26 17:58:55
        }),
    }

@greghaynes @nabuskey

[cmoulliard]

A better zap format should be this one

    customTimeEncoder := func(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
        enc.AppendString(t.Format("2006-01-02 15:04:05.000"))
    }
    customCallerEncoder := func(caller zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder) {
        enc.AppendString("[" + caller.TrimmedPath() + "]")
    }
    zapLoggerEncoderConfig := zapcore.EncoderConfig{
        TimeKey:          "time",
        LevelKey:         "level",
        NameKey:          "logger",
        CallerKey:        "caller",
        MessageKey:       "message",
        StacktraceKey:    "stacktrace",
        EncodeCaller:     customCallerEncoder,
        EncodeTime:       customTimeEncoder,
        EncodeLevel:      zapcore.CapitalColorLevelEncoder,,
        EncodeDuration:   zapcore.SecondsDurationEncoder,
        LineEnding:       "\n",
        ConsoleSeparator: " ",
    }

    zapfs := flag.NewFlagSet("zap", flag.ExitOnError)
    opts := zap.Options{
        Development: true,
        Encoder:     zapcore.NewConsoleEncoder(zapLoggerEncoderConfig),
    }
    opts.BindFlags(zapfs)
    CreateCmd.Flags().AddGoFlagSet(zapfs)
    ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts)))

which produces

Remark: The controller logger only supports 2 levels: INFO ERROR but no DEBUG !!

WDYT ? @greghaynes @nabuskey @jessesanford

[cmoulliard]

We should certainly look to the new go Logger (which corresponds to what we can use with languages such as ; Java ;-) - https://go.dev/blog/slog

Great blog post: https://betterstack.com/community/guides/logging/logging-in-go/ Resources page: https://github.com/golang/go/wiki/Resources-for-slog

    opts := &slog.HandlerOptions{
        Level: slog.LevelDebug,
    }
    logger := slog.New(slog.NewTextHandler(os.Stdout, opts))
    slog.SetDefault(logger)
    logger.Info("An info message")
    logger.Warn("A warning message")
    logger.Debug("A debug message")