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.

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

Bug: BasicLogger Panics When len(keyvals) is 1 #856

Open
vicluq opened this issue Nov 6, 2024 · 3 comments
Open

Bug: BasicLogger Panics When len(keyvals) is 1 #856

vicluq opened this issue Nov 6, 2024 · 3 comments
Labels
bug Something isn't working has pr

Comments

@vicluq
Copy link

vicluq commented Nov 6, 2024

Context

When calling kgo.BasicLogger .Log() with only one extra argument (len(keyvals) = 1), it panics because len(keyvals) / 2 will be 0 for int variables, the second parameter of strings.Repeat. Since the result is 0, the length of the format variable will be 0, which will cause an out of slice bound access. Therefore that single value should be an EXTRA attribute such as when passing an even number of keyvals.

Refer to PR #857

Error Reproduction

package main

import (
	"os"
	"time"

	"github.com/twmb/franz-go/pkg/kgo"
)

func main() {
	logger := kgo.BasicLogger(os.Stderr, kgo.LogLevelInfo, func() string {
		return time.Now().Format("[2006-01-02 15:04:05.999] ")
	})

	logger.Log(kgo.LogLevelDebug, "main message", "key1")
	// Error: Key1 should be an EXTRA, but it panics
}

Output:

panic: runtime error: slice bounds out of range [:-2]

goroutine 1 [running]:
github.com/twmb/franz-go/pkg/kgo.(*basicLogger).Log(0x14000153f18, 0x4, {0x104168e66, 0xc}, {0x14000153f08, 0x1, 0x1})
	/Users/victorialuquet/go/pkg/mod/github.com/twmb/[email protected]/pkg/kgo/logger.go:92 +0x26c
main.main()
	/Users/victorialuquet/documents/go_tests/kgo_logger_debug.go:16 +0x98
exit status 2

But, when passing an even number of keyvals greater than 1, it is treated as an EXTRA attribute and we have the following behavior:

	logger.Log(kgo.LogLevelDebug, "main message", "key1", "val1") // Normal key value
	logger.Log(kgo.LogLevelDebug, "main message", "key1", "val1", "key2")
	logger.Log(kgo.LogLevelDebug, "main message", "key1", "val1", "key2", "val2")

Output:

[2024-11-06 19:29:49.425] [DEBUG] main message; key1: val1
[2024-11-06 19:29:49.425] [DEBUG] main message; key1: val1%!(EXTRA string=key2)
[2024-11-06 19:29:49.425] [DEBUG] main message; key1: val1, key2: val2

Expected Behavior

If keyvals length is equal to 1, it should be treated as an EXTRA as follows:

[2024-11-06 19:32:06.375] [DEBUG] main message; %!(EXTRA string=key1)
@twmb
Copy link
Owner

twmb commented Feb 4, 2025

See comment on PR -- I'm okay keeping a change if a "missing" field is added, but do not want to strip an extraneous extra argument. As is, the basic logger contract specifies that it should be key/value fields, and Go is no stranger to panicking on invalid usage of APIs.

@twmb twmb closed this as completed Feb 4, 2025
@vicluq
Copy link
Author

vicluq commented Feb 7, 2025

See comment on PR -- I'm okay keeping a change if a "missing" field is added, but do not want to strip an extraneous extra argument. As is, the basic logger contract specifies that it should be key/value fields, and Go is no stranger to panicking on invalid usage of APIs.

Yes, sure! I just think that from a user point of view, that wasn't very clear and, since it is suposed to be used as key/value arguments, it should also panic on an even number of elements, right?

I think that if you want to ensure that behaviour, a good idea would be to follow the slog or zap loggers patterns, in wich you specify the fields such as below:

logger.Log(kgo.LogLevelDebug, "main message", log.String("key", "Value"), log.Bool("key2", true))

@twmb twmb reopened this Feb 10, 2025
@twmb
Copy link
Owner

twmb commented Feb 18, 2025

Adding slog or zap APIs would expand the API surface a bit more than seemingly needed at the moment.

That said, I misread your original PR -- I thought it was trimming an argument, not a trailing comma / space. My mistake, I'll merge it into the next release.

@twmb twmb added the bug Something isn't working label Feb 18, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working has pr
Projects
None yet
Development

No branches or pull requests

2 participants