Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[VC-35738] Log with klog to stdout and stderr in Kubernetes text format #596

Merged
merged 12 commits into from
Oct 31, 2024
Merged

[VC-35738] Log with klog to stdout and stderr in Kubernetes text format #596

Changes from 1 commit
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
e745fe0
Log with klog to stdout and stderr in JSON format
wallrj Oct 14, 2024
08d5e8c
logs_test.go: assert didn't make the test exit with 1, move to require
maelvls Oct 18, 2024
dcca1b3
logs_test.go: assert the logs themselves
maelvls Oct 18, 2024
ba052e4
logs.go: move to slog and show the src (vcert or agent) of the logs
maelvls Oct 18, 2024
fda1d3e
logs.go: re-wrap the introductionary comment, AKA -> aka.
maelvls Oct 18, 2024
e4bf7cb
logs.go: LogToSlogWriter wasn't setting the right logs as ERROR
maelvls Oct 18, 2024
d9bc223
logs_test.go: replaceWithStaticTimestamps breaks for short PIDs
maelvls Oct 18, 2024
c39594a
logs.go: use --log-level instead of --v
maelvls Oct 18, 2024
f3b721e
logs_test.go: replaceWithStaticTimestamps: ts may not have nanoseconds
maelvls Oct 18, 2024
6f8c52e
Set the default logging format to text
wallrj Oct 25, 2024
73526f3
Remove redundant test for vcert log prefix
wallrj Oct 25, 2024
54eb5a5
Fix some out-of-date comments
wallrj Oct 29, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Prev Previous commit
Next Next commit
logs_test.go: assert the logs themselves 
That's useful to keep track what the logs look like, especially now that
I'm trying to switch from plain klog to slog.
  • Loading branch information
@maelvls @wallrj
maelvls authored and wallrj committed Oct 29, 2024
commit dcca1b38693e9f3dbae1d614b3967a2449412f5d
171 changes: 168 additions & 3 deletions pkg/logs/logs_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,13 +8,13 @@ import (
"log/slog"
"os"
"os/exec"
"regexp"
"strings"
"testing"
"time"

_ "github.com/Venafi/vcert/v5"
"github.com/spf13/pflag"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"k8s.io/klog/v2"

Expand Down Expand Up @@ -64,54 +64,178 @@ func TestLogs(t *testing.T) {
flags string
skipIntialize bool
expectError bool
expectStdout string
expectStderr string
}{
{
name: "help",
flags: "-h",
expectError: true,
expectStdout: `
pflag: help requested
`,
expectStderr: `
Usage of test-logs:
--logging-format string Sets the log format. Permitted formats: "json", "text". (default "json")
-v, --v Level number for the log level verbosity
--vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format)
`,
},
{
name: "unrecognized-flag",
flags: "--foo",
expectError: true,
expectStdout: `
unknown flag: --foo
`,
expectStderr: `
unknown flag: --foo
Usage of test-logs:
--logging-format string Sets the log format. Permitted formats: "json", "text". (default "json")
-v, --v Level number for the log level verbosity
--vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format)
`,
},
{
name: "logging-format-unrecognized",
flags: "--logging-format=foo",
expectError: true,
expectStderr: `
Error in logging configuration: format: Invalid value: "foo": Unsupported log format
`,
},
{
name: "original-defaults",
flags: "",
skipIntialize: true,
expectStderr: `
vCert: 0000/00/00 00:00:00 log Print
vCert: 0000/00/00 00:00:00 INFO slog Info
vCert: 0000/00/00 00:00:00 WARN slog Warn
vCert: 0000/00/00 00:00:00 ERROR slog Error
I0000 00:00:00.000000 00000 logs_test.go:000] klog Info
W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning
E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error"
I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value"
E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value"
`,
},
{
name: "modified-defaults",
flags: "",
expectStdout: `
{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wish we were able to show the real source of the log line rather than the generic logs/logs_test.go. I guess we can improve this once we have migrated the logs.Log.Printf calls to slog.Info.

{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"}
`,
expectStderr: `
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"}
{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"}
`,
},
{
name: "logging-format-json",
flags: "--logging-format=json",
expectStdout: `
{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"}
`,
expectStderr: `
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"}
{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"}
`,
},
{
name: "log-json-split-stream-false",
flags: "--logging-format=json --log-json-split-stream=false",
expectStderr: `
{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"}
{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"}
`,
},
{
name: "logging-format-text",
flags: "--logging-format=text",
expectStdout: `
I0000 00:00:00.000000 00000 log.go:000] log Print
I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info"
I0000 00:00:00.000000 00000 logs_test.go:000] klog Info
I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value"
`,
expectStderr: `
W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn"
E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error"
W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning
E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error"
E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value"
`,
},
{
name: "log-text-split-stream-false",
flags: "--logging-format=text --log-text-split-stream=false",
expectStderr: `
I0000 00:00:00.000000 00000 log.go:000] log Print
I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info"
W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn"
E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error"
I0000 00:00:00.000000 00000 logs_test.go:000] klog Info
W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning
E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error"
I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value"
E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value"
`,
},
{
name: "v-level-3",
flags: "--v=3",
expectStdout: `
{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"}
{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual Info Level 3","v":3,"key":"value"}
`,
expectStderr: `
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"}
{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"}
{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"}
`,
},
{
name: "vmodule-level-3",
flags: "--logging-format=text --vmodule=logs_test=3",
expectStdout: `
I0000 00:00:00.000000 00000 log.go:000] log Print
I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info"
I0000 00:00:00.000000 00000 logs_test.go:000] klog Info
I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value"
I0000 00:00:00.000000 00000 logs_test.go:000] "Contextual Info Level 3" logger="foo" key="value"
`,
expectStderr: `
W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn"
E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error"
W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning
E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error"
E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value"
`,
},
}

Expand All @@ -138,8 +262,10 @@ func TestLogs(t *testing.T) {

t.Logf("FLAGS\n%s\n", test.flags)
// Remove the standard output generated by `-test.v`
t.Logf("STDOUT\n%s\n", strings.TrimPrefix(stdout.String(), "=== RUN TestLogs\n"))
t.Logf("STDERR\n%s\n", stderr.String())
stdoutStr := strings.TrimPrefix(stdout.String(), "=== RUN TestLogs\n")
stderrStr := stderr.String()
t.Logf("STDOUT\n%s\n", stdoutStr)
t.Logf("STDERR\n%s\n", stderrStr)
if test.expectError {
var target *exec.ExitError
require.ErrorAs(t, err, &target)
Expand All @@ -148,6 +274,45 @@ func TestLogs(t *testing.T) {
} else {
require.NoError(t, err)
}

// This trick helps with the readability of the table test: we can
// have the first "expected" log line at the same level as the other
// lines.
test.expectStdout = strings.TrimPrefix(test.expectStdout, "\n")
test.expectStderr = strings.TrimPrefix(test.expectStderr, "\n")

require.Equal(t, test.expectStdout, replaceWithStaticTimestamps(stdoutStr), "stdout doesn't match")
require.Equal(t, test.expectStderr, replaceWithStaticTimestamps(stderrStr), "stderr doesn't match")
})
}
}

var (
timestampRegexpStdLog = regexp.MustCompile(`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}`)
timestampRegexpKlog = regexp.MustCompile(`\d{4} \d{2}:\d{2}:\d{2}\.\d{6} \d{5}`)
timestampRegexpJSON = regexp.MustCompile(`"ts":\d+\.\d+`)
fileAndLineRegexpJSON = regexp.MustCompile(`"caller":"([^"]+).go:\d+"`)
fileAndLineRegexpKlog = regexp.MustCompile(` ([^:]+).go:\d+`)
)

// Replaces the klog and JSON timestamps with a static timestamp to make it
// easier to assert the logs. It also replaces the line number with 000 as it
// often changes.
//
// I1018 15:12:57.953433 22183 logs.go:000] log
// {"ts":1729258473588.828,"caller":"log/log.go:000","msg":"log Print","v":0}
// 2024/10/18 15:40:50 log Print
//
// to the fixed:
//
// I0000 00:00:00.000000 00000 logs.go:000] log
// {"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0}
// 0000/00/00 00:00:00 log Print
func replaceWithStaticTimestamps(input string) string {
input = timestampRegexpKlog.ReplaceAllString(input, "0000 00:00:00.000000 00000")
input = timestampRegexpJSON.ReplaceAllString(input, `"ts":0000000000000.000`)
input = timestampRegexpStdLog.ReplaceAllString(input, "0000/00/00 00:00:00")
input = fileAndLineRegexpJSON.ReplaceAllString(input, `"caller":"$1.go:000"`)
input = fileAndLineRegexpKlog.ReplaceAllString(input, " $1.go:000")
return input
}