Confusion around loglevel, not seeing expected console logs

[aggieben]

I'm working on a .NET Core console app intended to be run as a service. I configure a log manager in as a module-level binding, like this:

module Cfg
open Hopac
open Logary
open Logary.Configuration
open Logary.Message
open Logary.Targets

let private defaultLogLevel = Info
let private buildLogary() = 
    let console = LiterateConsole.create LiterateConsole.empty "console"
    let logfileName = File.Naming ("{service}-{date}", "log")
    let logfile = File.create (File.FileConf.create Environment.CurrentDirectory logfileName) "file"
    Config.create "My.App.Name" (Dns.GetHostName())
    |> Config.targets [console; logfile] 
    |> Config.ilogger (ILogger.Console Info)
    |> Config.build
    |> run

let private logary = buildLogary()
let getLogger (name:string) =
    logary.getLogger (PointName.parse name)

In the same module, I also parse arguments using Argu, and with Log_Level being one of the arguments, I try to adjust the logmanager's loglevel like this:

let mutable private parsedArgs : ParseResults<Arguments> option = None
let setArgs args =
    match parsedArgs with
    | Some _ -> 
        log.error (eventX "Attempt to set args after initialization")
        Result.Error()
    | None ->
        let pa = parser.Parse args
        let logLevel = pa.GetResult(Log_Level, Info)
        
        log.info (eventX <| sprintf "Setting log level: %A" logLevel)
        logary.switchLoggerLevel (".*", logLevel)

        parsedArgs <- pa |> Some
        Result.Ok()

I know this at least partially works, because if I use my Log_Level option and set it to Debug, then I see some of my expected debug-level outputs. However, I don't see them all.

For example, in my entry point:

[<EntryPoint>]
let main argv =
    use mre = new System.Threading.ManualResetEventSlim(false);
    use sub = Console.CancelKeyPress.Subscribe(fun _ -> mre.Set())

    let log = getLogger _moduleType.FullName

    match setArgs argv with
    | Ok _ -> 
        let initStr = getNetwork() |> sprintf "Initializing daemon (%A)"
        log.info (eventX initStr)

        let dnsCh = Peers.startDiscoveryServer() |> run

        log.debug (eventX <| sprintf "discovery server started")
        Peers.getAddresses dnsCh |> run |> ignore

    | Result.Error _ -> 
        log.error (eventX "Failed to initialize daemon")
        failwith "unexpected failure in initialization"

    mre.Wait()
    0

the "discovery server started" message makes it to the console. But elsewhere, in the Hopac job created by startDiscoveryServer(), they don't make it to the console.

let startDiscoveryServer () = job {
        let ch = Ch<IPHostEntry>()
        let rec server () = job {
            _log.debug (eventX <| sprintf "waiting on IPHostEntry")
            let! iphe = Ch.take ch
            _log.debug (eventX <| sprintf "got IPHostEntry with %d addresses" iphe.AddressList.Length)
            return! server()
        }
        do! Job.start (server())
        return ch
    }

When I run under a debugger, I can prove that the startDiscoveryServer job actually does execute because I can hit a breakpoint; But the "waiting on IPHostEntry" message never appears in the output. If I change it to an info-level message, it does appear. To recap, these are the messages that appear in the console:

λ  dotnet run -- --log-level debug
[09:46:51 INF] Initializing daemon (network) <My.App.Name.Program>
[09:46:51 DBG] discovery server started <My.App.Name.Program>
[09:46:51 INF] Setting log level: Debug <My.App.Name.Cfg>

Am I switching the log level incorrectly, or is there some odd interaction between jobs as used in my app vs jobs as used in Logary that would prevent these messages from going out?

[haf]

I’m not sure what might be going on. I can help you debug it after my vacation if you could put together a minimal repel like the above. I haven’t seen this behaviour except if one Hopac thread is crashing in the background due to the app code.

[aggieben]

I've created this: https://github.com/aggieben/logary-hopac-repro in an attempt to repro. I haven't yet reproduced the issue, but I'll keep trying as I have time.

[haf]

I'm going to close this due to the lack of a repro. If you manage to reproduce it, give me a shout!