diff --git a/pkg/logger/handler.go b/pkg/logger/handler.go index 961a11ab..f67a3098 100644 --- a/pkg/logger/handler.go +++ b/pkg/logger/handler.go @@ -1,14 +1,15 @@ package logger import ( + "bytes" "context" "fmt" "io" "log/slog" "runtime" "slices" + "strings" "sync" - "time" ) // https://en.wikipedia.org/wiki/ANSI_escape_code @@ -25,7 +26,8 @@ const ( CyanDim = "\033[36;2m" // this mirrors the limit value from the internal slog package maxBufferSize = 16384 - dateFormat = time.Stamp + dateFormat = "2006-01-02 15:04:05,000" + levelWidth = 10 ) var bufPool = sync.Pool{ @@ -154,7 +156,6 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { free(bufp) }() - // append time, level, then message. if h.opts.Colored { buf = fmt.Appendf(buf, WhiteDim) buf = slog.Time(slog.TimeKey, record.Time).Value.Time().AppendFormat(buf, fmt.Sprintf("%s%s ", dateFormat, Reset)) @@ -172,13 +173,13 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { default: color = Magenta } - buf = fmt.Appendf(buf, "%s%s%s ", color, record.Level.String(), Reset) - + buf = fmt.Appendf(buf, "%s%-7s%s ", color, record.Level.String(), Reset) buf = fmt.Appendf(buf, "%s%s%s ", Cyan, record.Message, Reset) } else { - buf = slog.Time(slog.TimeKey, record.Time).Value.Time().AppendFormat(buf, fmt.Sprintf("%s ", dateFormat)) - buf = fmt.Appendf(buf, "%s ", record.Level) - buf = fmt.Appendf(buf, "%s ", record.Message) + buf = slog.Time(slog.TimeKey, record.Time).Value.Time().AppendFormat(buf, dateFormat) + buf = append(buf, ' ') + buf = fmt.Appendf(buf, "%-7s ", record.Level.String()) + buf = fmt.Appendf(buf, " %s ", record.Message) } if h.opts.AddSource { @@ -194,12 +195,64 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { }) } buf = append(buf, "\n"...) + buf = []byte(formatMessage(string(buf))) h.mu.Lock() defer h.mu.Unlock() _, err := h.w.Write(buf) return err } +func formatMessage(message string) string { + parts := strings.SplitN(message, " ", 4) + if len(parts) < 4 { + return message // Not enough parts, return original message + } + + dateTime := parts[0] + " " + parts[1] + logLevel := parts[2] + content := parts[3] + + // Split content into main message and controller info + contentParts := strings.SplitN(content, "controller=", 2) + if len(contentParts) < 2 { + return message // No controller info, return original message + } + + prefixLen := len(dateFormat) + levelWidth + indent := strings.Repeat(" ", prefixLen) + + mainMessage := contentParts[0] + + var buf bytes.Buffer + buf.WriteString(dateTime) + buf.WriteByte(' ') + buf.WriteString(logLevel) + buf.WriteByte(' ') + buf.WriteString(mainMessage) + buf.WriteString("\r\n") + + words := strings.Fields(fmt.Sprintf("controller=%s", contentParts[1])) + lineLength, maxLineLength := 0, 140-prefixLen + for i, word := range words { + if i > 0 && lineLength+len(word)+1 > maxLineLength { + buf.WriteString("\r\n") + buf.WriteString(indent) + lineLength = 0 + } else if i > 0 { + buf.WriteByte(' ') + lineLength++ + } else if i == 0 { + buf.WriteString(indent) + lineLength += prefixLen + } + buf.WriteString(word) + lineLength += len(word) + } + buf.WriteString("\r\n") + + return buf.String() +} + func (h *Handler) appendKeyValuePair(buf []byte, a slog.Attr) []byte { if h.opts.Colored { if a.Key == "err" { diff --git a/pkg/logger/handler_test.go b/pkg/logger/handler_test.go new file mode 100644 index 00000000..1570b58b --- /dev/null +++ b/pkg/logger/handler_test.go @@ -0,0 +1,60 @@ +package logger + +import ( + "strings" + "testing" +) + +func TestFormatMessage(t *testing.T) { + // Define test cases + tests := []struct { + name string + input string + expected string + }{ + { + name: "Message without controller info", + input: "2024-10-20 17:06:42,779 INFO Simple log message without controller", + expected: "2024-10-20 17:06:42,779 INFO Simple log message without controller", + }, + { + name: "Message with insufficient parts", + input: "2024-10-20 17:06:42,779 INFO", + expected: "2024-10-20 17:06:42,779 INFO", + }, + { + name: "Long controller info", + input: "2024-10-20 17:06:42,779 INFO Message controller=localbuild controllerGroup=idpbuilder.cnoe.io controllerKind=Localbuild name=localdev name=localdev reconcileID=34cd11fb-3f43-4e1c-8582-ac37add91248 error=failed installing gitea: Internal error occurred: failed calling webhook validate.nginx.ingress.kubernetes.io: failed to call webhook: Post https://ingress-nginx-controller-admission.ingress-nginx.svc:443/networking/v1/ingresses?timeout=10s: dial tcp 10.96.14.62:443: connect: connection refused", + expected: "2024-10-20 17:06:42,779 INFO Message \r\n controller=localbuild controllerGroup=idpbuilder.cnoe.io\r\n controllerKind=Localbuild name=localdev name=localdev reconcileID=34cd11fb-3f43-4e1c-8582-ac37add91248\r\n error=failed installing gitea: Internal error occurred: failed calling webhook\r\n validate.nginx.ingress.kubernetes.io: failed to call webhook: Post\r\n https://ingress-nginx-controller-admission.ingress-nginx.svc:443/networking/v1/ingresses?timeout=10s: dial\r\n tcp 10.96.14.62:443: connect: connection refused", + }, + } + + // Run test cases + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + result := strings.Trim(formatMessage(tt.input), "\r\n") + if result != tt.expected { + t.Errorf("formatMessage() = %v, want %v", result, tt.expected) + } + }) + } +} + +func TestFormatMessageIndentation(t *testing.T) { + input := "2024-10-20 17:06:42,779 INFO Message controller=test" + result := strings.Trim(formatMessage(input), "\r\n") + lines := strings.Split(result, "\r\n") + + if len(lines) < 2 { + t.Fatalf("Expected at least 2 lines, got %d", len(lines)) + } + + firstLineLength := len("2024-10-20 17:06:42,779") + levelWidth + expectedIndentation := strings.Repeat(" ", firstLineLength) + + for i, line := range lines[1:] { + if !strings.HasPrefix(line, expectedIndentation) { + t.Errorf("Line %d does not have correct indentation. Expected prefix: '%s', got: '%s'", i+2, expectedIndentation, line) + } + } +}