Skip to content

Commit

Permalink
Improving server exception logging by including exception in log mess…
Browse files Browse the repository at this point in the history 
…age (#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 <[email protected]>
  • Loading branch information
@valbers @xperiandri
valbers and xperiandri authored Apr 12, 2024
1 parent cf60e89 commit ac6eae9
Show file tree
Hide file tree
Showing 8 changed files with 137 additions and 86 deletions.
4 changes: 0 additions & 4 deletions .editorconfig
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
138 changes: 69 additions & 69 deletions src/FSharp.Data.GraphQL.Server.AspNetCore/Giraffe/HttpHandlers.fs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
}

Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
)

Expand Down
2 changes: 2 additions & 0 deletions src/FSharp.Data.GraphQL.Server/Exceptions.fs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion src/FSharp.Data.GraphQL.Server/Executor.fs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) =
Expand Down
4 changes: 4 additions & 0 deletions src/FSharp.Data.GraphQL.Server/IO.fs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) =
Expand Down
4 changes: 3 additions & 1 deletion src/FSharp.Data.GraphQL.Server/Schema.fs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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() }
Expand Down
Loading

0 comments on commit ac6eae9

Please sign in to comment.