ai cooking
Propagate operation IDs, add context-aware logging, and include operation IDs in AppInsights tracking (#378)
* Correlate App Insights request telemetry with operation IDs
* ignore traceparent and request-id for now
---------
Co-authored-by: paul miller <paul.miller>
authored by
Paul Miller
paul miller
and committed by
GitHub
4820cad8
e81da5ca
+153
-8
+33
-5
cmd/careme/middleware.go
+33
-5
cmd/careme/middleware.go
···
1
1
package main
2
2
3
3
import (
4
+
"context"
4
5
"errors"
5
6
"log/slog"
6
7
"net/http"
···
14
15
"careme/internal/logsetup"
15
16
16
17
"github.com/clerk/clerk-sdk-go/v2"
18
+
"github.com/google/uuid"
17
19
azureappinsights "github.com/microsoft/ApplicationInsights-Go/appinsights"
20
+
"github.com/microsoft/ApplicationInsights-Go/appinsights/contracts"
18
21
)
19
22
20
23
type logger struct {
···
45
48
return
46
49
}
47
50
48
-
slog.Info("request", "method", r.Method, "url", r.URL.Path, "query", r.URL.Query(), "response", lrw.statusCode, "user", user, "form", r.Form, "duration", time.Since(start))
51
+
slog.InfoContext(r.Context(), "request", "method", r.Method, "url", r.URL.Path, "query", r.URL.Query(), "response", lrw.statusCode, "user", user, "form", r.Form, "duration", time.Since(start))
49
52
}
50
53
51
54
type requestTracker interface {
52
-
TrackRequest(method, url string, duration time.Duration, responseCode string)
55
+
TrackRequest(ctx context.Context, method, url string, duration time.Duration, responseCode string)
53
56
}
54
57
55
58
type appInsightsTracker struct {
···
58
61
}
59
62
60
63
const appInsightsIngestionPath = "/v2/track"
64
+
65
+
type appInsightsTelemetryTracker struct {
66
+
client azureappinsights.TelemetryClient
67
+
}
68
+
69
+
func (t *appInsightsTelemetryTracker) TrackRequest(ctx context.Context, method, url string, duration time.Duration, responseCode string) {
70
+
request := azureappinsights.NewRequestTelemetry(method, url, duration, responseCode)
71
+
if operationID, ok := logsetup.OperationIDFromContext(ctx); ok {
72
+
contracts.ContextTags(request.ContextTags()).Operation().SetId(operationID)
73
+
}
74
+
t.client.Track(request)
75
+
}
61
76
62
77
func (a *appInsightsTracker) ServeHTTP(w http.ResponseWriter, r *http.Request) {
63
78
start := time.Now()
···
68
83
return
69
84
}
70
85
71
-
a.tracker.TrackRequest(r.Method, r.URL.String(), time.Since(start), strconv.Itoa(lrw.statusCode))
86
+
a.tracker.TrackRequest(r.Context(), r.Method, r.URL.String(), time.Since(start), strconv.Itoa(lrw.statusCode))
72
87
}
73
88
74
89
func newAppInsightsTracker(next http.Handler, connectionString string) (http.Handler, error) {
···
78
93
}
79
94
return &appInsightsTracker{
80
95
Handler: next,
81
-
tracker: client,
96
+
tracker: &appInsightsTelemetryTracker{client: client},
82
97
}, nil
83
98
}
84
99
···
161
176
r.Handler.ServeHTTP(w, req)
162
177
}
163
178
179
+
type operationIDHandler struct {
180
+
http.Handler
181
+
}
182
+
183
+
// extract or generate an operation ID for the request, add it to the context, and set it in the response header. The operation ID is used for correlating logs and telemetry.
184
+
func (h *operationIDHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
185
+
operationID := uuid.NewString()
186
+
ctx := logsetup.WithOperationID(r.Context(), operationID)
187
+
w.Header().Set("X-Operation-ID", operationID)
188
+
h.Handler.ServeHTTP(w, r.WithContext(ctx))
189
+
}
190
+
164
191
func WithMiddleware(h http.Handler) http.Handler {
165
192
h = &recoverer{h}
166
193
h = newAppInsightsTrackerFromEnv(h)
167
-
return &logger{h}
194
+
h = &logger{h}
195
+
return &operationIDHandler{h}
168
196
}
+29
-1
cmd/careme/middleware_test.go
+29
-1
cmd/careme/middleware_test.go
···
1
1
package main
2
2
3
3
import (
4
+
"context"
4
5
"net/http"
5
6
"net/http/httptest"
6
7
"strings"
7
8
"testing"
8
9
"time"
10
+
11
+
"careme/internal/logsetup"
9
12
)
10
13
11
14
type trackedRequest struct {
···
13
16
url string
14
17
duration time.Duration
15
18
responseCode string
19
+
operationID string
16
20
}
17
21
18
22
type fakeRequestTracker struct {
19
23
calls []trackedRequest
20
24
}
21
25
22
-
func (f *fakeRequestTracker) TrackRequest(method, url string, duration time.Duration, responseCode string) {
26
+
func (f *fakeRequestTracker) TrackRequest(ctx context.Context, method, url string, duration time.Duration, responseCode string) {
27
+
operationID, _ := logsetup.OperationIDFromContext(ctx)
23
28
f.calls = append(f.calls, trackedRequest{
24
29
method: method,
25
30
url: url,
26
31
duration: duration,
27
32
responseCode: responseCode,
33
+
operationID: operationID,
28
34
})
29
35
}
30
36
···
122
128
}
123
129
if tracker.calls[0].responseCode != "500" {
124
130
t.Fatalf("expected response code 500, got %q", tracker.calls[0].responseCode)
131
+
}
132
+
}
133
+
134
+
func TestAppInsightsTrackerReusesOperationIDFromContext(t *testing.T) {
135
+
tracker := &fakeRequestTracker{}
136
+
mw := &appInsightsTracker{
137
+
Handler: http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
138
+
w.WriteHeader(http.StatusAccepted)
139
+
}),
140
+
tracker: tracker,
141
+
}
142
+
143
+
req := httptest.NewRequest(http.MethodGet, "https://careme.cooking/about", nil)
144
+
req = req.WithContext(logsetup.WithOperationID(req.Context(), "op-555"))
145
+
rec := httptest.NewRecorder()
146
+
mw.ServeHTTP(rec, req)
147
+
148
+
if len(tracker.calls) != 1 {
149
+
t.Fatalf("expected 1 tracked request, got %d", len(tracker.calls))
150
+
}
151
+
if tracker.calls[0].operationID != "op-555" {
152
+
t.Fatalf("expected tracker to receive operation id op-555, got %q", tracker.calls[0].operationID)
125
153
}
126
154
}
127
155
+55
internal/logsetup/context.go
+55
internal/logsetup/context.go
···
1
+
package logsetup
2
+
3
+
import (
4
+
"context"
5
+
"log/slog"
6
+
)
7
+
8
+
type contextKey string
9
+
10
+
const operationIDContextKey contextKey = "operation_id"
11
+
12
+
func WithOperationID(ctx context.Context, operationID string) context.Context {
13
+
if operationID == "" {
14
+
return ctx
15
+
}
16
+
return context.WithValue(ctx, operationIDContextKey, operationID)
17
+
}
18
+
19
+
func OperationIDFromContext(ctx context.Context) (string, bool) {
20
+
if ctx == nil {
21
+
return "", false
22
+
}
23
+
operationID, ok := ctx.Value(operationIDContextKey).(string)
24
+
if !ok || operationID == "" {
25
+
return "", false
26
+
}
27
+
return operationID, true
28
+
}
29
+
30
+
type contextHandler struct {
31
+
handler slog.Handler
32
+
}
33
+
34
+
func newContextHandler(handler slog.Handler) slog.Handler {
35
+
return &contextHandler{handler: handler}
36
+
}
37
+
38
+
func (h *contextHandler) Enabled(ctx context.Context, level slog.Level) bool {
39
+
return h.handler.Enabled(ctx, level)
40
+
}
41
+
42
+
func (h *contextHandler) Handle(ctx context.Context, record slog.Record) error {
43
+
if operationID, ok := OperationIDFromContext(ctx); ok {
44
+
record.AddAttrs(slog.String("operation_id", operationID))
45
+
}
46
+
return h.handler.Handle(ctx, record)
47
+
}
48
+
49
+
func (h *contextHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
50
+
return &contextHandler{handler: h.handler.WithAttrs(attrs)}
51
+
}
52
+
53
+
func (h *contextHandler) WithGroup(name string) slog.Handler {
54
+
return &contextHandler{handler: h.handler.WithGroup(name)}
55
+
}
+34
internal/logsetup/context_test.go
+34
internal/logsetup/context_test.go
···
1
+
package logsetup
2
+
3
+
import (
4
+
"bytes"
5
+
"context"
6
+
"log/slog"
7
+
"strings"
8
+
"testing"
9
+
)
10
+
11
+
func TestContextHandlerAddsOperationID(t *testing.T) {
12
+
var buf bytes.Buffer
13
+
logger := slog.New(newContextHandler(slog.NewTextHandler(&buf, nil)))
14
+
ctx := WithOperationID(context.Background(), "op-123")
15
+
16
+
logger.InfoContext(ctx, "hello")
17
+
18
+
output := buf.String()
19
+
if !strings.Contains(output, "operation_id=op-123") {
20
+
t.Fatalf("expected operation_id in output, got %q", output)
21
+
}
22
+
}
23
+
24
+
func TestContextHandlerSkipsMissingOperationID(t *testing.T) {
25
+
var buf bytes.Buffer
26
+
logger := slog.New(newContextHandler(slog.NewTextHandler(&buf, nil)))
27
+
28
+
logger.InfoContext(context.Background(), "hello")
29
+
30
+
output := buf.String()
31
+
if strings.Contains(output, "operation_id=") {
32
+
t.Fatalf("did not expect operation_id in output, got %q", output)
33
+
}
34
+
}
+2
-2
internal/logsetup/logger.go
+2
-2
internal/logsetup/logger.go
···
13
13
const AppInsightsConnectionStringEnv = "APPLICATIONINSIGHTS_CONNECTION_STRING"
14
14
15
15
func Configure(ctx context.Context) (func(), error) {
16
-
handlers := []slog.Handler{slog.NewTextHandler(os.Stdout, nil)}
16
+
handlers := []slog.Handler{newContextHandler(slog.NewTextHandler(os.Stdout, nil))}
17
17
18
18
closeFn := func() {} // can be a list if we have multiple
19
19
···
22
22
if err != nil {
23
23
return nil, fmt.Errorf("create app insights handler: %w", err)
24
24
}
25
-
handlers = append(handlers, handler)
25
+
handlers = append(handlers, newContextHandler(handler))
26
26
closeFn = handler.Close
27
27
}
28
28