diff --git a/go.mod b/go.mod index 1eec711..26f0e8c 100644 --- a/go.mod +++ b/go.mod @@ -3,11 +3,6 @@ module github.com/smallstep/scep go 1.16 require ( - github.com/go-kit/kit v0.4.0 + github.com/go-kit/log v0.2.1 github.com/smallstep/pkcs7 v0.0.0-20231024181729-3b98ecc1ca81 ) - -require ( - github.com/go-logfmt/logfmt v0.5.1 // indirect - github.com/go-stack/stack v1.6.0 // indirect -) diff --git a/go.sum b/go.sum index e4723fa..eb826c1 100644 --- a/go.sum +++ b/go.sum @@ -1,8 +1,6 @@ -github.com/go-kit/kit v0.4.0 h1:KeVK+Emj3c3S4eRztFuzbFYb2BAgf2jmwDwyXEri7Lo= -github.com/go-kit/kit v0.4.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as= +github.com/go-kit/log v0.2.1 h1:MRVx0/zhvdseW+Gza6N9rVzU/IVzaeE1SFI4raAhmBU= +github.com/go-kit/log v0.2.1/go.mod h1:NwTd00d/i8cPZ3xOwwiv2PO5MOcx78fFErGNcVmBjv0= github.com/go-logfmt/logfmt v0.5.1 h1:otpy5pqBCBZ1ng9RQ0dPu4PN7ba75Y/aA+UpowDyNVA= github.com/go-logfmt/logfmt v0.5.1/go.mod h1:WYhtIu8zTZfxdn5+rREduYbwxfcBr/Vr6KEVveWlfTs= -github.com/go-stack/stack v1.6.0 h1:MmJCxYVKTJ0SplGKqFVX3SBnmaUhODHZrrFF6jMbpZk= -github.com/go-stack/stack v1.6.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY= github.com/smallstep/pkcs7 v0.0.0-20231024181729-3b98ecc1ca81 h1:B6cED3iLJTgxpdh4tuqByDjRRKan2EvtnOfHr2zHJVg= github.com/smallstep/pkcs7 v0.0.0-20231024181729-3b98ecc1ca81/go.mod h1:SoUAr/4M46rZ3WaLstHxGhLEgoYIDRqxQEXLOmOEB0Y= diff --git a/scep.go b/scep.go index 2184fb6..8004af2 100644 --- a/scep.go +++ b/scep.go @@ -14,7 +14,6 @@ import ( "errors" "fmt" - "github.com/go-kit/kit/log/level" "github.com/smallstep/pkcs7" "github.com/smallstep/scep/cryptoutil" @@ -27,12 +26,6 @@ var ( errUnknownMessageType = errors.New("scep: unknown messageType") ) -// prepare the go-kit leveled logging configuration -var ( - levelKey = level.Key() - levelDebug = level.DebugValue() -) - // The MessageType attribute specifies the type of operation performed // by the transaction. This attribute MUST be included in all PKI // messages. @@ -276,7 +269,6 @@ func ParsePKIMessage(data []byte, opts ...Option) (*PKIMessage, error) { } msg.logger.Log( - levelKey, levelDebug, "msg", "parsed scep pkiMessage", "scep_message_type", msgType, "transaction_id", tID, @@ -369,7 +361,6 @@ func (msg *PKIMessage) DecryptPKIEnvelope(cert *x509.Certificate, key crypto.Pri } logKeyVals := []interface{}{ - levelKey, levelDebug, "msg", "decrypt pkiEnvelope", } defer func() { msg.logger.Log(logKeyVals...) }() @@ -613,7 +604,6 @@ func NewCSRRequest(csr *x509.CertificateRequest, tmpl *PKIMessage, opts ...Optio } conf.logger.Log( - levelKey, levelDebug, "msg", "creating SCEP CSR request", "transaction_id", tID, "signer_cn", tmpl.SignerCert.Subject.CommonName, diff --git a/scep_test.go b/scep_test.go index cd92a3d..a27bb24 100644 --- a/scep_test.go +++ b/scep_test.go @@ -1,6 +1,7 @@ package scep import ( + "bytes" "crypto" "crypto/rand" "crypto/rsa" @@ -13,26 +14,40 @@ import ( "math/big" "os" "path" + "regexp" + "strings" "testing" "time" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" + "github.com/go-kit/log" + "github.com/go-kit/log/level" "github.com/smallstep/scep/cryptoutil" ) +var newLines = regexp.MustCompile("\r?\n") + func testParsePKIMessage(t *testing.T, data []byte) *PKIMessage { t.Helper() - logger := log.NewLogfmtLogger(os.Stderr) + buf := bytes.Buffer{} + logger := log.NewLogfmtLogger(&buf) logger = level.NewFilter(logger, level.AllowDebug()) + logger = level.NewInjector(logger, level.DebugValue()) + msg, err := ParsePKIMessage(data, WithLogger(logger)) if err != nil { t.Fatal(err) } validateParsedPKIMessage(t, msg) + + lines := newLines.Split(strings.TrimSpace(buf.String()), -1) + if len(lines) != 1 { + t.Errorf("expected single log line") + } + validateLogLevelDebug(t, lines) + return msg } @@ -57,6 +72,39 @@ func validateParsedPKIMessage(t *testing.T, msg *PKIMessage) { } } +// textAttrs captures all key=value pairs produced the go-kit logger +var textAttrs = regexp.MustCompile(`(\w+(?:\.\w+)*)=("(?:\\"|[^"])*"|\[.*?\]|[^ ]+)`) + +// splitTextAttrs splits the input string into key=value pairs. Every pair is +// returned as a single string. +func splitTextAttrs(input string) []string { + return textAttrs.FindAllString(input, -1) +} + +// validateLogLevelDebug validates the input string has the debug level +// set on each non-empty line. +func validateLogLevelDebug(t *testing.T, lines []string) { + t.Helper() + + for _, line := range lines { + if line == "" { + continue + } + + attrs := splitTextAttrs(line) + countLogLevel := 0 + for _, a := range attrs { + if a == "level=debug" { + countLogLevel += 1 + } + } + + if countLogLevel != 1 { + t.Errorf("expected log level debug to be set once; found %d occurrences", countLogLevel) + } + } +} + // Tests the case when servers reply with PKCS #7 signed-data that contains no // certificates assuming that the client can request CA certificates using // GetCaCert request. @@ -230,7 +278,12 @@ func TestNewCSRRequest(t *testing.T) { SignerKey: clientkey, } - pkcsreq, err := NewCSRRequest(csr, tmpl, WithCertsSelector(test.certsSelectorFunc)) + buf := bytes.Buffer{} + logger := log.NewLogfmtLogger(&buf) + logger = level.NewFilter(logger, level.AllowDebug()) + logger = level.NewInjector(logger, level.DebugValue()) + + pkcsreq, err := NewCSRRequest(csr, tmpl, WithCertsSelector(test.certsSelectorFunc), WithLogger(logger)) if test.shouldCreateCSR && err != nil { t.Fatalf("keyUsage: %d, failed creating a CSR request: %v", test.keyUsage, err) } @@ -241,6 +294,12 @@ func TestNewCSRRequest(t *testing.T) { return } + lines := newLines.Split(strings.TrimSpace(buf.String()), -1) + if len(lines) != 1 { + t.Errorf("expected single log line") + } + validateLogLevelDebug(t, lines) + msg := testParsePKIMessage(t, pkcsreq.Raw) err = msg.DecryptPKIEnvelope(cacert, cakey) if err != nil {