Logging enhancements & error/warning logging bug corrections

[zsogitbe]

1. There were a lot of unnecessary logging messages which were slowing down execution. We should only show detailed logging messages if details are requested.
2. There were a few places where error or warning level was missing.

[zhongkaifu]

Hi @zsogitbe

In Logger class, it already has code to check if the log should be output or not by checking Verbose value. (File: https://github.com/zhongkaifu/Seq2SeqSharp/blob/master/AdvUtils/Logger.cs) public static void WriteLine(string s, params object[] args) { if (Verbose == LogVerbose.None) { return; }

        WriteLine(Level.info, s, args);
    }

So, you could move these checks: """ if (Logger.Verbose != Logger.LogVerbose.None && Logger.Verbose != Logger.LogVerbose.Normal && Logger.Verbose != Logger.LogVerbose.Callback) """ into Logger.WriteLine(...), so it would be much easier to maintain this change.

Thanks Zhongkai Fu

[zsogitbe]

The problem with that is that we cannot differentiate between details and important info. What I have done is let through only a few messages if no details are requested. Or do you mean something else?(Sent from Smartphone) -------- Oorspronkelijk bericht --------Van: Zhongkai Fu @.> Datum: 10-11-2023 17:09 (GMT+01:00) Aan: zhongkaifu/Seq2SeqSharp @.> Cc: Zoli Somogyi @.>, Mention @.> Onderwerp: Re: [zhongkaifu/Seq2SeqSharp] Logging enhancements & error/warning logging bug corrections (PR #80) Hi @zsogitbe In Logger class, it already has code to check if the log should be output or not by checking Verbose value. ("https://github.com/zhongkaifu/Seq2SeqSharp/blob/master/AdvUtils/Logger.cs">https://github.com/zhongkaifu/Seq2SeqSharp/blob/master/AdvUtils/Logger.cs) public static void WriteLine(string s, params object[] args) { if (Verbose == LogVerbose.None) { return; } WriteLine(Level.info, s, args); }

So, you could move these checks: """ if (Logger.Verbose != Logger.LogVerbose.None && Logger.Verbose != Logger.LogVerbose.Normal && Logger.Verbose != Logger.LogVerbose.Callback) """ into Logger.WriteLine(...), so it would be much easier to maintain this change. Thanks Zhongkai Fu

—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you were mentioned.Message ID: @.***>

[zhongkaifu]

I see. Maybe the Logger.Level and Logger.LogVerbose should be merged into a single variable, and then check if these log should be printed out according to Verbose in setting.

The new Logger.Level could look like: {err, warn, info, details, debug}

I'm not sure what's scenario that Callback and Progress in existing LogVerbose should be used, or they are already covered by the above types?

[zsogitbe]

We use LogVerbose now for directing the messages to different locations: a) console b) callback c) logfile. I think that this is good. The name 'verbose' is maybe misleading but no problem for me.

The problem is that we have hundreds of 'info' messages which slow down execution and a bit disturbing because you do not see the important staff anymore between all of these messages. We need to differentiate between important info and less important info. There is no easy solution for this, except what I have done. The other solution (similar to what you suggest) would be much more work because we would need to modify each logging line where we log info (hundreds). With this solution we would need to differentiate between important and less important info messages, for example, by adding a new info level, for example, 'infodetail'. But, the level is the first param in WriteLine, therefore we cannot use default value, thus we would need to change each info line in the code and add the info level... there are approximately ~300 lines...

[zhongkaifu]

Maybe we could create a new enums called "Destination" for console, callback and logfile. It may look likes: Enum Destination { Console = 1, Callback = 2, LogFile = 4 }

and use AND operator to let logs output to multi-destination.

For "Verbose", it will be just used to control which information users want to log. It could look likes: { ERROR = 1, WARNING = 2, INFO = 4, DEBUG = 8 } And users could use settings "LogVerbose" in config file to control which information should be logged, for example: LogVerbose=7 means it will log error, warning and info, but do not log debug information.

For existing WriteLine, if it doesn't specify log level, the default level will be "info". In addition, most of these logs are printed out during loading model and when the model starts to train or infer, it won't print out too much logs, so I don't understand why it will make your execution slow down.

[zsogitbe]

Destination

For the destination we would probably need a kind of bitset in c# like this:

[Flags]
public enum LogDestination: byte
{
    Console = 0b_0000_0000,  // 0
    Callback = 0b_0000_0001,  // 1
    LogFile = 0b_0000_0010,  // 2
    //Placeholder = 0b_0000_0100,  // 4
}

And, then the user sets it like this:

LogDestination ldest = LogDestination.Console | LogDestination.LogFile;

And in Logger we check it like this:

bool isConsole = (ldest & LogDestination.Console) == LogDestination.Console;

Verbose

I do not like Verbose because it does not handle the situations we need. For example, stack trace should only be printed if DEBUG is requested, but it is usually an error message. Also, this still does not solve the issue of important INFO and less important INFO. And, it does not solve the issue of having a progress message which is usually also just an INFO. Etc.

Maybe we need an extra Enum for message type like this:

public enum MessageType
{
    Normal,
    Detail,
    Progress
}

We can, then set in the code Normal for some INFO and Detail for most of the INFO. In Logger we print Detail only if Verbose = DEBUG. Or, for stack trace, we set it to Detail and the error is only printed in Logger if Verbose = Debug.

But, this will be a bit longer work, then my current pull. What would you like to do?

[zhongkaifu]

It seems Trace and Debug class in .NET could resolve these problems. https://learn.microsoft.com/en-us/dotnet/api/system.diagnostics.trace?view=net-7.0 https://learn.microsoft.com/en-us/dotnet/api/system.diagnostics.debug?view=net-7.0

It has different types of Listeners (Console, Callback, Text file and others). Debug class is only for Debug build and could be used to output call stack. Trace class could be used for Release build and output logs in MessageType,

For MessageType, why "Error" and "Warning" are not included in it?

[zsogitbe]

Because Error, Warning and Info should all have this MessageType. For example, if an INFO is MessageType.Detail, then it will only be printed when Verbose = DEBUG. Or, a stack trace ERROR should have MessageType.Detail also and thus it will not be printed if Verbose < DEBUG.

[zhongkaifu]

I just made a commit: https://github.com/zhongkaifu/Seq2SeqSharp/commit/3db7c6e2d2445c63afa5b3fbeaa1d447e0b88514 It introduces two new options for logging:

    [Arg("Log destination. Supported Values: None = 0, Console = 1, LogFile = 2, Callback = 4, and These values can be combined. For example: Value 3 means the log will be outputted to both Console and LogFile", nameof(LogDestination))]
    public Logger.Destination LogDestination = (Logger.Destination.Console | Logger.Destination.Logfile);

    [Arg("The level of logs to be printed out. Supported Values: none = 0, err = 1, warn = 2, info = 4 and debug = 8. These values can be combined. For example: Value 15 means err, warn, info and debug will be outputted.", nameof(LogLevel))]
    public Logger.Level LogLevel = (Logger.Level.err | Logger.Level.warn | Logger.Level.info | Logger.Level.debug);

You could set LogDestination = Logger.Destination.LogFile to ask Logger only prints out logs to file rather than console. For those logs which you think they are too much, you can rewrite those logs calling to Logger.WriteLine(Logger.Level.debug, ...), and set LogLevel = 7 in config file or command line, then it won't be printed out.

[zsogitbe]

OK! It looks cleaner and more logical. I have adjusted the callback part a bit in the Logger to handle progress reporting. I have also adjusted my pull request to the new form (added debug level instead of the long line...). I would however still remove Logger.Writeline in the future without a logging level. I think that the logging level should be required all the time.

[zsogitbe]

I have encountered a few problems with the new Logger:

• If I do not know the logfile name when I initialize the Logger, then I cannot set it later. Reinitializing the Logger does not work because the Trace listener is not removed.
• Also, if Initialize is called again, than what happens to the already existing Trace listeners?

[zhongkaifu]

OK! It looks cleaner and more logical. I have adjusted the callback part a bit in the Logger to handle progress reporting. I have also adjusted my pull request to the new form (added debug level instead of the long line...). I would however still remove Logger.Writeline in the future without a logging level. I think that the logging level should be required all the time.

Totally agree. Or we could have different methods for logs in different levels, such as: WriteInfo ==> Print out info logs WriteError ==> Print out error logs WriteDebug ==> Print out debug logs ...

[zhongkaifu]

I have encountered a few problems with the new Logger:

• If I do not know the logfile name when I initialize the Logger, then I cannot set it later. Reinitializing the Logger does not work because the Trace listener is not removed.
• Also, if Initialize is called again, than what happens to the already existing Trace listeners?

I just made a fix for it. For re-initialization, the existing listeners will be closed and removed from Trace, and then re-initialize.

[zsogitbe]

Good job! Thank you!