8000 feat: improve logging, add request id and consumer info (#4990) · ovh/cds@dc21e90 · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

Commit dc21e90

Browse files
richardltrichardlt
authored
feat: improve logging, add request id and consumer info (#4990)
* feat: improve logging, add request id and consumer info * feat: add prefix for custom logger * feat: add request id in obs trace * fix: code review
1 parent f30e8f0 commit dc21e90

File tree

19 files changed

+239
-156
lines changed

19 files changed

+239
-156
lines changed

‎cli/cdsctl/admin_errors.go

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -22,21 +22,23 @@ func adminErrors() *cobra.Command {
2222

2323
var adminErrorsGetCmd = cli.Command{
2424
Name: "get",
25-
Short: "Get CDS error",
25+
Short: "Get CDS errors for given request id",
2626
Args: []cli.Arg{
27-
{Name: "uuid"},
27+
{Name: "request-id"},
2828
},
2929
}
3030

3131
func adminErrorsGetFunc(v cli.Values) error {
32-
res, err := client.MonErrorsGet(v.GetString("uuid"))
32+
res, err := client.MonErrorsGet(v.GetString("request-id"))
3333
if err != nil {
3434
return err
3535
}
3636

37-
fmt.Printf("Message: %s\n", res.Message)
38-
if res.StackTrace != "" {
39-
fmt.Printf("Stack trace:\n%s", res.StackTrace)
37+
for i := range res {
38+
fmt.Printf("Message[%d]: %s\n", i, res[i].Message)
39+
if res[i].StackTrace != "" {
40+
fmt.Printf("Stack trace[%d]:\n%s", i, res[i].StackTrace)
41+
}
4042
}
4143

4244
return nil

‎cli/cobra.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ func ExitOnError(err error, helpFunc ...func() error) {
3232

3333
switch e := err.(type) {
3434
case sdk.Error:
35-
fmt.Printf("Error(%s): %s\n", e.UUID, e.Message)
35+
fmt.Printf("Error(request_id:%s): %s\n", e.RequestID, e.Message)
3636
case *Error:
3737
code = e.Code
3838
fmt.Println("Error:", e.Error())

‎contrib/grpcplugins/action/clair/go.sum

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -394,6 +394,7 @@ github.com/prometheus/client_golang v0.9.3-0.20190127221311-3c4408c8b829/go.mod
394394
github.com/prometheus/client_golang v0.9.3/go.mod h1:/TN21ttK/J9q6uSwhBd54HahCDft0ttaMvbicHlPoso=
395395
github.com/prometheus/client_golang v0.9.4 h1:Y8E/JaaPbmFSW2V81Ab/d8yZFYQQGbni1b1jPcG9Y6A=
396396
github.com/prometheus/client_golang v0.9.4/go.mod h1:oCXIBxdI62A4cR6aTRJCgetEjecSIYzOEaeAn4iYEpM=
397+
github.com/prometheus/client_golang v1.0.0/go.mod h1:db9x61etRT2tGnBNRi70OPL5FsnadC4Ky3P0J6CfImo=
397398
github.com/prometheus/client_model v0.0.0-20170216185247-6f3806018612/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
398399
github.com/prometheus/client_model v0.0.0-20180712105110-5c3871d89910/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
399400
github.com/prometheus/client_model v0.0.0-20190115171406-56726106282f/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
@@ -408,6 +409,7 @@ github.com/prometheus/common v0.2.0/go.mod h1:TNfzLD0ON7rHzMJeJkieUDPYmFC7Snx/y8
408409
github.com/prometheus/common v0.4.0/go.mod h1:TNfzLD0ON7rHzMJeJkieUDPYmFC7Snx/y86RQel1bk4=
409410
github.com/prometheus/common v0.4.1 h1:K0MGApIoQvMw27RTdJkPbr3JZ7DNbtxQNyi5STVM6Kw=
410411
github.com/prometheus/common v0.4.1/go.mod h1:TNfzLD0ON7rHzMJeJkieUDPYmFC7Snx/y86RQel1bk4=
412+
github.com/prometheus/common v0.6.0/go.mod h1:eBmuwkDJBwy6iBfxCBob6t6dR6ENT/y+J+Zk0j9GMYc=
411413
github.com/prometheus/procfs v0.0.0-20170502131342-d098ca18df8b/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
412414
github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
413415
github.com/prometheus/procfs v0.0.0-20181204211112-1dc9a6cbc91a/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
@@ -549,6 +551,7 @@ golang.org/x/net v0.0.0-20190501004415-9ce7a6920f09/go.mod h1:t9HGtf8HONx5eT2rtn
549551
golang.org/x/net v0.0.0-20190503192946-f4e77d36d62c/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
550552
golang.org/x/net v0.0.0-20190522155817-f3200d17e092/go.mod h1:HSz+uSET+XFnRR8LxR5pz3Of3rY3CfYBVs4xY44aLks=
551553
golang.org/x/net v0.0.0-20190603091049-60506f45cf65/go.mod h1:HSz+uSET+XFnRR8LxR5pz3Of3rY3CfYBVs4xY44aLks=
554+
golang.org/x/net v0.0.0-20190613194153-d28f0bde5980/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
552555
golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
553556
golang.org/x/net v0.0.0-20191204025024-5ee1b9f4859a h1:+HHJiFUXVOIS9mr1ThqkQD1N8vpFCfCShqADBM12KTc=
554557
golang.org/x/net v0.0.0-20191204025024-5ee1b9f4859a/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=

‎engine/api/error.go

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -26,10 +26,10 @@ type graylogResponse struct {
2626
func (api *API) getErrorHandler() service.Handler {
2727
return func(ctx context.Context, w http.ResponseWriter, r *http.Request) error {
2828
vars := mux.Vars(r)
29-
uuid := vars["uuid"]
29+
id := vars["request_id"]
3030

3131
if api.Config.Graylog.URL == "" || api.Config.Graylog.AccessToken == "" {
32-
return sdk.WithStack(sdk.ErrNotImplemented)
32+
return sdk.WithStack(sdk.ErrNotFound)
3333
}
3434

3535
req, err := http.NewRequest("GET", fmt.Sprintf("%s/api/search/universal/absolute", api.Config.Graylog.URL), nil)
@@ -38,10 +38,9 @@ func (api *API) getErrorHandler() service.Handler {
3838
}
3939

4040
q := req.URL.Query()
41-
q.Add("query", fmt.Sprintf("error_uuid:%s", uuid))
41+
q.Add("query", fmt.Sprintf("request_id:%s", id))
4242
q.Add("from", "1970-01-01 00:00:00.000")
4343
q.Add("to", time.Now().Format("2006-01-02 15:04:05"))
44-
q.Add("limit", "1")
4544
q.Add("filter", fmt.Sprintf("streams:%s", api.Config.Graylog.Stream))
4645
req.URL.RawQuery = q.Encode()
4746

@@ -66,15 +65,16 @@ func (api *API) getErrorHandler() service.Handler {
6665
return sdk.WithStack(sdk.ErrNotFound)
6766
}
6867

69-
e := sdk.Error{
70-
UUID: res.Messages[0].Message["error_uuid"].(string),
71-
Message: res.Messages[0].Message["message"].(string),
72-
}
73-
if st, ok := res.Messages[0].Message["stack_trace"]; ok {
74-
e.StackTrace = st.(string)
68+
logs := make([]sdk.Error, res.TotalResult)
69+
for i := range res.Messages {
70+
logs[i].RequestID = res.Messages[i].Message["request_id"].(string)
71+
logs[i].Message = res.Messages[i].Message["message"].(string)
72+
if st, ok := res.Messages[i].Message["stack_trace"]; ok {
73+
logs[i].StackTrace = st.(string)
74+
}
7575
}
7676

77-
return service.WriteJSON(w, e, http.StatusOK)
77+
return service.WriteJSON(w, logs, http.StatusOK)
7878
}
7979
}
8080

‎engine/api/observability/stats.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ const (
2626
Path = "http.path"
2727
Method = "http.method"
2828
Handler = "http.handler"
29+
RequestID = "http.request-id"
2930
)
3031

3132
type ExposedView struct {

‎engine/api/router.go

Lines changed: 60 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,8 @@ import (
1818
"github.com/gorilla/handlers"
1919
"github.com/gorilla/mux"
2020
"github.com/pkg/errors"
21+
uuid "github.com/satori/go.uuid"
22+
"github.com/sirupsen/logrus"
2123
"go.opencensus.io/stats"
2224
"go.opencensus.io/tag"
2325

@@ -154,7 +156,7 @@ func (r *Router) recoverWrap(h http.HandlerFunc) http.HandlerFunc {
154156
log.Error(context.TODO(), "[PANIC_RECOVERY] RESTART NEEDED")
155157
}
156158

157-
service.WriteError(w, req, err)
159+
service.WriteError(context.TODO(), w, req, err)
158160
}
159161
}()
160162
h.ServeHTTP(w, req)
@@ -273,6 +275,17 @@ func (r *Router) Handle(uri string, scope HandlerScope, handlers ...*service.Han
273275
ctx, cancel := context.WithCancel(req.Context())
274276
defer cancel()
275277

278+
var requestID string
279+
if existingRequestID := req.Header.Get("Request-ID"); existingRequestID != "" {
280+
if _, err := uuid.FromString(existingRequestID); err == nil {
281+
requestID = existingRequestID
282+
}
283+
}
284+
if requestID == "" {
285+
requestID = uuid.NewV4().String()
286+
}
287+
ctx = context.WithValue(ctx, log.ContextLoggingRequestIDKey, requestID)
288+
276289
dateRFC5322 := req.Header.Get("Date")
277290
dateReq, err := sdk.ParseDateRFC5322(dateRFC5322)
278291
if err == nil {
@@ -309,7 +322,7 @@ func (r *Router) Handle(uri string, scope HandlerScope, handlers ...*service.Han
309322
rc := cfg.Config[req.Method]
310323
if rc == nil || rc.Handler == nil {
311324
observability.Record(ctx, Errors, 1)
312-
service.WriteError(w, req, sdk.ErrNotFound)
325+
service.WriteError(ctx, w, req, sdk.ErrNotFound)
313326
return
314327
}
315328

@@ -320,31 +333,61 @@ func (r *Router) Handle(uri string, scope HandlerScope, handlers ...*service.Han
320333
log.Error(ctx, "observability.ContextGetTags> %v", err)
321334
}
322335
ctx = observability.ContextWithTag(ctx,
336+
observability.RequestID, requestID,
323337
observability.Handler, rc.Name,
324338
observability.Host, req.Host,
325339
observability.Path, req.URL.Path,
326340
observability.Method, req.Method)
327341

328-
//Log request
342+
// Prepare logging fields
343+
ctx = context.WithValue(ctx, log.ContextLoggingFuncKey, func(ctx context.Context) logrus.Fields {
344+
fields := make(logrus.Fields)
345+
346+
// Add consumer info if exists
347+
iConsumer := ctx.Value(contextAPIConsumer)
348+
if iConsumer != nil {
349+
if consumer, ok := iConsumer.(*sdk.AuthConsumer); ok {
350+
fields["auth_user_id"] = consumer.AuthentifiedUserID
351+
fields["auth_consumer_id"] = consumer.ID
352+
}
353+
}
354+
355+
// Add session info if exists
356+
iSession := ctx.Value(contextSession)
357+
if iSession != nil {
358+
if session, ok := iSession.(*sdk.AuthSession); ok {
359+
fields["auth_session_id"] = session.ID
360+
}
361+
}
362+
363+
return fields
364+
})
365+
366+
// Log request start
329367
start := time.Now()
330-
defer func(ctx context.Context) {
368+
log.Info(ctx, "%s | BEGIN | %s [%s]", req.Method, req.URL, rc.Name)
369+
370+
// Defer log request end
371+
deferFunc := func(ctx context.Context) {
331372
if responseWriter.statusCode == 0 {
332373
responseWriter.statusCode = 200
333374
}
334375
ctx = observability.ContextWithTag(ctx, observability.StatusCode, responseWriter.statusCode)
335376

336377
end := time.Now()
337378
latency := end.Sub(start)
338-
if rc.IsDeprecated {
339-
log.Error(ctx, "[%-3d] | %-7s | %13v | DEPRECATED ROUTE | %v [%s]", responseWriter.statusCode, req.Method, latency, req.URL, rc.Name)
340-
} else {
341-
log.Info(ctx, "[%-3d] | %-7s | %13v | %v [%s]", responseWriter.statusCode, req.Method, latency, req.URL, rc.Name)
342-
}
379+
380+
log.InfoWithFields(ctx, logrus.Fields{
381+
"method": req.Method,
382+
"latency": latency,
383+
"status": responseWriter.statusCode,
384+
"deprecated": rc.IsDeprecated,
385+
}, "[%d] | %s | END | %s [%s]", responseWriter.statusCode, req.Method, req.URL, rc.Name)
343386

344387
observability.RecordFloat64(ctx, ServerLatency, float64(latency)/float64(time.Millisecond))
345388
observability.Record(ctx, ServerRequestBytes, responseWriter.reqSize)
346389
observability.Record(ctx, ServerResponseBytes, responseWriter.respSize)
347-
}(ctx)
390+
}
348391

349392
observability.Record(r.Background, Hits, 1)
350393
observability.Record(ctx, ServerRequestCount, 1)
@@ -354,15 +397,17 @@ func (r *Router) Handle(uri string, scope HandlerScope, handlers ...*service.Han
354397
ctx, err = m(ctx, responseWriter, req, rc)
355398
if err != nil {
356399
observability.Record(r.Background, Errors, 1)
357-
service.WriteError(w, req, err)
400+
service.WriteError(ctx, w, req, err)
401+
deferFunc(ctx)
358402
return
359403
}
360404
}
361405

362406
if err := rc.Handler(ctx, responseWriter.wrappedResponseWriter(), req); err != nil {
363407
observability.Record(r.Background, Errors, 1)
364408
observability.End(ctx, responseWriter, req)
365-
service.WriteError(responseWriter, req, err)
409+
service.WriteError(ctx, responseWriter, req, err)
410+
deferFunc(ctx)
366411
return
367412
}
368413

@@ -377,6 +422,8 @@ func (r *Router) Handle(uri string, scope HandlerScope, handlers ...*service.Han
377422
log.Error(ctx, "PostMiddlewares > %s", err)
378423
}
379424
}
425+
426+
deferFunc(ctx)
380427
}
381428

382429
// The chain is http -> mux -> f -> recover -> wrap -> pprof -> opencensus -> http
@@ -577,7 +624,7 @@ func EnableTracing() HandlerConfigParam {
577624

578625
// NotFoundHandler is called by default by Mux is any matching handler has been found
579626
func NotFoundHandler(w http.ResponseWriter, req *http.Request) {
580-
service.WriteError(w, req, sdk.WithStack(sdk.ErrNotFound))
627+
service.WriteError(context.Background(), w, req, sdk.WithStack(sdk.ErrNotFound))
581628
}
582629

583630
// StatusPanic returns router status. If nbPanic > 30 -> Alert, if nbPanic > 0 -> Warn

‎engine/api/router_middleware_auth.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -152,7 +152,7 @@ func (api *API) authMiddleware(ctx context.Context, w http.ResponseWriter, req *
152152

153153
// If we set Auth(false) on a handler, with should have a consumer in the context if a valid JWT is given
154154
if rc.NeedAuth && getAPIConsumer(ctx) == nil {
155-
return nil, sdk.WithStack(sdk.ErrUnauthorized)
155+
return ctx, sdk.WithStack(sdk.ErrUnauthorized)
156156
}
157157

158158
if rc.NeedAdmin && !isAdmin(ctx) {

‎engine/api/services/http.go

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -287,6 +287,13 @@ func doRequestFromURL(ctx context.Context, db gorp.SqlExecutor, method string, c
287287
}
288288
}
289289

290+
iRequestID := ctx.Value(log.ContextLoggingRequestIDKey)
291+
if iRequestID != nil {
292+
if requestID, ok := iRequestID.(string); ok {
293+
req.Header.Set(log.HeaderRequestID, requestID)
294+
}
295+
}
296+
290297
// Sign the http request with API private RSA Key
291298
if err := HTTPSigner.Sign(req); err != nil {
292299
return nil, nil, 0, sdk.WrapError(err, "services.DoRequest> Request signature failed")

‎engine/api/worker.go

Lines changed: 17 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -30,26 +30,25 @@ func (api *API) postRegisterWorkerHandler() service.Handler {
3030

3131
var registrationForm sdk.WorkerRegistrationForm
3232
if err := service.UnmarshalBody(r, &registrationForm); err != nil {
33-
return sdk.WrapError(err, "Unable to parse registration form")
33+
return err
3434
}
3535

3636
// Check that the worker can authentify on CDS API
3737
workerTokenFromHatchery, err := workerauth.VerifyToken(ctx, api.mustDB(), jwt)
3838
if err != nil {
39-
log.Error(ctx, "registerWorkerHandler> unauthorized worker jwt token %s: %v", jwt, err)
40-
return sdk.WithStack(sdk.ErrUnauthorized)
39+
return sdk.NewErrorWithStack(sdk.WrapError(err, "unauthorized worker jwt token %s", jwt), sdk.ErrUnauthorized)
4140
}
4241

4342
// Check that hatchery exists
4443
hatchSrv, err := services.LoadByNameAndType(ctx, api.mustDB(), workerTokenFromHatchery.Worker.HatcheryName, services.TypeHatchery)
4544
if err != nil {
46-
return sdk.WrapError(err, "registerWorkerHandler> Unable to load hatchery %s", workerTokenFromHatchery.Worker.HatcheryName)
45+
return sdk.WrapError(err, "unable to load hatchery %s", workerTokenFromHatchery.Worker.HatcheryName)
4746
}
4847

4948
// Retrieve the authentifed Consumer from the hatchery
5049
hatcheryConsumer, err := authentication.LoadConsumerByID(ctx, api.mustDB(), *hatchSrv.ConsumerID, authentication.LoadConsumerOptions.WithAuthentifiedUser)
5150
if err != nil {
52-
return sdk.WrapError(err, "registerWorkerHandler> Unable to load consumer %v", hatchSrv.ConsumerID)
51+
return sdk.WrapError(err, "unable to load consumer %v", hatchSrv.ConsumerID)
5352
}
5453

5554
tx, err := api.mustDB().Begin()
@@ -62,7 +61,7 @@ func (api *API) postRegisterWorkerHandler() service.Handler {
6261
if wor A92E kerTokenFromHatchery.Worker.JobID != 0 {
6362
job, err := workflow.LoadNodeJobRun(ctx, tx, api.Cache, workerTokenFromHatchery.Worker.JobID)
6463
if err != nil {
65-
return sdk.NewError(sdk.ErrForbidden, err)
64+
return sdk.NewErrorWithStack(err, sdk.ErrForbidden)
6665
}
6766
groupIDs = sdk.Groups(job.ExecGroups).ToIDs()
6867
} else {
@@ -78,16 +77,20 @@ func (api *API) postRegisterWorkerHandler() service.Handler {
7877
// Try to register worker
7978
wk, err := worker.RegisterWorker(ctx, tx, api.Cache, workerTokenFromHatchery.Worker, hatchSrv.ID, workerConsumer, registrationForm)
8079
if err != nil {
81-
err = sdk.NewError(sdk.ErrUnauthorized, err)
82-
return sdk.WrapError(err, "[%s] Registering failed", workerTokenFromHatchery.Worker.WorkerName)
80+
return sdk.NewErrorWithStack(
81+
sdk.WrapError(err, "[%s] Registering failed", workerTokenFromHatchery.Worker.WorkerName),
82+
sdk.ErrUnauthorized,
83+
)
8384
}
8485

8586
log.Debug("New worker: [%s] - %s", wk.ID, wk.Name)
8687

8788
workerSession, err := authentication.NewSession(ctx, tx, workerConsumer, workerauth.SessionDuration, false)
8889
if err != nil {
89-
err = sdk.NewError(sdk.ErrUnauthorized, err)
90-
return sdk.WrapError(err, "[%s] Registering failed", workerTokenFromHatchery.Worker.WorkerName)
90+
return sdk.NewErrorWithStack(
91+
sdk.WrapError(err, "[%s] Registering failed", workerTokenFromHatchery.Worker.WorkerName),
92+
sdk.ErrUnauthorized,
93+
)
9194
}
9295

9396
if err := tx.Commit(); err != nil {
@@ -96,8 +99,10 @@ func (api *API) postRegisterWorkerHandler() service.Handler {
9699

97100
jwt, err = authentication.NewSessionJWT(workerSession)
98101
if err != nil {
99-
err = sdk.NewError(sdk.ErrUnauthorized, err)
100-
return sdk.WrapError(err, "[%s] Registering failed", workerTokenFromHatchery.Worker.WorkerName)
102+
return sdk.NewErrorWithStack(
103+
sdk.WrapError(err, "[%s] Registering failed", workerTokenFromHatchery.Worker.WorkerName),
104+
sdk.ErrUnauthorized,
105+
)
101106
}
102107

103108
// Set the JWT token as a header

0 commit comments

Comments
 (0)
0