Improving server exception logging by including exception in log message

.editorconfig

@@ -245,10 +245,6 @@ fsharp_multi_line_lambda_closing_newline=false
 # default false
 fsharp_keep_indent_in_branch=true
 
-# multiline, nested expressions must be surrounded by blank lines
-# default true
-fsharp_blank_lines_around_nested_multiline_expressions=false
-
 # whether a bar is placed before DU
 # false: type MyDU = Short of int
 # true:  type MyDU = | Short of int

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

@@ -25,9 +25,9 @@ module HttpHandlers =
 
     let rec private moduleType = getModuleType <@ moduleType @>
 
-    let ofTaskIResult ctx (taskRes: Task<IResult>) : HttpFuncResult = task {
+    let ofTaskIResult ctx (taskRes : Task<IResult>) : HttpFuncResult = task {
         let! res = taskRes
-        do! res.ExecuteAsync(ctx)
+        do! res.ExecuteAsync (ctx)
         return Some ctx
     }
 
@@ -41,28 +41,28 @@ module HttpHandlers =
 
         let logger = sp.CreateLogger moduleType
 
-        let options = sp.GetRequiredService<IOptionsMonitor<GraphQLOptions<'Root>>>()
+        let options = sp.GetRequiredService<IOptionsMonitor<GraphQLOptions<'Root>>> ()
 
         let toResponse { DocumentId = documentId; Content = content; Metadata = metadata } =
 
             let serializeIndented value =
                 let jsonSerializerOptions = options.Get(IndentedOptionsName).SerializerOptions
-                JsonSerializer.Serialize(value, jsonSerializerOptions)
+                JsonSerializer.Serialize (value, jsonSerializerOptions)
 
             match content with
-            | Direct(data, errs) ->
-                logger.LogDebug(
+            | Direct (data, errs) ->
+                logger.LogDebug (
                     $"Produced direct GraphQL response with documentId = '{{documentId}}' and metadata:\n{{metadata}}",
                     documentId,
                     metadata
                 )
 
                 if logger.IsEnabled LogLevel.Trace then
-                    logger.LogTrace($"GraphQL response data:\n:{{data}}", serializeIndented data)
+                    logger.LogTrace ($"GraphQL response data:\n:{{data}}", serializeIndented data)
 
-                GQLResponse.Direct(documentId, data, errs)
-            | Deferred(data, errs, deferred) ->
-                logger.LogDebug(
+                GQLResponse.Direct (documentId, data, errs)
+            | Deferred (data, errs, deferred) ->
+                logger.LogDebug (
                     $"Produced deferred GraphQL response with documentId = '{{documentId}}' and metadata:\n{{metadata}}",
                     documentId,
                     metadata
@@ -71,41 +71,32 @@ module HttpHandlers =
                 if logger.IsEnabled LogLevel.Debug then
                     deferred
                     |> Observable.add (function
-                        | DeferredResult(data, path) ->
-                            logger.LogDebug(
-                                "Produced GraphQL deferred result for path: {path}",
-                                path |> Seq.map string |> Seq.toArray |> Path.Join
-                            )
+                        | DeferredResult (data, path) ->
+                            logger.LogDebug ("Produced GraphQL deferred result for path: {path}", path |> Seq.map string |> Seq.toArray |> Path.Join)
 
                             if logger.IsEnabled LogLevel.Trace then
-                                logger.LogTrace(
-                                    $"GraphQL deferred data:\n{{data}}",
-                                    serializeIndented data
-                                )
-                        | DeferredErrors(null, errors, path) ->
-                            logger.LogDebug(
-                                "Produced GraphQL deferred errors for path: {path}",
-                                path |> Seq.map string |> Seq.toArray |> Path.Join
-                            )
+                                logger.LogTrace ($"GraphQL deferred data:\n{{data}}", serializeIndented data)
+                        | DeferredErrors (null, errors, path) ->
+                            logger.LogDebug ("Produced GraphQL deferred errors for path: {path}", path |> Seq.map string |> Seq.toArray |> Path.Join)
 
                             if logger.IsEnabled LogLevel.Trace then
-                                logger.LogTrace($"GraphQL deferred errors:\n{{errors}}", errors)
-                        | DeferredErrors(data, errors, path) ->
-                            logger.LogDebug(
+                                logger.LogTrace ($"GraphQL deferred errors:\n{{errors}}", errors)
+                        | DeferredErrors (data, errors, path) ->
+                            logger.LogDebug (
                                 "Produced GraphQL deferred result with errors for path: {path}",
                                 path |> Seq.map string |> Seq.toArray |> Path.Join
                             )
 
                             if logger.IsEnabled LogLevel.Trace then
-                                logger.LogTrace(
+                                logger.LogTrace (
                                     $"GraphQL deferred errors:\n{{errors}}\nGraphQL deferred data:\n{{data}}",
                                     errors,
                                     serializeIndented data
                                 ))
 
-                GQLResponse.Direct(documentId, data, errs)
+                GQLResponse.Direct (documentId, data, errs)
             | Stream stream ->
-                logger.LogDebug(
+                logger.LogDebug (
                     $"Produced stream GraphQL response with documentId = '{{documentId}}' and metadata:\n{{metadata}}",
                     documentId,
                     metadata
@@ -115,48 +106,60 @@ module HttpHandlers =
                     stream
                     |> Observable.add (function
                         | SubscriptionResult data ->
-                            logger.LogDebug("Produced GraphQL subscription result")
+                            logger.LogDebug ("Produced GraphQL subscription result")
 
                             if logger.IsEnabled LogLevel.Trace then
-                                logger.LogTrace(
-                                    $"GraphQL subscription data:\n{{data}}",
-                                    serializeIndented data
-                                )
-                        | SubscriptionErrors(null, errors) ->
-                            logger.LogDebug("Produced GraphQL subscription errors")
+                                logger.LogTrace ($"GraphQL subscription data:\n{{data}}", serializeIndented data)
+                        | SubscriptionErrors (null, errors) ->
+                            logger.LogDebug ("Produced GraphQL subscription errors")
 
                             if logger.IsEnabled LogLevel.Trace then
-                                logger.LogTrace($"GraphQL subscription errors:\n{{errors}}", errors)
-                        | SubscriptionErrors(data, errors) ->
-                            logger.LogDebug("Produced GraphQL subscription result with errors")
+                                logger.LogTrace ($"GraphQL subscription errors:\n{{errors}}", errors)
+                        | SubscriptionErrors (data, errors) ->
+                            logger.LogDebug ("Produced GraphQL subscription result with errors")
 
                             if logger.IsEnabled LogLevel.Trace then
-                                logger.LogTrace(
+                                logger.LogTrace (
                                     $"GraphQL subscription errors:\n{{errors}}\nGraphQL deferred data:\n{{data}}",
                                     errors,
                                     serializeIndented data
                                 ))
 
                 GQLResponse.Stream documentId
             | RequestError errs ->
-                logger.LogWarning(
-                    $"Produced request error GraphQL response with documentId = '{{documentId}}' and metadata:\n{{metadata}}",
-                    documentId,
-                    metadata
-                )
+                let noExceptionsFound =
+                    errs
+                    |> Seq.map
+                        (fun x ->
+                            x.Exception |> ValueOption.iter (fun ex ->
+                                logger.LogError (ex, "Error while processing request that generated response with documentId '{documentId}'", documentId)
+                            )
+                            x.Exception.IsNone
+                        )
+                    |> Seq.forall id
+                if noExceptionsFound then
+                    logger.LogWarning (
+                        ("Produced request error GraphQL response with:\n"
+                         + "- documentId: '{documentId}'\n"
+                         + "- error(s):\n    {requestError}\n"
+                         + "- metadata:\n    {metadata}\n"),
+                        documentId,
+                        errs,
+                        metadata
+                    )
 
-                GQLResponse.RequestError(documentId, errs)
+                GQLResponse.RequestError (documentId, errs)
 
         /// Checks if the request contains a body
-        let checkIfHasBody (request: HttpRequest) = task {
+        let checkIfHasBody (request : HttpRequest) = task {
             if request.Body.CanSeek then
                 return (request.Body.Length > 0L)
             else
-                request.EnableBuffering()
+                request.EnableBuffering ()
                 let body = request.Body
                 let buffer = Array.zeroCreate 1
-                let! bytesRead = body.ReadAsync(buffer, 0, 1)
-                body.Seek(0, SeekOrigin.Begin) |> ignore
+                let! bytesRead = body.ReadAsync (buffer, 0, 1)
+                body.Seek (0, SeekOrigin.Begin) |> ignore
                 return bytesRead > 0
         }
 
@@ -165,23 +168,21 @@ module HttpHandlers =
         /// and lastly by parsing document AST for introspection operation definition.
         /// </summary>
         /// <returns>Result of check of <see cref="OperationType"/></returns>
-        let checkOperationType (ctx: HttpContext) = taskResult {
+        let checkOperationType (ctx : HttpContext) = taskResult {
 
-            let checkAnonymousFieldsOnly (ctx: HttpContext) = taskResult {
-                let! gqlRequest = ctx.TryBindJsonAsync<GQLRequestContent>(GQLRequestContent.expectedJSON)
+            let checkAnonymousFieldsOnly (ctx : HttpContext) = taskResult {
+                let! gqlRequest = ctx.TryBindJsonAsync<GQLRequestContent> (GQLRequestContent.expectedJSON)
                 let! ast = Parser.parseOrIResult ctx.Request.Path.Value gqlRequest.Query
                 let operationName = gqlRequest.OperationName |> Skippable.toOption
 
-                let createParsedContent() = {
+                let createParsedContent () = {
                     Query = gqlRequest.Query
                     Ast = ast
                     OperationName = gqlRequest.OperationName
                     Variables = gqlRequest.Variables
                 }
                 if ast.IsEmpty then
-                    logger.LogTrace(
-                        "Request is not GET, but 'query' field is an empty string. Must be an introspection query"
-                    )
+                    logger.LogTrace ("Request is not GET, but 'query' field is an empty string. Must be an introspection query")
                     return IntrospectionQuery <| ValueNone
                 else
                     match Ast.findOperationByName operationName ast with
@@ -196,34 +197,33 @@ module HttpHandlers =
                             let hasNonMetaFields =
                                 Ast.containsFieldsBeyond
                                     Ast.metaTypeFields
-                                    (fun x ->
-                                        logger.LogTrace($"Operation Selection in Field with name: {{fieldName}}", x.Name))
+                                    (fun x -> logger.LogTrace ($"Operation Selection in Field with name: {{fieldName}}", x.Name))
                                     (fun _ -> logger.LogTrace "Operation Selection is non-Field type")
                                     op
 
                             if hasNonMetaFields then
-                                return createParsedContent() |> OperationQuery
+                                return createParsedContent () |> OperationQuery
                             else
                                 return IntrospectionQuery <| ValueSome ast
             }
 
             let request = ctx.Request
 
             if HttpMethods.Get = request.Method then
-                logger.LogTrace("Request is GET. Must be an introspection query")
+                logger.LogTrace ("Request is GET. Must be an introspection query")
                 return IntrospectionQuery <| ValueNone
             else
                 let! hasBody = checkIfHasBody request
 
                 if not hasBody then
-                    logger.LogTrace("Request is not GET, but has no body. Must be an introspection query")
+                    logger.LogTrace ("Request is not GET, but has no body. Must be an introspection query")
                     return IntrospectionQuery <| ValueNone
                 else
                     return! checkAnonymousFieldsOnly ctx
         }
 
         /// Execute default or custom introspection query
-        let executeIntrospectionQuery (executor: Executor<_>) (ast: Ast.Document voption) = task {
+        let executeIntrospectionQuery (executor : Executor<_>) (ast : Ast.Document voption) = task {
             let! result =
                 match ast with
                 | ValueNone -> executor.AsyncExecute IntrospectionQuery.Definition
@@ -239,18 +239,18 @@ module HttpHandlers =
             let variables = content.Variables |> Skippable.filter (not << isNull) |> Skippable.toOption
 
             operationName
-            |> Option.iter (fun on -> logger.LogTrace("GraphQL operation name: '{operationName}'", on))
+            |> Option.iter (fun on -> logger.LogTrace ("GraphQL operation name: '{operationName}'", on))
 
-            logger.LogTrace($"Executing GraphQL query:\n{{query}}", content.Query)
+            logger.LogTrace ($"Executing GraphQL query:\n{{query}}", content.Query)
 
             variables
-            |> Option.iter (fun v -> logger.LogTrace($"GraphQL variables:\n{{variables}}", v))
+            |> Option.iter (fun v -> logger.LogTrace ($"GraphQL variables:\n{{variables}}", v))
 
             let root = options.CurrentValue.RootFactory ctx
 
             let! result =
-                Async.StartAsTask(
-                    executor.AsyncExecute(content.Ast, root, ?variables = variables, ?operationName = operationName),
+                Async.StartAsTask (
+                    executor.AsyncExecute (content.Ast, root, ?variables = variables, ?operationName = operationName),
                     cancellationToken = ctx.RequestAborted
                 )
 

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

@@ -21,6 +21,8 @@ type GQLMessageExceptionBase (errorKind, msg, [<Optional>] extensions) =
     inherit GraphQLException (msg)
     interface IGQLError with
         member _.Message = msg
+    interface IGQLExceptionError with
+        member this.Exception = this
     interface IGQLErrorExtensions with
         member _.Extensions =
             match extensions with

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

@@ -123,7 +123,7 @@ type Executor<'Root>(schema: ISchema<'Root>, middlewares : IExecutorMiddleware s
                     return prepareOutput res
             with
             | :? GQLMessageException as ex -> return prepareOutput(GQLExecutionResult.Error (documentId, ex, executionPlan.Metadata))
-            | ex -> return prepareOutput (GQLExecutionResult.Error(documentId, ex.ToString(), executionPlan.Metadata)) // TODO: Handle better
+            | ex -> return prepareOutput (GQLExecutionResult.ErrorFromException(documentId, ex, executionPlan.Metadata))
         }
 
     let execute (executionPlan: ExecutionPlan, data: 'Root option, variables: ImmutableDictionary<string, JsonElement> option) =

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

@@ -58,6 +58,10 @@ type GQLExecutionResult =
         GQLExecutionResult.RequestError(documentId, errors |> List.map GQLProblemDetails.OfError, meta)
     static member Error(documentId, msg, meta) =
         GQLExecutionResult.RequestError(documentId, [ GQLProblemDetails.Create msg ], meta)
+
+    static member ErrorFromException(documentId : int, ex : Exception, meta : Metadata) =
+        GQLExecutionResult.RequestError(documentId, [ GQLProblemDetails.Create (ex.Message, ex) ], meta)
+
     static member Invalid(documentId, errors, meta) =
         GQLExecutionResult.RequestError(documentId, errors, meta)
     static member ErrorAsync(documentId, msg : string, meta) =

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

@@ -133,7 +133,9 @@ type SchemaConfig =
             fun path ex ->
                 match ex with
                 | :? GQLMessageException as ex -> [ex]
-                | ex -> [{ new IGQLError with member _.Message = ex.Message }]
+                | ex -> [{ new IGQLExceptionError with
+                            member _.Message = ex.Message
+                            member _.Exception = ex }]
           SubscriptionProvider = SchemaConfig.DefaultSubscriptionProvider()
           LiveFieldSubscriptionProvider = SchemaConfig.DefaultLiveFieldSubscriptionProvider()
           JsonOptions = JsonFSharpOptions.Default().ToJsonSerializerOptions() }