Unable to attach a unique requestId to Suave log messages

[adamchester]

I'm looking at sending Suave logs to Seq.

A key feature is missing. Log messages generated by Suave should have the associated requestId (where appropriate) so they can be easily filtered:

Using the following sample code, I've managed to associate my custom log events with the context.request.trace.traceId field, however all other related Suave debug events have no such field:

open System
open Suave
open Suave.Operators
open Suave.Filters
open Suave.RequestErrors

[<EntryPoint>]
let main argv =
    let logger = Logary.Facade.Seq.SeqTarget([||], Logging.Verbose, "http://localhost:5341")
                 :> Suave.Logging.Logger
    let myapp : WebPart =
        choose [
            path "/" >=> GET >=> Successful.OK "Hello World!"
            path "/" >=> POST >=> Successful.OK "{\"hello\": \"world\"}"
            NOT_FOUND "What are you trying to do?"
        ]
        >=> logWithLevelStructured Logging.Info logger (fun context ->
            let fields : (string * obj) list = [
                "requestMethod", box context.request.method
                "requestPathAndQuery", box context.request.url.PathAndQuery
                "requestId", box context.request.trace.traceId
                "httpStatusReason", box context.response.status.reason
                "httpStatusCode", box context.response.status.code
                "requestForm", box context.request.form ]
            "HTTP {requestMethod} at \"{requestPathAndQuery}\" responded {httpStatusReason} ({httpStatusCode})",
            fields |> Map.ofList
        )

    let config = { defaultConfig with logger = logger }
    startWebServer config myapp

    0

@haf what do you think? Have you ever tried correlating Suave debug messages to a particular request?

[haf]

Yes, I'm on my way towards it, but haven't reached that point yet.

• https://github.com/SuaveIO/suave/blob/master/src/Suave/Http.fsi#L177
• http://zipkin.io/pages/data_model.html
• https://github.com/logary/logary/blob/master/src/targets/Logary.Targets.Zipkin/Targets_Zipkin.fs
• https://github.com/logary/logary/tree/master/src/targets/Logary.Zipkin
• https://github.com/logary/logary-js/blob/master/src/index.js#L94

So as you can see I have all the building parts written, just need to combine them. I wouldn't mind help doing that.

[lust4life]

module Program

open System
open Suave
open Suave.Operators
open Suave.Filters
open Suave.RequestErrors
open Suave.Logging
open Logary
open Logary.Adapters.Facade
open Logary.Configuration
open Logary.EventsProcessing
open Logary.Targets
open System.Runtime.Remoting.Messaging

[<EntryPoint>]
let main argv =

  let traceId =
    fun next msg ->
      Message.setContext "traceId" (CallContext.LogicalGetData("traceId")) msg
      |> next

  let threadId =
    fun next msg ->
      Message.setContext "ManagedThreadId" (System.Threading.Thread.CurrentThread.ManagedThreadId) msg
      |> next

  let logary = 
    Config.create "suave.example" "localhost"
    |> Config.ilogger (ILogger.LiterateConsole Verbose)
    |> Config.middleware traceId
    |> Config.middleware threadId
    |> Config.target (LiterateConsole.create LiterateConsole.empty "console")
    |> Config.processing (Events.events |> Events.sink ["console"])
    |> Config.build
    |> Hopac.Hopac.run

  LogaryFacadeAdapter.initialise<Suave.Logging.Logger> logary

  let logger = Suave.Logging.Log.create "logger.from.suave"
  let myapp : WebPart =
      (fun ctx -> async {
        CallContext.LogicalSetData("traceId", ctx.request.trace.traceId)
        logger.info (Suave.Logging.Message.eventX "set trace id from beginning")
        return Some ctx
      })
      >=>
      choose [
          path "/" >=> GET >=> fun x -> async {
            logger.info (Suave.Logging.Message.eventX "got some msg")
            do! Async.Sleep 200
            do! logger.infoWithBP (Suave.Logging.Message.eventX "after some working")
            failwith "something wrong"
            return! Successful.OK "Hello World!" x
          }
          path "/" >=> POST >=> Successful.OK "{\"hello\": \"world\"}"
          NOT_FOUND "What are you trying to do?"
      ]

  let eh (ex: exn) msg ctx = async {
    let msg =
      Suave.Logging.Message.eventX msg
      >> Suave.Logging.Message.addExn ex
      |> logger.infoWithBP
    do! msg

    return! Suave.RequestErrors.BAD_REQUEST (ctx.request.trace.traceId.ToString() + "   "+ ex.Message) ctx
  }

  let config = { defaultConfig with logger = logger; errorHandler = eh }
  startWebServer config myapp

  0

if you are concern about request logs around application business logic, maybe things above can meet your need.

however all other related Suave debug events have no such field:

some parts are not have their request info there, so they can not have such a field. if we can hook the set traceid part here facade.processRequest _ctx , maybe can get something you want ?