[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 
\\\"[email protected]\\\"    \\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 
\\\"[email protected]\\\"    \\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")

[cmoulliard]

This request has been addressed. I created a new issue to address long message logged #395