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..0d47b5f 100644 --- a/scep_test.go +++ b/scep_test.go @@ -1,6 +1,7 @@ package scep import ( + "bytes" "crypto" "crypto/rand" "crypto/rsa" @@ -13,6 +14,8 @@ import ( "math/big" "os" "path" + "regexp" + "strings" "testing" "time" @@ -22,17 +25,29 @@ import ( "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.