Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

NLog logger swallows a lot of messages #3428

Closed
vasily-kirichenko opened this issue May 2, 2018 · 2 comments
Closed

NLog logger swallows a lot of messages #3428

vasily-kirichenko opened this issue May 2, 2018 · 2 comments

Comments

@vasily-kirichenko
Copy link
Contributor 

open System
open Akkling
open Akkling
open System

[<EntryPoint>]
let main _ =
    let config = """
akka {  
    stdout-loglevel = DEBUG
    loglevel = DEBUG
    log-config-on-start = on        
    // loggers = ["Akka.Logger.NLog.NLogLogger, Akka.Logger.NLog"] <- commented for now
    actor {                
        debug {  
              receive = on 
              autoreceive = on
              lifecycle = on
              event-stream = on
              unhandled = on
        }
    }  
}"""
    let sys = System.create "test" (Configuration.parse config)

    let slave =
        props (actorOf2 (fun ctx msg ->
            logInfof ctx "Got %A" msg
            ignored()
        ))
        
    let master = 
        props (actorOf2 (fun ctx msg ->
            logInfof ctx "Got %A, spawing a slave..." msg
            let s = spawn ctx "slave-actor" slave
            s <! "From master to slave!"
            ignored()
        ))


    let a = spawn sys "master-actor" master
    a <! "oops!" 
    0

output:

[DEBUG][05/02/2018 09:00:29][Thread 0001][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Debug
[DEBUG][05/02/2018 09:00:29][Thread 0001][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Info
[DEBUG][05/02/2018 09:00:29][Thread 0001][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Warning
[DEBUG][05/02/2018 09:00:29][Thread 0001][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Error
[DEBUG][05/02/2018 09:00:29][Thread 0001][EventStream] StandardOutLogger started
[DEBUG][05/02/2018 09:00:30][Thread 0003][akka://test/] Started (Akka.Actor.GuardianActor)
[DEBUG][05/02/2018 09:00:30][Thread 0005][akka://test/system] Started (Akka.Actor.SystemGuardianActor)
[DEBUG][05/02/2018 09:00:30][Thread 0004][akka://test/user] Started (Akka.Actor.GuardianActor)
[DEBUG][05/02/2018 09:00:30][Thread 0003][akka://test/] now supervising akka://test/user
[DEBUG][05/02/2018 09:00:30][Thread 0003][akka://test/] now supervising akka://test/system
[DEBUG][05/02/2018 09:00:30][Thread 0006][akka://test/user] now watched by [akka://test/system]
[DEBUG][05/02/2018 09:00:30][Thread 0005][akka://test/system] now watched by [akka://test/]
[DEBUG][05/02/2018 09:00:30][Thread 0003][akka://test/system/log1-DefaultLogger] Started (Akka.Event.DefaultLogger)
[DEBUG][05/02/2018 09:00:30][Thread 0004][akka://test/system] now supervising akka://test/system/log1-DefaultLogger
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/log1-DefaultLogger#1496186702] to channel Akka.Event.Debug
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/log1-DefaultLogger#1496186702] to channel Akka.Event.Debug
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/log1-DefaultLogger#1496186702] to channel Akka.Event.Info
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/log1-DefaultLogger#1496186702] to channel Akka.Event.Info
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/log1-DefaultLogger#1496186702] to channel Akka.Event.Warning
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/log1-DefaultLogger#1496186702] to channel Akka.Event.Warning
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/log1-DefaultLogger#1496186702] to channel Akka.Event.Error
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/log1-DefaultLogger#1496186702] to channel Akka.Event.Error
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream(test)] Logger log1-DefaultLogger [DefaultLogger] started
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream(test)] Logger log1-DefaultLogger [DefaultLogger] started
[DEBUG][05/02/2018 09:00:30][Thread 0005][akka://test/system] now supervising akka://test/system/UnhandledMessageForwarder
[DEBUG][05/02/2018 09:00:30][Thread 0005][akka://test/system] now supervising akka://test/system/UnhandledMessageForwarder
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/UnhandledMessageForwarder#1221342939] to channel Akka.Event.UnhandledMessage
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] subscribing [akka://test/system/UnhandledMessageForwarder#1221342939] to channel Akka.Event.UnhandledMessage
[DEBUG][05/02/2018 09:00:30][Thread 0003][akka://test/system/UnhandledMessageForwarder] Started (Akka.Event.LoggingBus+UnhandledMessageForwarder)
[DEBUG][05/02/2018 09:00:30][Thread 0003][akka://test/system/UnhandledMessageForwarder] Started (Akka.Event.LoggingBus+UnhandledMessageForwarder)
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream(test)] StandardOutLogger being removed
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream(test)] StandardOutLogger being removed
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] unsubscribing [akka://all-systems/] from all channels
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream] unsubscribing [akka://all-systems/] from all channels
[DEBUG][05/02/2018 09:00:30][Thread 0001][EventStream(test)] Default Loggers started
[DEBUG][05/02/2018 09:00:30][Thread 0003][akka://test/system] now supervising akka://test/system/deadLetterListener
[DEBUG][05/02/2018 09:00:30][Thread 0005][EventStream] subscribing [akka://test/system/deadLetterListener#178358093] to channel Akka.Event.DeadLetter
[DEBUG][05/02/2018 09:00:30][Thread 0005][akka://test/system/deadLetterListener] Started (Akka.Event.DeadLetterListener)
[DEBUG][05/02/2018 09:00:30][Thread 0004][akka://test/system] now supervising akka://test/system/EventStreamUnsubscriber-1
[DEBUG][05/02/2018 09:00:30][Thread 0006][EventStreamUnsubscriber] registering unsubscriber with Akka.Event.EventStream
[DEBUG][05/02/2018 09:00:30][Thread 0006][akka://test/system/EventStreamUnsubscriber-1] Started (Akka.Event.EventStreamUnsubscriber)
[INFO][05/02/2018 09:00:30][Thread 0001][ActorSystem(test)]   akka : {
    stdout-loglevel : DEBUG
    loglevel : DEBUG
    log-config-on-start : on
    actor : {
      debug : {
        receive : on
        autoreceive : on
        lifecycle : on
        event-stream : on
        unhandled : on
      }
      serializers : {
        hyperion : "Akka.Serialization.HyperionSerializer, Akka.Serialization.Hyperion"
      }
      serialization-bindings : {
        System.Object : hyperion
      }
    }
  }

[DEBUG][05/02/2018 09:00:30][Thread 0004][akka://test/user] now supervising akka://test/user/master-actor
[DEBUG][05/02/2018 09:00:30][Thread 0004][akka://test/user/master-actor] Started (Akkling.Actors+FunActor`1[System.String])
[INFO][05/02/2018 09:00:30][Thread 0004][[akka://test/user/master-actor#1507315687]] Got "oops!", spawing a slave...
[DEBUG][05/02/2018 09:00:30][Thread 0005][akka://test/user/master-actor/slave-actor] Started (Akkling.Actors+FunActor`1[System.String])
[DEBUG][05/02/2018 09:00:30][Thread 0004][akka://test/user/master-actor] now supervising akka://test/user/master-actor/slave-actor
[INFO][05/02/2018 09:00:30][Thread 0005][[akka://test/user/master-actor/slave-actor#470602874]] Got "From master to slave!"

All is good, the info messages are there.

Now with the NLog logger on:

[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Debug
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Info
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Warning
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Error
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] StandardOutLogger started
[DEBUG][05/02/2018 09:02:12][Thread 0003][akka://test/] Started (Akka.Actor.GuardianActor)
[DEBUG][05/02/2018 09:02:12][Thread 0004][akka://test/user] Started (Akka.Actor.GuardianActor)
[DEBUG][05/02/2018 09:02:12][Thread 0005][akka://test/system] Started (Akka.Actor.SystemGuardianActor)
[DEBUG][05/02/2018 09:02:12][Thread 0003][akka://test/] now supervising akka://test/user
[DEBUG][05/02/2018 09:02:12][Thread 0003][akka://test/] now supervising akka://test/system
[DEBUG][05/02/2018 09:02:12][Thread 0006][akka://test/user] now watched by [akka://test/system]
[DEBUG][05/02/2018 09:02:12][Thread 0005][akka://test/system] now watched by [akka://test/]
[DEBUG][05/02/2018 09:02:12][Thread 0004][akka://test/system] now supervising akka://test/system/log1-NLogLogger
[DEBUG][05/02/2018 09:02:12][Thread 0003][akka://test/system/log1-NLogLogger] Started (Akka.Logger.NLog.NLogLogger)
[INFO][05/02/2018 09:02:12][Thread 0003][[akka://test/system/log1-NLogLogger#2059840408]] NLogLogger started
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://test/system/log1-NLogLogger#2059840408] to channel Akka.Event.Debug
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://test/system/log1-NLogLogger#2059840408] to channel Akka.Event.Info
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://test/system/log1-NLogLogger#2059840408] to channel Akka.Event.Warning
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://test/system/log1-NLogLogger#2059840408] to channel Akka.Event.Error
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream(test)] Logger log1-NLogLogger [NLogLogger] started
[DEBUG][05/02/2018 09:02:12][Thread 0006][akka://test/system] now supervising akka://test/system/UnhandledMessageForwarder
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] subscribing [akka://test/system/UnhandledMessageForwarder#991061292] to channel Akka.Event.UnhandledMessage
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream(test)] StandardOutLogger being removed
[DEBUG][05/02/2018 09:02:12][Thread 0005][akka://test/system/UnhandledMessageForwarder] Started (Akka.Event.LoggingBus+UnhandledMessageForwarder)
[DEBUG][05/02/2018 09:02:12][Thread 0001][EventStream] unsubscribing [akka://all-systems/] from all channels

A lot of messages are not presented:

  • the config is absent
  • the both of my info messages are lost

https://github.com/vasily-kirichenko/AkkaNLogBug
@vasily-kirichenko vasily-kirichenko changed the title NLog logger swallow a lot of messages NLog logger swallows a lot of messages May 2, 2018
@vasily-kirichenko
Copy link
Contributor Author

Solved by adding NLog config:

let nlogConfig = LoggingConfiguration()
let consoleTarget = new ColoredConsoleTarget()
nlogConfig.AddTarget("console", consoleTarget)
let rule = LoggingRule("*", LogLevel.Debug, consoleTarget)
nlogConfig.LoggingRules.Add(rule)
LogManager.Configuration <- nlogConfig

However, the adapter names are very long and rather meaningless, they do not contain actor names:

2018-05-02 12:11:43.9341|DEBUG|Akka.Actor.GuardianActor|now supervising akka://test/user/master-actor
2018-05-02 12:11:43.9341|DEBUG|Akkling.Actors+FunActor`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]|Started (Akkling.Actors+FunActor`1[System.String])
2018-05-02 12:11:43.9818|INFO|Akkling.Actors+FunActor`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]|Got "oops!", spawing a slave...
2018-05-02 12:11:43.9818|DEBUG|Akkling.Actors+FunActor`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]|Started (Akkling.Actors+FunActor`1[System.String])
2018-05-02 12:11:43.9837|DEBUG|Akkling.Actors+FunActor`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]|now supervising akka://test/user/master-actor/slave-actor
2018-05-02 12:11:43.9865|INFO|Akkling.Actors+FunActor`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]|Got "From master to slave!"

Which is already reported in Horusiath/Akkling#94

@snakefoot snakefoot mentioned this issue May 2, 2018
Closed
@snakefoot
Copy link

snakefoot commented May 17, 2018 •
edited
Loading

@vasily-kirichenko Try updating to latest Akka.Logger.NLog 1.3.1: https://www.nuget.org/packages/Akka.Logger.NLog/

It should improve the logger-names for NLog. Alternative use ${event-properties:item=logSource:whenEmpty=${logger}} instead of just ${logger}.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@vasily-kirichenko @snakefoot