Using TraceSource in Multithreaded environment

Question

I have written an application in F# using asyncronous-workflows. Now what I'd like to do is to add some Tracing to it!

There is basically a class A which can be instantiated several times. Each one of the instances is working independend asynchronous (in itself) and parallel (to others). My Basic idea now is to add a TraceSource instance for every instance of A, which is most likely what I want to do. I managed to solve the problem of distributing the TraceSource with the Async objects via https://github.com/matthid/fsharpasynctrace

However If every TraceSource instance is given the same name, some of them will be written in the same file (log.txt) and others will be written to {guid}log.txt.

If I give every instance an other name the user has to edit the app.config file to get the logging right. Every instance of A has a logical name given by the user so ideally I would save the log for the instance in name_log.txt. (This is because the user is basically creating instances of A at runtime)

So my question is: Is there a better way to do this, ie without the user interacting and still get the desired output and flexibility (via app.config)?

Note: Because basically everything is in the threadpool, and because there can be a lot of actions across instances at the same time, tracing classes or threads is not an option at all.

Note2: I can think of extending the app.config in some way and doing it myself, is this my only option?

EDIT: To make the Question more clear:

Imagine the following class:

module OtherModule = 
    let doSomethingAsync m = async{return()}
[<AbstractClass>]
type A (name:string) as x = 
    let processor = 
        MailboxProcessor.Start(
            fun inbox -> async {
                while true do
                    let! msg = inbox.Receive()
                    do! x.B(msg)
                    do! OtherModule.doSomethingAsync(msg)})
    abstract member B : string -> Async<unit>
    member x.Do(t:string) = processor.Post(t)

You have lots of instances of this class and every instance is living very long. You have now the situation described above. (You also want to trace abstract member, which could be done by a protected tracesource... which is not available in F#. And you want to trace some module Functions. Thats why i have choosen the above distribution model. If you do it any other way you will have a hard time going through the logs.)

Answer 1

I haven't tested this, but it seems like it would work. The TraceXXX methods on TraceSource accept an id parameter. What about using that as an "instance identifier"? You could then write a custom trace listener to redirect the output based on that id. Maybe this will serve as a starting point:

type MultiOutputTraceListener(directory) =
  inherit TraceListener()

  let mutable output : TextWriter = null
  let writers = Dictionary()

  let setOutput (id: int) =
    lock writers <| fun () ->
      match writers.TryGetValue(id) with
      | true, w -> output <- w
      | _ ->
        let w = new StreamWriter(Path.Combine(directory, id.ToString() + ".log"))
        writers.Add(id, w)
        output <- w

  override x.Write(msg: string) = output.Write(msg)
  override x.WriteLine(msg: string) = output.WriteLine(msg)

  override x.TraceData(eventCache, source, eventType, id, data: obj) =
    setOutput id
    base.TraceData(eventCache, source, eventType, id, data)

  override x.TraceData(eventCache, source, eventType, id, data) =
    setOutput id
    base.TraceData(eventCache, source, eventType, id, data)

  override x.TraceEvent(eventCache, source, eventType, id, message) =
    setOutput id
    base.TraceEvent(eventCache, source, eventType, id, message)

  override x.TraceEvent(eventCache, source, eventType, id, format, args) =
    setOutput id
    base.TraceEvent(eventCache, source, eventType, id, format, args)

  override x.Dispose(disposing) =
    if disposing then
      for w in writers.Values do
        w.Dispose()

Usage

module Tracing =
  let Source = TraceSource("MyTraceSource")

type A(id) =
  member x.M() =
    Tracing.Source.TraceEvent(TraceEventType.Verbose, id, "Entering method M()")
    ...

let a1 = A(1)
let a2 = A(2)

Answer 2

Your solution looks pretty interesting, but I think that using custom workflow based on async just to pass around object used for tracing might be an overkill.

I would probably try using F# agents - you could create a TracingAgent with methods such as Error, Warning and Trace to report individual kinds of messages. When you initialize the agent, you can specify what file it should use. When you call the agent from multiple threads, that's fine because agents serialize messages as they process them.

So, your user code would look like this:

let tracer = TracingAgent("Workflow 01")

let doSomeThingInner v = async {
    tracer.Critical "CRITICAL! %s" v
    return "ToOuter" }

let testIt () = async {
    tracer.Verbose "Verbose!" 
    let! d = doSomeThingInner "ToInner"
    tracer.Warning "WARNING: %s" d }

testIt () |> Async.RunSynchronously

This way, you will have to pass around tracer objects on your own, but that should not really be an issue, because normally you would use a small number of global tracers. If you want to change the output file for some reason, you can add message to your agent for doing that.

The structure of the agent would be something like:

type TracingAgent(log) = 
  let inbox = MailboxProcessor.Start(fun inbox -> async {
    while true do
      let! msg = inbox.Receive()
      // Process the message - write to a log
    })
  // Methods that are used to write to the log file
  member x.Warning fmt = 
    Printf.kprintf (fun str -> inbox.Post(Warning(str))) fmt

  // Optionally a method that changes the log file
  member x.ChangeFile(file) = 
    inbox.Post(ChangeFile(file))

The configuration of the logging could be loaded from a config file - I suppose the logical place for doing that would be inside the TracingAgent.

Answer 3

After some testing and thinking about the answers I came up with the following solution:

type ITracer = 
    inherit IDisposable
    abstract member log : Diagnostics.TraceEventType ->Printf.StringFormat<'a, unit> -> 'a


type ITracer with
    member x.logVerb fmt = x.log System.Diagnostics.TraceEventType.Verbose fmt
    member x.logWarn fmt = x.log System.Diagnostics.TraceEventType.Warning fmt
    member x.logCrit fmt = x.log System.Diagnostics.TraceEventType.Critical fmt
    member x.logErr fmt =  x.log System.Diagnostics.TraceEventType.Error fmt
    member x.logInfo fmt = x.log System.Diagnostics.TraceEventType.Information fmt

type MyTraceSource(traceEntry:string,name:string) as x= 
    inherit TraceSource(traceEntry)
    do 
        let newTracers = [|
            for l in x.Listeners do
                let t = l.GetType()
                let initField =
                    t.GetField(
                        "initializeData", System.Reflection.BindingFlags.NonPublic ||| 
                                          System.Reflection.BindingFlags.Instance)
                let oldRelFilePath =
                    if initField <> null then
                         initField.GetValue(l) :?> string
                    else System.IO.Path.Combine("logs", sprintf "%s.log" l.Name)

                let newFileName =
                    if oldRelFilePath = "" then ""
                    else
                        let fileName = Path.GetFileNameWithoutExtension(oldRelFilePath)
                        let extension = Path.GetExtension(oldRelFilePath)
                        Path.Combine(
                            Path.GetDirectoryName(oldRelFilePath),
                            sprintf "%s.%s%s" fileName name extension)
                let constr = t.GetConstructor(if newFileName = "" then [| |] else [| typeof<string> |])
                if (constr = null) then 
                    failwith (sprintf "TraceListener Constructor for Type %s not found" (t.FullName))
                let listener = constr.Invoke(if newFileName = "" then [| |]  else [| newFileName |]) :?> TraceListener
                yield listener |]
        x.Listeners.Clear()
        x.Listeners.AddRange(newTracers)

type DefaultStateTracer(traceSource:TraceSource, activityName:string) = 
    let trace = traceSource
    let activity = Guid.NewGuid()
    let doInId f = 
        let oldId = Trace.CorrelationManager.ActivityId
        try
            Trace.CorrelationManager.ActivityId <- activity
            f()
        finally
            Trace.CorrelationManager.ActivityId <- oldId
    let logHelper ty (s : string) =  
        doInId 
            (fun () ->
                trace.TraceEvent(ty, 0, s)
                trace.Flush())
    do 
        doInId (fun () -> trace.TraceEvent(TraceEventType.Start, 0, activityName);)

    interface IDisposable with
        member x.Dispose() = 
            doInId (fun () -> trace.TraceEvent(TraceEventType.Stop, 0, activityName);)

    interface ITracer with 
        member x.log ty fmt = Printf.kprintf (logHelper ty) fmt  

Actually I found also a solution not depending on reflection: You inherit all important TraceListeners yourself and expose the data they got initialized with. Then you create the matching Listeners with the changed data in the MyTraceSource constructor.

Edit: The non reflection solution is not as general as the above with reflection.

Usage is like this:

let SetTracer tracer (traceAsy:AsyncTrace<_,_>) = 
    traceAsy.SetInfo tracer
    traceAsy |> convertToAsync

module OtherModule = 
    let doSomethingAsync m = asyncTrace() {
        let! (tracer:ITracer) = traceInfo()
        return()
        }

[<AbstractClass>]
type A (name:string) as x = 

    let processor = 
        let traceSource = new MyTraceSource("Namespace.A", name)
        MailboxProcessor.Start(
            fun inbox -> async {
                while true do
                    let tracer = new DefaultStateTracer(traceSource, "Doing activity Foo now") :> ITracer
                    let! msg = inbox.Receive()
                    let w = x.B(msg) |> SetTracer tracer
                    do! OtherModule.doSomethingAsync(msg) |> SetTracer tracer})
    abstract member B : string -> AsyncTrace<ITracer, unit>
    member x.Do(t:string) = processor.Post(t)

If you configured in app.config "logs\Namespace.A.log" then you will get files like "logs\Namespace.A.name.log".

NOTE: you still have to copy the other properties you can configure over app.config, but it should be easy to complete that now.

If you feel like this is not the right way to do this please leave a comment.

EDIT: Added this tracing solution to https://github.com/matthid/fsharpasynctrace.