mirror of
https://github.com/goharbor/harbor
synced 2024-09-20 16:47:47 +00:00
feat: log with trace ID (#18181)
feat: log trace ID Implements #18029 If the Trace ID is sent to the Harbor in HTTP header or the tracing is enabled (and the Trace ID is generated), the Trace ID will be added to the log lines as a new field. Signed-off-by: Peter Gillich <pgillich@gmail.com>
This commit is contained in:
pgillich
GitHub
parent
de6e517136
commit
eec5342490
|
|
@ -22,6 +22,7 @@ import (
|
|||
"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
|
||||
"go.opentelemetry.io/otel"
|
||||
"go.opentelemetry.io/otel/codes"
|
||||
"go.opentelemetry.io/otel/propagation"
|
||||
oteltrace "go.opentelemetry.io/otel/trace"
|
||||
)
|
||||
|
||||
|
|
@ -86,3 +87,33 @@ func NewHandler(h http.Handler, operation string) http.Handler {
|
|||
func StartTrace(ctx context.Context, tracerName string, spanName string, opts ...oteltrace.SpanStartOption) (context.Context, oteltrace.Span) {
|
||||
return otel.Tracer(tracerName).Start(ctx, spanName, opts...)
|
||||
}
|
||||
|
||||
/*
|
||||
ExractTraceID returns OpenTelemetry Trace ID
|
||||
|
||||
If tracing is enabled, the trace middleware already put the Span into request context,
|
||||
so the func returns the Trace ID form request context
|
||||
If tracing is NOT enabled, the func returns the Trace ID from the request header (if exists)
|
||||
If Trace ID is not found, the func returns empty string
|
||||
*/
|
||||
func ExractTraceID(r *http.Request) string {
|
||||
var traceID string
|
||||
if Enabled() {
|
||||
sc := oteltrace.SpanContextFromContext(r.Context())
|
||||
if sc.HasTraceID() {
|
||||
traceID = sc.TraceID().String()
|
||||
}
|
||||
}
|
||||
if traceID == "" {
|
||||
if tpHeader := r.Header.Get("traceparent"); tpHeader != "" {
|
||||
var prop propagation.TraceContext
|
||||
ctx := prop.Extract(context.Background(), propagation.HeaderCarrier(r.Header))
|
||||
sc := oteltrace.SpanContextFromContext(ctx)
|
||||
if sc.HasTraceID() {
|
||||
traceID = sc.TraceID().String()
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
return traceID
|
||||
}
|
||||
|
|
|
|||
|
|
@ -15,9 +15,15 @@
|
|||
package trace
|
||||
|
||||
import (
|
||||
"context"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"net/url"
|
||||
"testing"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
|
||||
"go.opentelemetry.io/otel/propagation"
|
||||
)
|
||||
|
||||
func TestHarborSpanNameFormatter(t *testing.T) {
|
||||
|
|
@ -88,3 +94,204 @@ func TestHarborSpanNameFormatter(t *testing.T) {
|
|||
})
|
||||
}
|
||||
}
|
||||
|
||||
func TestExractTraceID(t *testing.T) {
|
||||
type args struct {
|
||||
headers map[string]string
|
||||
ctxTraceparent string
|
||||
traceEnabled bool
|
||||
}
|
||||
tests := []struct {
|
||||
name string
|
||||
args args
|
||||
want string
|
||||
}{
|
||||
{
|
||||
name: "Dummy",
|
||||
args: args{
|
||||
headers: map[string]string{},
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Header, trace enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
traceEnabled: true,
|
||||
},
|
||||
want: "0af7651916cd43dd8448eb211c80319c",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Header, trace not enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
traceEnabled: false,
|
||||
},
|
||||
want: "0af7651916cd43dd8448eb211c80319c",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Header, invalid",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "INVALID",
|
||||
},
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context, trace enabled",
|
||||
args: args{
|
||||
headers: map[string]string{},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
traceEnabled: true,
|
||||
},
|
||||
want: "80e1afed08e019fc1110464cfa66635c",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context, trace not enabled",
|
||||
args: args{
|
||||
headers: map[string]string{},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
traceEnabled: false,
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context, invalid, trace enabled",
|
||||
args: args{
|
||||
headers: map[string]string{},
|
||||
ctxTraceparent: "INVALID",
|
||||
traceEnabled: true,
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context, invalid, trace not enabled",
|
||||
args: args{
|
||||
headers: map[string]string{},
|
||||
ctxTraceparent: "INVALID",
|
||||
traceEnabled: false,
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, trace enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
traceEnabled: true,
|
||||
},
|
||||
want: "80e1afed08e019fc1110464cfa66635c",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, trace not enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
traceEnabled: false,
|
||||
},
|
||||
want: "0af7651916cd43dd8448eb211c80319c",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, invalid #1, trace enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "INVALID",
|
||||
},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
traceEnabled: true,
|
||||
},
|
||||
want: "80e1afed08e019fc1110464cfa66635c",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, invalid #1, trace not enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "INVALID",
|
||||
},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
traceEnabled: false,
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, invalid #2, trace enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
ctxTraceparent: "INVALID",
|
||||
traceEnabled: true,
|
||||
},
|
||||
want: "0af7651916cd43dd8448eb211c80319c",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, invalid #2, trace not enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
ctxTraceparent: "INVALID",
|
||||
traceEnabled: false,
|
||||
},
|
||||
want: "0af7651916cd43dd8448eb211c80319c",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, invalid #3, trace enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "INVALID",
|
||||
},
|
||||
ctxTraceparent: "INVALID",
|
||||
traceEnabled: true,
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, invalid #3, trace not enabled",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "INVALID",
|
||||
},
|
||||
ctxTraceparent: "INVALID",
|
||||
traceEnabled: false,
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
}
|
||||
|
||||
origEnabled := C.Enabled
|
||||
defer func() {
|
||||
C.Enabled = origEnabled
|
||||
}()
|
||||
|
||||
for _, tt := range tests {
|
||||
tt := tt
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
C.Enabled = tt.args.traceEnabled
|
||||
|
||||
ctx := context.Background()
|
||||
if tt.args.ctxTraceparent != "" {
|
||||
var prop propagation.TraceContext
|
||||
ctx = prop.Extract(ctx, propagation.MapCarrier{"traceparent": tt.args.ctxTraceparent})
|
||||
}
|
||||
|
||||
req := httptest.NewRequest("GET", "/v1/library/photon/manifests/2.0", nil).WithContext(ctx)
|
||||
for h, v := range tt.args.headers {
|
||||
req.Header.Set(h, v)
|
||||
}
|
||||
|
||||
traceID := ExractTraceID(req)
|
||||
|
||||
assert.Equal(t, tt.want, traceID, tt.name)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -18,6 +18,7 @@ import (
|
|||
"net/http"
|
||||
|
||||
"github.com/goharbor/harbor/src/lib/log"
|
||||
tracelib "github.com/goharbor/harbor/src/lib/trace"
|
||||
"github.com/goharbor/harbor/src/server/middleware"
|
||||
)
|
||||
|
||||
|
|
@ -30,9 +31,15 @@ func Middleware() func(http.Handler) http.Handler {
|
|||
logger.Debugf("attach request id %s to the logger for the request %s %s", rid, r.Method, r.URL.Path)
|
||||
|
||||
ctx := log.WithLogger(r.Context(), logger.WithFields(log.Fields{"requestID": rid}))
|
||||
next.ServeHTTP(w, r.WithContext(ctx))
|
||||
} else {
|
||||
next.ServeHTTP(w, r)
|
||||
r = r.WithContext(ctx)
|
||||
}
|
||||
|
||||
traceID := tracelib.ExractTraceID(r)
|
||||
if traceID != "" {
|
||||
ctx := log.WithLogger(r.Context(), log.G(r.Context()).WithFields(log.Fields{"traceID": traceID}))
|
||||
r = r.WithContext(ctx)
|
||||
}
|
||||
|
||||
next.ServeHTTP(w, r)
|
||||
})
|
||||
}
|
||||
|
|
|
|||
|
|
@ -15,52 +15,192 @@
|
|||
package log
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"context"
|
||||
"fmt"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"regexp"
|
||||
"testing"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/suite"
|
||||
"go.opentelemetry.io/otel/propagation"
|
||||
|
||||
"github.com/goharbor/harbor/src/lib/log"
|
||||
tracelib "github.com/goharbor/harbor/src/lib/trace"
|
||||
)
|
||||
|
||||
type MiddlewareTestSuite struct {
|
||||
suite.Suite
|
||||
}
|
||||
|
||||
func (suite *MiddlewareTestSuite) TestMiddleware() {
|
||||
func (s *MiddlewareTestSuite) TestTableMiddleware() {
|
||||
next := func(fields log.Fields) http.Handler {
|
||||
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
log.G(r.Context()).WithFields(fields).Info("this is message")
|
||||
log.G(r.Context()).WithFields(fields).Info("this is message") // variable loc below refers to this line
|
||||
|
||||
w.WriteHeader(http.StatusOK)
|
||||
})
|
||||
}
|
||||
loc := "/server/middleware/log/log_test.go:41"
|
||||
locPrefix := regexp.MustCompile(fmt.Sprintf(`\[([^\s]*)%s\]`, loc))
|
||||
|
||||
{
|
||||
req := httptest.NewRequest("GET", "/v1/library/photon/manifests/2.0", nil)
|
||||
rr := httptest.NewRecorder()
|
||||
|
||||
Middleware()(next(nil)).ServeHTTP(rr, req)
|
||||
type args struct {
|
||||
headers map[string]string
|
||||
fields map[string]interface{}
|
||||
ctxTraceparent string
|
||||
}
|
||||
tests := []struct {
|
||||
name string
|
||||
args args
|
||||
want string
|
||||
}{
|
||||
{
|
||||
name: "Dummy",
|
||||
args: args{
|
||||
headers: map[string]string{},
|
||||
},
|
||||
want: fmt.Sprintf("TIMESTAMP [INFO] [%s]%s", loc,
|
||||
"[TestCase=\"Dummy\"]: this is message\n"),
|
||||
},
|
||||
{
|
||||
name: "X-Request-ID",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"X-Request-ID": "fd6139e6-9092-4181-9220-42d3d48bf658",
|
||||
},
|
||||
},
|
||||
want: fmt.Sprintf("TIMESTAMP [INFO] [%s]%s", loc,
|
||||
"[TestCase=\"X-Request-ID\" requestID=\"fd6139e6-9092-4181-9220-42d3d48bf658\"]: this is message\n"),
|
||||
},
|
||||
{
|
||||
name: "X-Request-ID, field",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"X-Request-ID": "fd6139e6-9092-4181-9220-42d3d48bf658",
|
||||
},
|
||||
fields: log.Fields{"method": "GET"},
|
||||
},
|
||||
want: fmt.Sprintf("TIMESTAMP [INFO] [%s]%s", loc,
|
||||
"[TestCase=\"X-Request-ID, field\" method=\"GET\" requestID=\"fd6139e6-9092-4181-9220-42d3d48bf658\"]: this is message\n"),
|
||||
},
|
||||
{
|
||||
name: "Traceparent Header",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
},
|
||||
want: fmt.Sprintf("TIMESTAMP [INFO] [%s]%s", loc,
|
||||
"[TestCase=\"Traceparent Header\" traceID=\"0af7651916cd43dd8448eb211c80319c\"]: this is message\n"),
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context",
|
||||
args: args{
|
||||
headers: map[string]string{},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
},
|
||||
want: fmt.Sprintf("TIMESTAMP [INFO] [%s]%s", loc,
|
||||
"[TestCase=\"Traceparent Context\" traceID=\"80e1afed08e019fc1110464cfa66635c\"]: this is message\n"),
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
},
|
||||
want: fmt.Sprintf("TIMESTAMP [INFO] [%s]%s", loc,
|
||||
"[TestCase=\"Traceparent Context+Header\" traceID=\"80e1afed08e019fc1110464cfa66635c\"]: this is message\n"),
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, X-Request-ID",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"X-Request-ID": "fd6139e6-9092-4181-9220-42d3d48bf658",
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
},
|
||||
want: fmt.Sprintf("TIMESTAMP [INFO] [%s]%s", loc,
|
||||
"[TestCase=\"Traceparent Context+Header, X-Request-ID\" requestID=\"fd6139e6-9092-4181-9220-42d3d48bf658\" traceID=\"80e1afed08e019fc1110464cfa66635c\"]: this is message\n"),
|
||||
},
|
||||
{
|
||||
name: "Traceparent Context+Header, X-Request-ID, field",
|
||||
args: args{
|
||||
headers: map[string]string{
|
||||
"X-Request-ID": "fd6139e6-9092-4181-9220-42d3d48bf658",
|
||||
"traceparent": "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
|
||||
},
|
||||
ctxTraceparent: "00-80e1afed08e019fc1110464cfa66635c-7a085853722dc6d2-01",
|
||||
fields: log.Fields{"method": "GET"},
|
||||
},
|
||||
want: fmt.Sprintf("TIMESTAMP [INFO] [%s]%s", loc,
|
||||
"[TestCase=\"Traceparent Context+Header, X-Request-ID, field\" method=\"GET\" requestID=\"fd6139e6-9092-4181-9220-42d3d48bf658\" traceID=\"80e1afed08e019fc1110464cfa66635c\"]: this is message\n"),
|
||||
},
|
||||
}
|
||||
|
||||
{
|
||||
req := httptest.NewRequest("GET", "/v1/library/photon/manifests/2.0", nil)
|
||||
req.Header.Set("X-Request-ID", "fd6139e6-9092-4181-9220-42d3d48bf658")
|
||||
rr := httptest.NewRecorder()
|
||||
origEnabled := tracelib.C.Enabled
|
||||
defer func() {
|
||||
tracelib.C.Enabled = origEnabled
|
||||
}()
|
||||
tracelib.C.Enabled = true
|
||||
|
||||
Middleware()(next(nil)).ServeHTTP(rr, req)
|
||||
}
|
||||
for _, tt := range tests {
|
||||
tt := tt
|
||||
s.T().Run(tt.name, func(t *testing.T) {
|
||||
b := make([]byte, 0, 200)
|
||||
buf := bytes.NewBuffer(b)
|
||||
formatter := log.NewTextFormatter()
|
||||
formatter.SetTimeFormat("TIMESTAMP")
|
||||
logger := log.New(buf, formatter, log.InfoLevel, 3).WithField("TestCase", tt.name)
|
||||
ctx := log.WithLogger(context.Background(), logger)
|
||||
if tt.args.ctxTraceparent != "" {
|
||||
var prop propagation.TraceContext
|
||||
ctx = prop.Extract(ctx, propagation.MapCarrier{"traceparent": tt.args.ctxTraceparent})
|
||||
}
|
||||
|
||||
{
|
||||
req := httptest.NewRequest("GET", "/v1/library/photon/manifests/2.0", nil)
|
||||
req.Header.Set("X-Request-ID", "fd6139e6-9092-4181-9220-42d3d48bf658")
|
||||
rr := httptest.NewRecorder()
|
||||
req := httptest.NewRequest("GET", "/v1/library/photon/manifests/2.0", nil).WithContext(ctx)
|
||||
for h, v := range tt.args.headers {
|
||||
req.Header.Set(h, v)
|
||||
}
|
||||
rr := httptest.NewRecorder()
|
||||
|
||||
Middleware()(next(log.Fields{"method": req.Method})).ServeHTTP(rr, req)
|
||||
Middleware()(next(tt.args.fields)).ServeHTTP(rr, req)
|
||||
|
||||
line := string(removeSubmatch(locPrefix, buf.Bytes()))
|
||||
s.Equal(tt.want, line, tt.name)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func TestMiddlewareTestSuite(t *testing.T) {
|
||||
suite.Run(t, &MiddlewareTestSuite{})
|
||||
}
|
||||
|
||||
func removeSubmatch(matchRe *regexp.Regexp, line []byte) []byte {
|
||||
matches := matchRe.FindSubmatchIndex(line)
|
||||
if len(matches) < 4 {
|
||||
return line
|
||||
}
|
||||
|
||||
return append(line[0:matches[2]], line[matches[3]:]...)
|
||||
}
|
||||
|
||||
func TestRemoveSubmatch(t *testing.T) {
|
||||
loc := "/server/middleware/log/log_test.go:41"
|
||||
locPrefix := regexp.MustCompile(fmt.Sprintf(`\[([^\s]*)%s\]`, loc))
|
||||
|
||||
line := `TIMESTAMP [INFO] [/github.com/goharbor/harbor/src/server/middleware/log/log_test.go:41][method="GET" requestID="fd6139e6-9092-4181-9220-42d3d48bf658" traceID="80e1afed08e019fc1110464cfa66635c"]: this is message`
|
||||
assert.Equal(t, `TIMESTAMP [INFO] [/server/middleware/log/log_test.go:41][method="GET" requestID="fd6139e6-9092-4181-9220-42d3d48bf658" traceID="80e1afed08e019fc1110464cfa66635c"]: this is message`,
|
||||
string(removeSubmatch(locPrefix, []byte(line))),
|
||||
)
|
||||
|
||||
line = `TIMESTAMP [INFO] [/server/middleware/log/log_test.go:41][method="GET" requestID="fd6139e6-9092-4181-9220-42d3d48bf658" traceID="80e1afed08e019fc1110464cfa66635c"]: this is message`
|
||||
assert.Equal(t, `TIMESTAMP [INFO] [/server/middleware/log/log_test.go:41][method="GET" requestID="fd6139e6-9092-4181-9220-42d3d48bf658" traceID="80e1afed08e019fc1110464cfa66635c"]: this is message`,
|
||||
string(removeSubmatch(locPrefix, []byte(line))),
|
||||
)
|
||||
|
||||
}
|
||||
|
|
|
|||
Loading…
Reference in New Issue
Block a user