From 9a09b04f4178977c91dea98478a46f6718b108b4 Mon Sep 17 00:00:00 2001 From: abhif22 Date: Mon, 6 Apr 2020 13:59:10 +0530 Subject: [PATCH 1/4] Changes for logging query string during panics --- graphql.go | 3 ++- internal/exec/exec.go | 18 +++++++++--------- internal/exec/subscribe.go | 4 ++-- subscriptions.go | 2 +- 4 files changed, 14 insertions(+), 13 deletions(-) diff --git a/graphql.go b/graphql.go index 6a852b55..39d23a56 100644 --- a/graphql.go +++ b/graphql.go @@ -223,7 +223,8 @@ func (s *Schema) exec(ctx context.Context, queryString string, operationName str varTypes[v.Name.Name] = introspection.WrapType(t) } traceCtx, finish := s.tracer.TraceQuery(ctx, queryString, operationName, variables, varTypes) - data, errs := r.Execute(traceCtx, res, op) + queryInfo := fmt.Sprintf("Query: %s\nVariables: %+v\n\n", queryString, variables) + data, errs := r.Execute(traceCtx, res, op, queryInfo) finish(errs) return &Response{ diff --git a/internal/exec/exec.go b/internal/exec/exec.go index 9f7fb597..f535ce49 100644 --- a/internal/exec/exec.go +++ b/internal/exec/exec.go @@ -26,10 +26,10 @@ type Request struct { Logger log.Logger } -func (r *Request) handlePanic(ctx context.Context) { +func (r *Request) handlePanic(ctx context.Context, queryString string) { if value := recover(); value != nil { r.Logger.LogPanic(ctx, value) - r.AddError(makePanicError(value)) + r.AddError(makePanicError(value, queryString)) } } @@ -37,14 +37,14 @@ type extensionser interface { Extensions() map[string]interface{} } -func makePanicError(value interface{}) *errors.QueryError { - return errors.Errorf("graphql: panic occurred: %v", value) +func makePanicError(value interface{}, info string) *errors.QueryError { + return errors.Errorf("graphql: panic occurred: %v\n%s\n\n", value, info) } -func (r *Request) Execute(ctx context.Context, s *resolvable.Schema, op *query.Operation) ([]byte, []*errors.QueryError) { +func (r *Request) Execute(ctx context.Context, s *resolvable.Schema, op *query.Operation, queryInfo string) ([]byte, []*errors.QueryError) { var out bytes.Buffer func() { - defer r.handlePanic(ctx) + defer r.handlePanic(ctx, queryInfo) sels := selected.ApplyOperation(&r.Request, s, op) r.execSelections(ctx, sels, nil, s, s.Resolver, &out, op.Type == query.Mutation) }() @@ -79,7 +79,7 @@ func (r *Request) execSelections(ctx context.Context, sels []selected.Selection, for _, f := range fields { go func(f *fieldToExec) { defer wg.Done() - defer r.handlePanic(ctx) + defer r.handlePanic(ctx, "") f.out = new(bytes.Buffer) execFieldSelection(ctx, r, s, f, &pathSegment{path, f.field.Alias}, true) }(f) @@ -178,7 +178,7 @@ func execFieldSelection(ctx context.Context, r *Request, s *resolvable.Schema, f defer func() { if panicValue := recover(); panicValue != nil { r.Logger.LogPanic(ctx, panicValue) - err = makePanicError(panicValue) + err = makePanicError(panicValue, "") err.Path = path.toSlice() } }() @@ -337,7 +337,7 @@ func (r *Request) execList(ctx context.Context, sels []selected.Selection, typ * for i := 0; i < l; i++ { go func(i int) { defer wg.Done() - defer r.handlePanic(ctx) + defer r.handlePanic(ctx, "") r.execSelectionSet(ctx, sels, typ.OfType, &pathSegment{path, i}, s, resolver.Index(i), &entryouts[i]) }(i) } diff --git a/internal/exec/subscribe.go b/internal/exec/subscribe.go index 10d8aede..f1e3e330 100644 --- a/internal/exec/subscribe.go +++ b/internal/exec/subscribe.go @@ -25,7 +25,7 @@ func (r *Request) Subscribe(ctx context.Context, s *resolvable.Schema, op *query var f *fieldToExec var err *errors.QueryError func() { - defer r.handlePanic(ctx) + defer r.handlePanic(ctx, "") sels := selected.ApplyOperation(&r.Request, s, op) var fields []*fieldToExec @@ -117,7 +117,7 @@ func (r *Request) Subscribe(ctx context.Context, s *resolvable.Schema, op *query // resolve response func() { - defer subR.handlePanic(subCtx) + defer subR.handlePanic(subCtx, "") var buf bytes.Buffer subR.execSelectionSet(subCtx, f.sels, f.field.Type, &pathSegment{nil, f.field.Alias}, s, resp, &buf) diff --git a/subscriptions.go b/subscriptions.go index bf773343..9a62195f 100644 --- a/subscriptions.go +++ b/subscriptions.go @@ -65,7 +65,7 @@ func (s *Schema) subscribe(ctx context.Context, queryString string, operationNam } if op.Type == query.Query || op.Type == query.Mutation { - data, errs := r.Execute(ctx, res, op) + data, errs := r.Execute(ctx, res, op, "") return sendAndReturnClosed(&Response{Data: data, Errors: errs}) } From 57196371cb7fa07bc33030c8134f5fb63b2a646d Mon Sep 17 00:00:00 2001 From: abhif22 Date: Mon, 6 Apr 2020 18:23:00 +0530 Subject: [PATCH 2/4] Refactored for minimal changes --- graphql.go | 4 ++-- internal/exec/exec.go | 23 ++++++++++++----------- internal/exec/subscribe.go | 4 ++-- log/log.go | 6 +++--- subscriptions.go | 2 +- 5 files changed, 20 insertions(+), 19 deletions(-) diff --git a/graphql.go b/graphql.go index 39d23a56..29b60bd0 100644 --- a/graphql.go +++ b/graphql.go @@ -223,8 +223,8 @@ func (s *Schema) exec(ctx context.Context, queryString string, operationName str varTypes[v.Name.Name] = introspection.WrapType(t) } traceCtx, finish := s.tracer.TraceQuery(ctx, queryString, operationName, variables, varTypes) - queryInfo := fmt.Sprintf("Query: %s\nVariables: %+v\n\n", queryString, variables) - data, errs := r.Execute(traceCtx, res, op, queryInfo) + r.QInfo = fmt.Sprintf("Query: %s\nVariables: %+v\n", queryString, variables) + data, errs := r.Execute(traceCtx, res, op) finish(errs) return &Response{ diff --git a/internal/exec/exec.go b/internal/exec/exec.go index f535ce49..0631e4c1 100644 --- a/internal/exec/exec.go +++ b/internal/exec/exec.go @@ -24,12 +24,13 @@ type Request struct { Limiter chan struct{} Tracer trace.Tracer Logger log.Logger + QInfo string } -func (r *Request) handlePanic(ctx context.Context, queryString string) { +func (r *Request) handlePanic(ctx context.Context) { if value := recover(); value != nil { - r.Logger.LogPanic(ctx, value) - r.AddError(makePanicError(value, queryString)) + r.Logger.LogPanic(ctx, value, r.QInfo) + r.AddError(makePanicError(value)) } } @@ -37,14 +38,14 @@ type extensionser interface { Extensions() map[string]interface{} } -func makePanicError(value interface{}, info string) *errors.QueryError { - return errors.Errorf("graphql: panic occurred: %v\n%s\n\n", value, info) +func makePanicError(value interface{}) *errors.QueryError { + return errors.Errorf("graphql: panic occurred: %v", value) } -func (r *Request) Execute(ctx context.Context, s *resolvable.Schema, op *query.Operation, queryInfo string) ([]byte, []*errors.QueryError) { +func (r *Request) Execute(ctx context.Context, s *resolvable.Schema, op *query.Operation) ([]byte, []*errors.QueryError) { var out bytes.Buffer func() { - defer r.handlePanic(ctx, queryInfo) + defer r.handlePanic(ctx) sels := selected.ApplyOperation(&r.Request, s, op) r.execSelections(ctx, sels, nil, s, s.Resolver, &out, op.Type == query.Mutation) }() @@ -79,7 +80,7 @@ func (r *Request) execSelections(ctx context.Context, sels []selected.Selection, for _, f := range fields { go func(f *fieldToExec) { defer wg.Done() - defer r.handlePanic(ctx, "") + defer r.handlePanic(ctx) f.out = new(bytes.Buffer) execFieldSelection(ctx, r, s, f, &pathSegment{path, f.field.Alias}, true) }(f) @@ -177,8 +178,8 @@ func execFieldSelection(ctx context.Context, r *Request, s *resolvable.Schema, f err = func() (err *errors.QueryError) { defer func() { if panicValue := recover(); panicValue != nil { - r.Logger.LogPanic(ctx, panicValue) - err = makePanicError(panicValue, "") + r.Logger.LogPanic(ctx, panicValue, r.QInfo) + err = makePanicError(panicValue) err.Path = path.toSlice() } }() @@ -337,7 +338,7 @@ func (r *Request) execList(ctx context.Context, sels []selected.Selection, typ * for i := 0; i < l; i++ { go func(i int) { defer wg.Done() - defer r.handlePanic(ctx, "") + defer r.handlePanic(ctx) r.execSelectionSet(ctx, sels, typ.OfType, &pathSegment{path, i}, s, resolver.Index(i), &entryouts[i]) }(i) } diff --git a/internal/exec/subscribe.go b/internal/exec/subscribe.go index f1e3e330..10d8aede 100644 --- a/internal/exec/subscribe.go +++ b/internal/exec/subscribe.go @@ -25,7 +25,7 @@ func (r *Request) Subscribe(ctx context.Context, s *resolvable.Schema, op *query var f *fieldToExec var err *errors.QueryError func() { - defer r.handlePanic(ctx, "") + defer r.handlePanic(ctx) sels := selected.ApplyOperation(&r.Request, s, op) var fields []*fieldToExec @@ -117,7 +117,7 @@ func (r *Request) Subscribe(ctx context.Context, s *resolvable.Schema, op *query // resolve response func() { - defer subR.handlePanic(subCtx, "") + defer subR.handlePanic(subCtx) var buf bytes.Buffer subR.execSelectionSet(subCtx, f.sels, f.field.Type, &pathSegment{nil, f.field.Alias}, s, resp, &buf) diff --git a/log/log.go b/log/log.go index 25569af7..581697ea 100644 --- a/log/log.go +++ b/log/log.go @@ -8,16 +8,16 @@ import ( // Logger is the interface used to log panics that occur during query execution. It is settable via graphql.ParseSchema type Logger interface { - LogPanic(ctx context.Context, value interface{}) + LogPanic(ctx context.Context, value interface{}, info string) } // DefaultLogger is the default logger used to log panics that occur during query execution type DefaultLogger struct{} // LogPanic is used to log recovered panic values that occur during query execution -func (l *DefaultLogger) LogPanic(_ context.Context, value interface{}) { +func (l *DefaultLogger) LogPanic(_ context.Context, value interface{}, info string) { const size = 64 << 10 buf := make([]byte, size) buf = buf[:runtime.Stack(buf, false)] - log.Printf("graphql: panic occurred: %v\n%s", value, buf) + log.Printf("graphql: panic occurred: %v\n%s\n\n%s", value, buf, info) } diff --git a/subscriptions.go b/subscriptions.go index 9a62195f..bf773343 100644 --- a/subscriptions.go +++ b/subscriptions.go @@ -65,7 +65,7 @@ func (s *Schema) subscribe(ctx context.Context, queryString string, operationNam } if op.Type == query.Query || op.Type == query.Mutation { - data, errs := r.Execute(ctx, res, op, "") + data, errs := r.Execute(ctx, res, op) return sendAndReturnClosed(&Response{Data: data, Errors: errs}) } From 9ca2ea2155c560ad645d77fb1321ab82b1a5702a Mon Sep 17 00:00:00 2001 From: abhif22 Date: Wed, 8 Apr 2020 18:08:46 +0530 Subject: [PATCH 3/4] Added a method to act as an config propogation interface between gqlserver and graphqlgo --- graphql.go | 14 ++++++++++++++ log/log.go | 22 +++++++++++++++++++++- 2 files changed, 35 insertions(+), 1 deletion(-) diff --git a/graphql.go b/graphql.go index 29b60bd0..9e957496 100644 --- a/graphql.go +++ b/graphql.go @@ -68,6 +68,7 @@ type Schema struct { logger log.Logger useStringDescriptions bool disableIntrospection bool + isPanicLogEnabled bool } // SchemaOpt is an option to pass to ParseSchema or MustParseSchema. @@ -150,6 +151,19 @@ func (s *Schema) Validate(queryString string, variables map[string]interface{}) return false, validation.Validate(s.schema, doc, variables, s.maxDepth) } +//EnablePanicLogging enables query info logging if panic occurs +func (s *Schema) EnablePanicLogging() { + s.isPanicLogEnabled = true + s.logger = getLogger(s) +} + +func getLogger(s *Schema) log.Logger { + if s != nil && s.isPanicLogEnabled { + return &log.CustomLogger{true} + } + return &log.DefaultLogger{} +} + // Exec executes the given query with the schema's resolver. It panics if the schema was created // without a resolver. If the context get cancelled, no further resolvers will be called and a // the context error will be returned as soon as possible (not immediately). diff --git a/log/log.go b/log/log.go index 581697ea..3105c4a3 100644 --- a/log/log.go +++ b/log/log.go @@ -2,6 +2,7 @@ package log import ( "context" + "fmt" "log" "runtime" ) @@ -19,5 +20,24 @@ func (l *DefaultLogger) LogPanic(_ context.Context, value interface{}, info stri const size = 64 << 10 buf := make([]byte, size) buf = buf[:runtime.Stack(buf, false)] - log.Printf("graphql: panic occurred: %v\n%s\n\n%s", value, buf, info) + log.Printf("graphql: panic occurred: %v\n%s", value, buf) } + +// CustomLogger is the custom logger for use with gqlserver custome config to log panics that occur during query execution +type CustomLogger struct{ + VerbosePanicLog bool +} + +// LogPanic is used to log recovered panic values that occur during query execution +func (l *CustomLogger) LogPanic(_ context.Context, value interface{}, info string) { + const size = 64 << 10 + buf := make([]byte, size) + buf = buf[:runtime.Stack(buf, false)] + msg := fmt.Sprintf("graphql: panic occurred: %v\n%s", value, buf) + if l.VerbosePanicLog { + msg = fmt.Sprintf("%s\n\n%s", msg, info) + } + + log.Printf(msg) +} + From 6ec64f97e5724f0a1a979811bcd4f707decd5dd8 Mon Sep 17 00:00:00 2001 From: abhif22 Date: Mon, 27 Apr 2020 13:28:32 +0530 Subject: [PATCH 4/4] Removed changes introduced for wrapping error inside graphql error extension --- internal/exec/exec.go | 15 +-------------- 1 file changed, 1 insertion(+), 14 deletions(-) diff --git a/internal/exec/exec.go b/internal/exec/exec.go index 0631e4c1..9820c550 100644 --- a/internal/exec/exec.go +++ b/internal/exec/exec.go @@ -217,20 +217,7 @@ func execFieldSelection(ctx context.Context, r *Request, s *resolvable.Schema, f err := errors.Errorf("%s", resolverErr) err.Path = path.toSlice() err.ResolverError = resolverErr - errs := errors.QueryError{ - Message: err.Message, - Locations: err.Locations, - Path: err.Path, - Rule: "", - ResolverError: err.ResolverError, - Extensions: errors.Extensions{ - Code: 0, - DeveloperMessage: err.Message, - MoreInfo: fmt.Sprintf("%s", err.Path), - Timestamp: "", - }, - } - return &errs + return err } } else { // TODO extract out unwrapping ptr logic to a common place