Simple logging with suave

[trbarrett]

Hi. I've been trying to figure out how to do some simple logging with suave. The documentation in https://suave.io/logs.html seems somewhat outdated. The first "sample" link on that page is neither relevant to suave or logging? And none of the code seems to work with the latest versions.

More relevant example code appears to be: https://github.com/SuaveIO/suave/blob/master/examples/Example/Program.fs#L27 which indicates suave has it's own logger which doesn't involve a Logary dependency. And by looking at https://github.com/SuaveIO/suave/blob/master/src/Suave/Tcp.fs I can see how that is used.

Am I right thinking I can do something like the following in my own code if I want some simple logging:

open Suave.Logging
open Suave.Logging.Message
let logger = Log.create "MyProject.MyApi" 
logger.debug (eventX "My Api Event")

Or is Suave.Logging really meant more for internal use by the Suave project, and I need to figure out Logary?

[ademar]

Yes, Suave.Logging is intended for internal logging.

I have used Serilog with success via the following https://github.com/Zaid-Ajaj/Suave.SerilogExtensions

[trbarrett]

Looks great. Thanks @ademar.

[svdHero]

Is the simple logging suggested by @trbarrett above bad practice are just "unusual"? I have a small web app and don't want to deal with big logging libraries.

I was even thinking about a simple

ctx.runtime.logger.debug (eventX "My Api Event")

inside my request handler functions / WebParts.

Is there anything wrong with that?

[ademar]

I guess you could, do note that calls to debug and verbose will be dropped when compiled in release mode.

https://github.com/SuaveIO/suave/blob/master/src/Suave/Utils/Logging.fs#L216

[svdHero]

Oh wow, thanks for the warning. I was not aware of that.

Could you explain quickly the outputTemplate format here, please: https://github.com/SuaveIO/suave/blob/master/examples/Example/Program.fs#L27-L32 What do the brackets mean? Are they meant literally or do they indicate optional values? What if some of the template variables are not present, e.g. exceptions?

Also, what purpose does the logger name have? So far I haven't seen where this is displayed or used.

Thanks a lot in advance.

[ademar]

The brackets in the template are just output, do not mean anything to the parser.

If my memory serves right when a variable is not provided it just doesn't print anything or prints the name of the missing variable.

For example you want to do:

ctx.runtime.logger.error (eventX "error while writing response {error}" >> setFieldValue "error" err)

If you miss setting the field.

newCtx.runtime.logger.error (eventX "Socket error while writing response {error}" )

it would just output

Socket error while writing response {error}

[svdHero]

Thanks @ademar for the explanations. Could you also say something about the logger name? Do you know where is it used?

[ademar]

The logger name currently have no function. It is an artifact from when we were compatible with Loggary. The idea was that you could create different loggers and later get them 'by name'

[svdHero]

Thanks @ademar. One final question. Is it possible to register new fields? I would like to do something like this:

outputTemplate = "[{timestamp} {level} {clientAddress}] {message} {exceptions}

and then in my custom error handler:

let clientAddress : string = ctx.connection.ipAddr.ToString()+":"+ctx.connection.port.ToString()
Message.eventX msg
>> Message.setSingleName "MyErrorHandler"
>> Message.setFieldValue "clientAddress" clientAddress
>> Message.addExn ex
|> ctx.runtime.logger.error

However, the custom field is always printed as {client_address} literally.

[ademar]

You can use any field names. Make sure the names match; you have typed two different names above; client_address and clientAddress.

[svdHero]

Sorry, that was a typo in my comment. However, please note that I did NOT use two different names in my sample code.

Unfortunately the field name is not replaced by the value. I will check again tomorrow.

[svdHero]

Sorry for the delay. I can confirm that with Release 2.5.6 the field template is not replaced by the value. I double-checked that the field name is correct.

@ademar can you reproduce this? Apart from this, I am pretty happy with the whole built-in logging and error handling system.

[ademar]

@svdHero I'll look at as soon as possible.

[svdHero]

@ademar Any progress on this or do you have a time estimate when you will look into this? Thanks.

[svdHero]

@ademar Any update on this?

[ademar]

Hi @svdHero

Sorry for the late response. This seems to be working.

I have written a unit test for it that passes successfully. See https://github.com/SuaveIO/suave/commit/3fddb3be5caad552a70f73b060f3427d63d0192d

I also see the output from running Suave indicates that it is working.

[10:03:03 INF] Smooth! Suave listener started in 75.611ms with binding 10.0.0.5:8083

It comes from here:

logger.info (
 eventX "Smooth! Suave listener started in {startedListeningMilliseconds:#.###}ms with binding {ipAddress}:{port}"
 >> setFieldValue "startedListeningMilliseconds" (startData.GetStartedListeningElapsedMilliseconds())
  // .Address can throw exceptions, just log its string representation
  >> setFieldValue "ipAddress" (startData.binding.ip.ToString())
  >> setFieldValue "port" startData.binding.port
  >> setSingleName "Suave.Tcp.runServer")

If you could share with us an example exhibiting the issue we can troubleshoot further.

[svdHero]

Thank you so much for your reply, @ademar .

I want to add the Correlation Id to the logging and I have the following real-life code:

namespace BT.RPE.BackEnd.Web.Config

type ErrorHandlerInfo = {
    ErrorMessage: string
    ExceptionMessage : string
    ExceptionDetails : string
    }

type UnhandledServerRuntimeError = UnhandledServerRuntimeError of ErrorHandlerInfo

[<RequireQualifiedAccess>]
module internal Server =

    open System.IO
    open Suave
    open Suave.Logging
    open BT.FSharp.Util.Data
    open BT.RPE.BackEnd.Web

    // ########################################################################

    [<RequireQualifiedAccess>]
    module private EnvVars =
        [<Literal>]
        let RPE_IP_ADDRESS = "RPE_IP_ADDRESS"
        [<Literal>]
        let RPE_PORT = "RPE_PORT"

    let private getEnvVar (envVarName: string) =
        let varValue = System.Environment.GetEnvironmentVariable(envVarName)
        if System.String.IsNullOrWhiteSpace varValue then
            nullArg (sprintf "environment variable \"%s\"" varValue)
        else
            printfn "Environment variable \"%s\" read for configuration." envVarName
            varValue

    // ########################################################################

    let private createLogger () =
        // Also see https://github.com/SuaveIO/suave/blob/v2.5.6/examples/Example/Program.fs#L23-L32
        // and https://github.com/SuaveIO/suave/issues/721#issuecomment-578553378
        let target = LiterateConsoleTarget (
                            name = [|"BT";"RPE";"BackEnd"|],
                            minLevel = LogLevel.Verbose,
                            options = Literate.LiterateOptions.create(),
                            outputTemplate = "[{timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} {level} {corrId}]{newline}{message} [{source}] {exceptions}{newline}"
                            )
        let logger = target :> Logger 
        logger

    let private createErrorHandler () =
        // Also see https://dusted.codes/custom-error-handling-and-logging-in-suave
        let errorHandler : ErrorHandler =
            let assemblyName = System.Reflection.Assembly.GetExecutingAssembly().GetName().Name
            fun ex msg ->
                fun ctx ->
                    let corrIdOpt = ctx.request |> CorrelationId.getCorrIdHeader
                    let corrId =
                        match corrIdOpt with
                        | Some c -> c |> HierarchicalCorrelationId.toString
                        | None -> "NOT AVAILABLE"
                    Message.eventX msg
                    >> Message.setSingleName (assemblyName+".ErrorHandler")
                    >> Message.setFieldValue "corrId" corrId
                    >> Message.addExn ex
                    |> ctx.runtime.logger.error

                    if ctx.isLocal then // change to ctx.isLocalTrustProxy with new release
                        let runtimeError = UnhandledServerRuntimeError {
                            ErrorMessage = msg
                            ExceptionMessage = if isNull ex then null else ex.Message
                            ExceptionDetails = if isNull ex then null else ex.ToString()
                            }
                        JsonResponses.INTERNAL_ERROR (Util.toJson runtimeError) ctx
                    else
                        let runtimeError = UnhandledServerRuntimeError {
                            ErrorMessage = msg
                            ExceptionMessage = if isNull ex then null else ex.Message
                            ExceptionDetails = null
                            }
                        JsonResponses.INTERNAL_ERROR (Util.toJson runtimeError) ctx
        errorHandler

    let private createBindings () =
        let port = getEnvVar EnvVars.RPE_PORT |> int
        let ip_address = getEnvVar EnvVars.RPE_IP_ADDRESS
        let bindings = [
            HttpBinding.createSimple HTTP ip_address port;
            ]
        bindings

    // ########################################################################

    /// Creates the Suave.io configuration
    let createServerConfig () =
        { defaultConfig with
            bindings = createBindings ()
            homeFolder = Some (Path.GetFullPath "./public")
            logger = createLogger ()
            errorHandler = createErrorHandler ()
        }

    // ########################################################################

However, when my web app produces an exception, all I get is this logging console output:

[2020-07-16 09:19:17.489 +02:00 ERR {corrId}]
request failed [BT.RPE.BackEnd.Web.ErrorHandler]
System.Exception: Boom! Nasty Exception!
   at BT.RPE.BackEnd.Web.QueryRequestHandler.query(RequestHandlerDependencies deps, FSharpOption`1 uidOpt, HttpContext ctx) in W:\RPE_BackEnd\projects\BT.RPE.BackEnd.Web\QueryRequestHandler.fs:line 63
   at BT.RPE.BackEnd.Web.Routing.postRoutes@68-2.Invoke(RequestHandlerDependencies deps, FSharpOption`1 uidOpt, HttpContext ctx) in W:\RPE_BackEnd\projects\BT.RPE.BackEnd.Web\Routing.fs:line 68
   at BT.RPE.BackEnd.Web.Util.toWebPart(FSharpFunc`2 handler, HttpContext ctx) in W:\RPE_BackEnd\projects\BT.RPE.BackEnd.Web\Common.fs:line 61
   at BT.RPE.BackEnd.Web.Routing.postRoutes@68-3.Invoke(HttpContext ctx) in W:\RPE_BackEnd\projects\BT.RPE.BackEnd.Web\Routing.fs:line 68
   at Microsoft.FSharp.Control.AsyncPrimitives.CallThenInvokeNoHijackCheck[a,b](AsyncActivation`1 ctxt, FSharpFunc`2 userCode, b result1) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 417
   at <StartupCode$FSharp-Core>.$Async.Return@1066.Invoke(AsyncActivation`1 ctxt) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 1066
[...]

Notice how the field template {corrId} is not replaced by any value, not even the NOT AVAILABLE value. What am I doing wrong?

If it's too much code, I can open a new issue and try to link a simple hello world repo.

[svdHero]

Update: I edited my example above and provided an exception scenario.

[ademar]

OK, I see the problem.

Note the first argument to Message.eventX is the message template. In the error handler above it should be called like this.

Message.eventX "[{corrId}]{message}"
>> Message.setSingleName (assemblyName+".ErrorHandler")
>> Message.setFieldValue "corrId" corrId
>> Message.setFieldValue "message" msg
>> Message.addExn ex
 |> ctx.runtime.logger.error

Also do not need to override the default logger's template; if you were to do so you would need to write an actual implementation for the logger since LiterateConsoleTarget doesn't know about the field corrId.

The logger's template and the message template are different and treated at different levels. The message string value is built before reaching down there to the logger. It is confusing here that we are using also a field message in our message template.

Let me know if you need more clarity, I know is confusing.

[svdHero]

Okay, thanks. I will give it a try tomorrow morning. Just to clarify: Can I overwrite the logger template the way I did, if I it's only about formatting and if do not add new, additional fields?

[ademar]

Yes, that'll work.

[svdHero]

@ademar Okay, that worked. Almost...

I've modified my code to:

let corrIdOpt = ctx.request |> CorrelationId.getCorrIdHeader
let corrId =
    match corrIdOpt with
    | Some c -> c |> HierarchicalCorrelationId.toString
    | None -> "NOT AVAILABLE"
Message.eventX "[{corrId}] {message}"
>> Message.setSingleName (assemblyName+".ErrorHandler")
>> Message.setFieldValue "corrId" corrId
>> Message.setFieldValue "message" msg
>> Message.addExn ex
|> ctx.runtime.logger.error

according to your suggestions. The template {corrId} is now replaced by NOT AVAILABLE. The problem: It is ALWAYS replaced by NOT AVAILABLE, although my routing roughly looks like this:

ensureCorrId // Makes sure that a correlation id is present and updated
>=> choose [
        path "/rpe/api/queries" >=> (Util.toWebPart QueryRequestHandler.query)
        [...]
        ]

In the WebPart ensureCorrId I check for a correaltion id header. If there is none, I generate a new one and add it to both ctx.request and ctx.response, in order to have it available further down the pipeline. So, in theory, if there is an exception in QueryRequestHandler.query then the error handler should already have a correlation id available. Unless of course, the error handler takes the context from the beginning of the routing pipeline.

Do you have any suggestions or idea on this? How can I access my correlation id in the error handler?

[ademar]

Unless of course, the error handler takes the context from the beginning of the routing pipeline.

Yeah, this is precisely what is happening.

Here HttpContext.userState was supposed to address this use case but I realize it was made an immutable map and as such will have the same problem.

Because I've run into this before and the immutable map is not useful here I'll be changing it into an mutable dictionary so we can have global user state per request.

Then you could do:

let ensureCorrId =
  context(fun ctx ->
    ctx.userState.Add("corrId", (Guid.NewGuid().ToString()))
    succeed)

And in the error handler:

let corrId =
  if ctx.userState.ContainsKey "corrId" then
    ctx.userState.["corrId"] :?> string
  else
    "NOT AVAILABLE"

Give me a couple of hours to test that this change won't break anything.

[ademar]

I'm killing the OWIN module; I hope you are not using it.

[svdHero]

Is that the embedded web server? I'm new to .NET backends. If yes, please don't!

[ademar]

No, OWIN is an interface to run OWIN applications on Suave.

http://owin.org/

If you do not know my bet is you don't need it.

I'll be pushing new nugets later today implementing these changes.

[ademar]

I've just published a new pre-release v2.6.0-beta; try my suggestion above of using the ctx.userState dictionary to carry the correlation id.

Let me know how it goes.

[svdHero]

@ademar I haven't had a chance to test it, yet, but I will.

I have another question concerning this: What would be the easiest way to

1. Redirect logger output from console into a log file.
2. Even better: duplicate all the logger output such that it is not only printed to console, but also written to a file.

I noticed the outputWriter parameter in the LiterateConsoleTarget constructor, but I don't know how to use it. Are there any example code snippets somewhere?