Skip to content

Commit ac6eae9

Browse files
valbersxperiandri
valbers
and
xperiandri
authored
Improving server exception logging by including exception in log message (#471)
* .AspNetCore: BREAKING CHANGE: logging server exceptions with exception info too There were two problems before: 1. The error message itself was not being logged, but only a mention that there was an error; 2. It was not possible to access the possibly original exception which led to the request processing error. However, it's extremely useful to log the error with the whole exception information including the stack trace of where the exception was thrown. However, these changes also introduce a breaking change as IGQLError and GQLProblemDetails now each have an additional mandatory member holding the possible exception which generated the error. These types (especiall GQLProblemDetails) are public and could be used by code using FSharp.Data.GraphQL. * refactor: trying to improve readability by removing confusing active pattern * adapting code to new exception parameter * .AspNetCore: logging server exceptions with exception info too There were two problems before: 1. The error message itself was not being logged, but only a mention that there was an error; 2. It was not possible to access the possibly original exception which led to the request processing error. However, it's extremely useful to log the error with the whole exception information including the stack trace of where the exception was thrown. However, these changes also introduce a breaking change as IGQLError and GQLProblemDetails now each have an additional mandatory member holding the possible exception which generated the error. These types (especiall GQLProblemDetails) are public and could be used by code using FSharp.Data.GraphQL. * Removed duplicate fantomas config. value (was causing problems) * Reduced allocations in `GQLProblemDetails` creation * Formatted `HttpHandlers` correctly --------- Co-authored-by: Andrii Chebukin <XperiAndri@Outlook.com>
1 parent cf60e89 commit ac6eae9

File tree

8 files changed

+137
-86
lines changed

8 files changed

+137
-86
lines changed

‎.editorconfig‎

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -245,10 +245,6 @@ fsharp_multi_line_lambda_closing_newline=false
245245
# default false
246246
fsharp_keep_indent_in_branch=true
247247

248-
# multiline, nested expressions must be surrounded by blank lines
249-
# default true
250-
fsharp_blank_lines_around_nested_multiline_expressions=false
251-
252248
# whether a bar is placed before DU
253249
# false: type MyDU = Short of int
254250
# true: type MyDU = | Short of int

‎src/FSharp.Data.GraphQL.Server.AspNetCore/Giraffe/HttpHandlers.fs‎

Lines changed: 69 additions & 69 deletions
Original file line numberDiff line numberDiff line change
@@ -25,9 +25,9 @@ module HttpHandlers =
2525

2626
let rec private moduleType = getModuleType <@ moduleType @>
2727

28-
let ofTaskIResult ctx (taskRes: Task<IResult>) : HttpFuncResult = task {
28+
let ofTaskIResult ctx (taskRes : Task<IResult>) : HttpFuncResult = task {
2929
let! res = taskRes
30-
do! res.ExecuteAsync(ctx)
30+
do! res.ExecuteAsync (ctx)
3131
return Some ctx
3232
}
3333

@@ -41,28 +41,28 @@ module HttpHandlers =
4141

4242
let logger = sp.CreateLogger moduleType
4343

44-
let options = sp.GetRequiredService<IOptionsMonitor<GraphQLOptions<'Root>>>()
44+
let options = sp.GetRequiredService<IOptionsMonitor<GraphQLOptions<'Root>>> ()
4545

4646
let toResponse { DocumentId = documentId; Content = content; Metadata = metadata } =
4747

4848
let serializeIndented value =
4949
let jsonSerializerOptions = options.Get(IndentedOptionsName).SerializerOptions
50-
JsonSerializer.Serialize(value, jsonSerializerOptions)
50+
JsonSerializer.Serialize (value, jsonSerializerOptions)
5151

5252
match content with
53-
| Direct(data, errs) ->
54-
logger.LogDebug(
53+
| Direct (data, errs) ->
54+
logger.LogDebug (
5555
$"Produced direct GraphQL response with documentId = '{{documentId}}' and metadata:\n{{metadata}}",
5656
documentId,
5757
metadata
5858
)
5959

6060
if logger.IsEnabled LogLevel.Trace then
61-
logger.LogTrace($"GraphQL response data:\n:{{data}}", serializeIndented data)
61+
logger.LogTrace ($"GraphQL response data:\n:{{data}}", serializeIndented data)
6262

63-
GQLResponse.Direct(documentId, data, errs)
64-
| Deferred(data, errs, deferred) ->
65-
logger.LogDebug(
63+
GQLResponse.Direct (documentId, data, errs)
64+
| Deferred (data, errs, deferred) ->
65+
logger.LogDebug (
6666
$"Produced deferred GraphQL response with documentId = '{{documentId}}' and metadata:\n{{metadata}}",
6767
documentId,
6868
metadata
@@ -71,41 +71,32 @@ module HttpHandlers =
7171
if logger.IsEnabled LogLevel.Debug then
7272
deferred
7373
|> Observable.add (function
74-
| DeferredResult(data, path) ->
75-
logger.LogDebug(
76-
"Produced GraphQL deferred result for path: {path}",
77-
path |> Seq.map string |> Seq.toArray |> Path.Join
78-
)
74+
| DeferredResult (data, path) ->
75+
logger.LogDebug ("Produced GraphQL deferred result for path: {path}", path |> Seq.map string |> Seq.toArray |> Path.Join)
7976

8077
if logger.IsEnabled LogLevel.Trace then
81-
logger.LogTrace(
82-
$"GraphQL deferred data:\n{{data}}",
83-
serializeIndented data
84-
)
85-
| DeferredErrors(null, errors, path) ->
86-
logger.LogDebug(
87-
"Produced GraphQL deferred errors for path: {path}",
88-
path |> Seq.map string |> Seq.toArray |> Path.Join
89-
)
78+
logger.LogTrace ($"GraphQL deferred data:\n{{data}}", serializeIndented data)
79+
| DeferredErrors (null, errors, path) ->
80+
logger.LogDebug ("Produced GraphQL deferred errors for path: {path}", path |> Seq.map string |> Seq.toArray |> Path.Join)
9081

9182
if logger.IsEnabled LogLevel.Trace then
92-
logger.LogTrace($"GraphQL deferred errors:\n{{errors}}", errors)
93-
| DeferredErrors(data, errors, path) ->
94-
logger.LogDebug(
83+
logger.LogTrace ($"GraphQL deferred errors:\n{{errors}}", errors)
84+
| DeferredErrors (data, errors, path) ->
85+
logger.LogDebug (
9586
"Produced GraphQL deferred result with errors for path: {path}",
9687
path |> Seq.map string |> Seq.toArray |> Path.Join
9788
)
9889

9990
if logger.IsEnabled LogLevel.Trace then
100-
logger.LogTrace(
91+
logger.LogTrace (
10192
$"GraphQL deferred errors:\n{{errors}}\nGraphQL deferred data:\n{{data}}",
10293
errors,
10394
serializeIndented data
10495
))
10596

106-
GQLResponse.Direct(documentId, data, errs)
97+
GQLResponse.Direct (documentId, data, errs)
10798
| Stream stream ->
108-
logger.LogDebug(
99+
logger.LogDebug (
109100
$"Produced stream GraphQL response with documentId = '{{documentId}}' and metadata:\n{{metadata}}",
110101
documentId,
111102
metadata
@@ -115,48 +106,60 @@ module HttpHandlers =
115106
stream
116107
|> Observable.add (function
117108
| SubscriptionResult data ->
118-
logger.LogDebug("Produced GraphQL subscription result")
109+
logger.LogDebug ("Produced GraphQL subscription result")
119110

120111
if logger.IsEnabled LogLevel.Trace then
121-
logger.LogTrace(
122-
$"GraphQL subscription data:\n{{data}}",
123-
serializeIndented data
124-
)
125-
| SubscriptionErrors(null, errors) ->
126-
logger.LogDebug("Produced GraphQL subscription errors")
112+
logger.LogTrace ($"GraphQL subscription data:\n{{data}}", serializeIndented data)
113+
| SubscriptionErrors (null, errors) ->
114+
logger.LogDebug ("Produced GraphQL subscription errors")
127115

128116
if logger.IsEnabled LogLevel.Trace then
129-
logger.LogTrace($"GraphQL subscription errors:\n{{errors}}", errors)
130-
| SubscriptionErrors(data, errors) ->
131-
logger.LogDebug("Produced GraphQL subscription result with errors")
117+
logger.LogTrace ($"GraphQL subscription errors:\n{{errors}}", errors)
118+
| SubscriptionErrors (data, errors) ->
119+
logger.LogDebug ("Produced GraphQL subscription result with errors")
132120

133121
if logger.IsEnabled LogLevel.Trace then
134-
logger.LogTrace(
122+
logger.LogTrace (
135123
$"GraphQL subscription errors:\n{{errors}}\nGraphQL deferred data:\n{{data}}",
136124
errors,
137125
serializeIndented data
138126
))
139127

140128
GQLResponse.Stream documentId
141129
| RequestError errs ->
142-
logger.LogWarning(
143-
$"Produced request error GraphQL response with documentId = '{{documentId}}' and metadata:\n{{metadata}}",
144-
documentId,
145-
metadata
146-
)
130+
let noExceptionsFound =
131+
errs
132+
|> Seq.map
133+
(fun x ->
134+
x.Exception |> ValueOption.iter (fun ex ->
135+
logger.LogError (ex, "Error while processing request that generated response with documentId '{documentId}'", documentId)
136+
)
137+
x.Exception.IsNone
138+
)
139+
|> Seq.forall id
140+
if noExceptionsFound then
141+
logger.LogWarning (
142+
("Produced request error GraphQL response with:\n"
143+
+ "- documentId: '{documentId}'\n"
144+
+ "- error(s):\n {requestError}\n"
145+
+ "- metadata:\n {metadata}\n"),
146+
documentId,
147+
errs,
148+
metadata
149+
)
147150

148-
GQLResponse.RequestError(documentId, errs)
151+
GQLResponse.RequestError (documentId, errs)
149152

150153
/// Checks if the request contains a body
151-
let checkIfHasBody (request: HttpRequest) = task {
154+
let checkIfHasBody (request : HttpRequest) = task {
152155
if request.Body.CanSeek then
153156
return (request.Body.Length > 0L)
154157
else
155-
request.EnableBuffering()
158+
request.EnableBuffering ()
156159
let body = request.Body
157160
let buffer = Array.zeroCreate 1
158-
let! bytesRead = body.ReadAsync(buffer, 0, 1)
159-
body.Seek(0, SeekOrigin.Begin) |> ignore
161+
let! bytesRead = body.ReadAsync (buffer, 0, 1)
162+
body.Seek (0, SeekOrigin.Begin) |> ignore
160163
return bytesRead > 0
161164
}
162165

@@ -165,23 +168,21 @@ module HttpHandlers =
165168
/// and lastly by parsing document AST for introspection operation definition.
166169
/// </summary>
167170
/// <returns>Result of check of <see cref="OperationType"/></returns>
168-
let checkOperationType (ctx: HttpContext) = taskResult {
171+
let checkOperationType (ctx : HttpContext) = taskResult {
169172

170-
let checkAnonymousFieldsOnly (ctx: HttpContext) = taskResult {
171-
let! gqlRequest = ctx.TryBindJsonAsync<GQLRequestContent>(GQLRequestContent.expectedJSON)
173+
let checkAnonymousFieldsOnly (ctx : HttpContext) = taskResult {
174+
let! gqlRequest = ctx.TryBindJsonAsync<GQLRequestContent> (GQLRequestContent.expectedJSON)
172175
let! ast = Parser.parseOrIResult ctx.Request.Path.Value gqlRequest.Query
173176
let operationName = gqlRequest.OperationName |> Skippable.toOption
174177

175-
let createParsedContent() = {
178+
let createParsedContent () = {
176179
Query = gqlRequest.Query
177180
Ast = ast
178181
OperationName = gqlRequest.OperationName
179182
Variables = gqlRequest.Variables
180183
}
181184
if ast.IsEmpty then
182-
logger.LogTrace(
183-
"Request is not GET, but 'query' field is an empty string. Must be an introspection query"
184-
)
185+
logger.LogTrace ("Request is not GET, but 'query' field is an empty string. Must be an introspection query")
185186
return IntrospectionQuery <| ValueNone
186187
else
187188
match Ast.findOperationByName operationName ast with
@@ -196,34 +197,33 @@ module HttpHandlers =
196197
let hasNonMetaFields =
197198
Ast.containsFieldsBeyond
198199
Ast.metaTypeFields
199-
(fun x ->
200-
logger.LogTrace($"Operation Selection in Field with name: {{fieldName}}", x.Name))
200+
(fun x -> logger.LogTrace ($"Operation Selection in Field with name: {{fieldName}}", x.Name))
201201
(fun _ -> logger.LogTrace "Operation Selection is non-Field type")
202202
op
203203

204204
if hasNonMetaFields then
205-
return createParsedContent() |> OperationQuery
205+
return createParsedContent () |> OperationQuery
206206
else
207207
return IntrospectionQuery <| ValueSome ast
208208
}
209209

210210
let request = ctx.Request
211211

212212
if HttpMethods.Get = request.Method then
213-
logger.LogTrace("Request is GET. Must be an introspection query")
213+
logger.LogTrace ("Request is GET. Must be an introspection query")
214214
return IntrospectionQuery <| ValueNone
215215
else
216216
let! hasBody = checkIfHasBody request
217217

218218
if not hasBody then
219-
logger.LogTrace("Request is not GET, but has no body. Must be an introspection query")
219+
logger.LogTrace ("Request is not GET, but has no body. Must be an introspection query")
220220
return IntrospectionQuery <| ValueNone
221221
else
222222
return! checkAnonymousFieldsOnly ctx
223223
}
224224

225225
/// Execute default or custom introspection query
226-
let executeIntrospectionQuery (executor: Executor<_>) (ast: Ast.Document voption) = task {
226+
let executeIntrospectionQuery (executor : Executor<_>) (ast : Ast.Document voption) = task {
227227
let! result =
228228
match ast with
229229
| ValueNone -> executor.AsyncExecute IntrospectionQuery.Definition
@@ -239,18 +239,18 @@ module HttpHandlers =
239239
let variables = content.Variables |> Skippable.filter (not << isNull) |> Skippable.toOption
240240

241241
operationName
242-
|> Option.iter (fun on -> logger.LogTrace("GraphQL operation name: '{operationName}'", on))
242+
|> Option.iter (fun on -> logger.LogTrace ("GraphQL operation name: '{operationName}'", on))
243243

244-
logger.LogTrace($"Executing GraphQL query:\n{{query}}", content.Query)
244+
logger.LogTrace ($"Executing GraphQL query:\n{{query}}", content.Query)
245245

246246
variables
247-
|> Option.iter (fun v -> logger.LogTrace($"GraphQL variables:\n{{variables}}", v))
247+
|> Option.iter (fun v -> logger.LogTrace ($"GraphQL variables:\n{{variables}}", v))
248248

249249
let root = options.CurrentValue.RootFactory ctx
250250

251251
let! result =
252-
Async.StartAsTask(
253-
executor.AsyncExecute(content.Ast, root, ?variables = variables, ?operationName = operationName),
252+
Async.StartAsTask (
253+
executor.AsyncExecute (content.Ast, root, ?variables = variables, ?operationName = operationName),
254254
cancellationToken = ctx.RequestAborted
255255
)
256256

‎src/FSharp.Data.GraphQL.Server/Exceptions.fs‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,8 @@ type GQLMessageExceptionBase (errorKind, msg, [<Optional>] extensions) =
2121
inherit GraphQLException (msg)
2222
interface IGQLError with
2323
member _.Message = msg
24+
interface IGQLExceptionError with
25+
member this.Exception = this
2426
interface IGQLErrorExtensions with
2527
member _.Extensions =
2628
match extensions with

‎src/FSharp.Data.GraphQL.Server/Executor.fs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -123,7 +123,7 @@ type Executor<'Root>(schema: ISchema<'Root>, middlewares : IExecutorMiddleware s
123123
return prepareOutput res
124124
with
125125
| :? GQLMessageException as ex -> return prepareOutput(GQLExecutionResult.Error (documentId, ex, executionPlan.Metadata))
126-
| ex -> return prepareOutput (GQLExecutionResult.Error(documentId, ex.ToString(), executionPlan.Metadata)) // TODO: Handle better
126+
| ex -> return prepareOutput (GQLExecutionResult.ErrorFromException(documentId, ex, executionPlan.Metadata))
127127
}
128128

129129
let execute (executionPlan: ExecutionPlan, data: 'Root option, variables: ImmutableDictionary<string, JsonElement> option) =

‎src/FSharp.Data.GraphQL.Server/IO.fs‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -58,6 +58,10 @@ type GQLExecutionResult =
5858
GQLExecutionResult.RequestError(documentId, errors |> List.map GQLProblemDetails.OfError, meta)
5959
static member Error(documentId, msg, meta) =
6060
GQLExecutionResult.RequestError(documentId, [ GQLProblemDetails.Create msg ], meta)
61+
62+
static member ErrorFromException(documentId : int, ex : Exception, meta : Metadata) =
63+
GQLExecutionResult.RequestError(documentId, [ GQLProblemDetails.Create (ex.Message, ex) ], meta)
64+
6165
static member Invalid(documentId, errors, meta) =
6266
GQLExecutionResult.RequestError(documentId, errors, meta)
6367
static member ErrorAsync(documentId, msg : string, meta) =

‎src/FSharp.Data.GraphQL.Server/Schema.fs‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -133,7 +133,9 @@ type SchemaConfig =
133133
fun path ex ->
134134
match ex with
135135
| :? GQLMessageException as ex -> [ex]
136-
| ex -> [{ new IGQLError with member _.Message = ex.Message }]
136+
| ex -> [{ new IGQLExceptionError with
137+
member _.Message = ex.Message
138+
member _.Exception = ex }]
137139
SubscriptionProvider = SchemaConfig.DefaultSubscriptionProvider()
138140
LiveFieldSubscriptionProvider = SchemaConfig.DefaultLiveFieldSubscriptionProvider()
139141
JsonOptions = JsonFSharpOptions.Default().ToJsonSerializerOptions() }

0 commit comments

Comments
 (0)