diff --git a/correlation/field.go b/correlation/field.go index db4c4815e29b548930f7ef25f2f118d21dbcbcbb..35cfbc35cdc1837578e6e87f315a82936955e4da 100644 --- a/correlation/field.go +++ b/correlation/field.go @@ -1,3 +1,4 @@ package correlation +// FieldName is the field used in structured logs that represents the correlationID const FieldName = "correlation_id" diff --git a/correlation/generator.go b/correlation/generator.go index b9cf7fd7ed658566e0ae948bade2c0091e756028..c81e63ca00b7baf62e547377af02c6071e1e1b03 100644 --- a/correlation/generator.go +++ b/correlation/generator.go @@ -1,47 +1,39 @@ package correlation import ( - "crypto/rand" - "fmt" - "log" - "math" - "math/big" - "net/http" + "io" "time" -) -var ( - randMax = big.NewInt(math.MaxInt64) - randSource = rand.Reader + "github.com/oklog/ulid/v2" ) -// generateRandomCorrelationID will attempt to generate a correlationid randomly -// or raise an error -func generateRandomCorrelationID() (string, error) { - id, err := rand.Int(randSource, randMax) - if err != nil { - return "", err - } - base62 := encodeReverseBase62(id.Int64()) - - return base62, nil -} +// By default we use nil, which tells ulid to use its own +// internal entropy source, but we replace this for testing +// purposes +var ulidEntropySource io.Reader = nil -func generatePseudorandomCorrelationID(req *http.Request) string { - return fmt.Sprintf("E:%s:%s", req.RemoteAddr, encodeReverseBase62(time.Now().UnixNano())) +func generatePseudorandomCorrelationID() string { + return "E:" + encodeReverseBase62(time.Now().UnixNano()) } // generateRandomCorrelationID will attempt to generate a correlationid randomly // if this fails, will log a message and fallback to a pseudorandom approach -func generateRandomCorrelationIDWithFallback(req *http.Request) string { - correlationID, err := generateRandomCorrelationID() - if err == nil { - return correlationID +func generateRandomCorrelationIDWithFallback() string { + uid, err := ulid.New(ulid.Timestamp(time.Now()), ulidEntropySource) + if err != nil { + // Swallow the error and return a pseudorandom correlation_id. + // Operators can determine that an error occurred by the shape of the + // correlation_id, which will be prefixed with a `E:` + return generatePseudorandomCorrelationID() } - log.Printf("can't generate random correlation-id: %v", err) - return generatePseudorandomCorrelationID(req) + return uid.String() } -// RandomID attempts to generate a random correlation ID -func RandomID() (string, error) { return generateRandomCorrelationID() } +// RandomID generates a random correlation ID. +// Deprecated: use SafeRandomID instead. +// Note, that this method will not return an error, it is here for compatibility reasons only. +func RandomID() (string, error) { return generateRandomCorrelationIDWithFallback(), nil } + +// SafeRandomID generates a random correlation ID. +func SafeRandomID() string { return generateRandomCorrelationIDWithFallback() } diff --git a/correlation/generator_test.go b/correlation/generator_test.go index 9eb0bad95d78aa62e6858eda5042ba52ce3f68f5..f5539fa5bbc463a98b342d98833b12c575a53f67 100644 --- a/correlation/generator_test.go +++ b/correlation/generator_test.go @@ -2,56 +2,79 @@ package correlation import ( "bytes" - "net/http" "strings" "testing" + "time" + "github.com/oklog/ulid" "github.com/stretchr/testify/require" ) -func Test_generateRandomCorrelationID(t *testing.T) { - require := require.New(t) +func emptyRandomSource() func() { + oldEntropySource := ulidEntropySource - got, err := generateRandomCorrelationID() - require.NoError(err) - require.NotEqual(got, "", "Expected a non-empty string response") + // Use an empty random source, which will lead to ULID generation failure + ulidEntropySource = &bytes.Buffer{} + + return func() { + ulidEntropySource = oldEntropySource + } +} + +func requireValidRecentULID(require *require.Assertions, got string) { + uid, err := ulid.Parse(got) + require.NoError(err, "Expected correlationID to be a valid ULID, got %s", got) + + utime := ulid.Time(uid.Time()) + diff := time.Since(utime) + require.True(diff > 0, "Expected ULID to be generated in the past") + require.True(diff < 1*time.Second, "Expected ULID to be generated with recent timestamp. Timestamp is %v", utime) } -func Test_generatePseudorandomCorrelationID(t *testing.T) { +func TestRandom(t *testing.T) { require := require.New(t) - req, err := http.NewRequest("GET", "http://example.com", nil) - require.NoError(err) + got, err := RandomID() + require.NoError(err, "Expected no error from RandomID") - got := generatePseudorandomCorrelationID(req) - require.NotEqual(got, "", "Expected a non-empty string response") - require.True(strings.HasPrefix(got, "E:"), "Expected the psuedorandom correlator to have an `E:` prefix") + requireValidRecentULID(require, got) } -func Test_generateRandomCorrelationIDWithFallback(t *testing.T) { +func TestSafeRandom(t *testing.T) { require := require.New(t) - req, err := http.NewRequest("GET", "http://example.com", nil) - require.NoError(err) + got := SafeRandomID() + requireValidRecentULID(require, got) +} - got := generateRandomCorrelationIDWithFallback(req) +func TestRandomEntropyFailure(t *testing.T) { + restore := emptyRandomSource() + defer restore() + + require := require.New(t) + + got, err := RandomID() + + require.NoError(err, "Expected no error from RandomID") require.NotEqual(got, "", "Expected a non-empty string response") - require.False(strings.HasPrefix(got, "E:"), "Not expecting fallback to pseudorandom correlationID") + require.True(strings.HasPrefix(got, "E:"), "Expecting fallback to pseudorandom correlationID") } -func Test_generateRandomCorrelationIDWithFallback_entropy_fail(t *testing.T) { - oldRandReader := randSource - randSource = &bytes.Buffer{} - defer func() { - randSource = oldRandReader - }() +func TestSafeRandomEntropyFailure(t *testing.T) { + restore := emptyRandomSource() + defer restore() require := require.New(t) - req, err := http.NewRequest("GET", "http://example.com", nil) - require.NoError(err) + got := SafeRandomID() - got := generateRandomCorrelationIDWithFallback(req) require.NotEqual(got, "", "Expected a non-empty string response") require.True(strings.HasPrefix(got, "E:"), "Expecting fallback to pseudorandom correlationID") } + +func BenchmarkSafeRandomID(b *testing.B) { + // run the Fib function b.N times + for n := 0; n < b.N; n++ { + SafeRandomID() + } +} diff --git a/correlation/inbound_http.go b/correlation/inbound_http.go index 28dd7552a81d84cc6d07703876d247fdf8d852ae..a1d2ff9434565cb7da3832d043a252150e201a8a 100644 --- a/correlation/inbound_http.go +++ b/correlation/inbound_http.go @@ -23,7 +23,7 @@ func InjectCorrelationID(h http.Handler, opts ...InboundHandlerOption) http.Hand } if correlationID == "" { - correlationID = generateRandomCorrelationIDWithFallback(r) + correlationID = SafeRandomID() } ctx := ContextWithCorrelation(parent, correlationID) diff --git a/go.mod b/go.mod index 343d62adf8b2f63505aebe2013e1287f3774200e..1acef5bc31443ebd060bf3cea41a5088e2459702 100644 --- a/go.mod +++ b/go.mod @@ -13,6 +13,8 @@ require ( github.com/jstemmer/go-junit-report v0.9.1 // indirect github.com/konsorten/go-windows-terminal-sequences v1.0.2 // indirect github.com/lightstep/lightstep-tracer-go v0.15.6 + github.com/oklog/ulid v1.3.1 + github.com/oklog/ulid/v2 v2.0.2 github.com/opentracing/opentracing-go v1.0.2 github.com/philhofer/fwd v1.0.0 // indirect github.com/prometheus/client_golang v1.0.0 diff --git a/go.sum b/go.sum index 577f1deaa927b09c23584e783d5e8481c970c5bc..0e96f17a0049031ec92118018cdcbb70f2d95bf0 100644 --- a/go.sum +++ b/go.sum @@ -184,6 +184,10 @@ github.com/mwitkow/go-conntrack v0.0.0-20161129095857-cc309e4a2223/go.mod h1:qRW github.com/nats-io/nats.go v1.8.1/go.mod h1:BrFz9vVn0fU3AcH9Vn4Kd7W0NpJ651tD5omQ3M8LwxM= github.com/nats-io/nkeys v0.0.2/go.mod h1:dab7URMsZm6Z/jp9Z5UGa87Uutgc2mVpXLC4B7TDb/4= github.com/nats-io/nuid v1.0.1/go.mod h1:19wcPz3Ph3q0Jbyiqsd0kePYG7A95tJPxeL+1OSON2c= +github.com/oklog/ulid v1.3.1 h1:EGfNDEx6MqHz8B3uNV6QAib1UR2Lm97sHi3ocA6ESJ4= +github.com/oklog/ulid v1.3.1/go.mod h1:CirwcVhetQ6Lv90oh/F+FBtV6XMibvdAFo93nm5qn4U= +github.com/oklog/ulid/v2 v2.0.2 h1:r4fFzBm+bv0wNKNh5eXTwU7i85y5x+uwkxCUTNVQqLc= +github.com/oklog/ulid/v2 v2.0.2/go.mod h1:mtBL0Qe/0HAx6/a4Z30qxVIAL1eQDweXq5lxOEiwQ68= github.com/onsi/ginkgo v1.6.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE= github.com/onsi/ginkgo v1.10.3 h1:OoxbjfXVZyod1fmWYhI7SEyaD8B00ynP3T+D5GiyHOY= github.com/onsi/ginkgo v1.10.3/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE= @@ -191,6 +195,7 @@ github.com/onsi/gomega v1.7.1 h1:K0jcRCwNQM3vFGh1ppMtDh/+7ApJrjldlX8fA0jDTLQ= github.com/onsi/gomega v1.7.1/go.mod h1:XdKZgCCFLUoM/7CFJVPcG8C1xQ1AJ0vpAezJrB7JYyY= github.com/opentracing/opentracing-go v1.0.2 h1:3jA2P6O1F9UOrWVpwrIo17pu01KWvNWg4X946/Y5Zwg= github.com/opentracing/opentracing-go v1.0.2/go.mod h1:UkNAQd3GIcIGf0SeVgPpRdFStlNbqXla1AfSYxPUl2o= +github.com/pborman/getopt v0.0.0-20170112200414-7148bc3a4c30/go.mod h1:85jBQOZwpVEaDAr341tbn15RS4fCAsIst0qp7i8ex1o= github.com/pelletier/go-toml v1.2.0/go.mod h1:5z9KED0ma1S8pY6P1sdut58dfprrGBbd/94hg7ilaic= github.com/philhofer/fwd v1.0.0 h1:UbZqGr5Y38ApvM/V/jEljVxwocdweyH+vmYvRPBnbqQ= github.com/philhofer/fwd v1.0.0/go.mod h1:gk3iGcWd9+svBvR0sR+KPcfE+RNWozjowpeBVG3ZVNU=