MetroLog stops logging when a few exceptions occurred

[basprins]

I have a universal app that runs on a Raspberry Pi with Windows IoT which uses MetroLog as loggings framework.

For some completely unknown reasons to me, sometimes MetroLog decides to stop logging to file completely. My app still runs, and it responds and does what it should do, except that there are no new log entries (and I know for certain that code is executes with log statements).

The usage of MetroLog in my app is as follows:

Creation/initialization in my App.xaml.cs

    private static readonly ILogger Log;

    static App()
    {
        var streamingFileTarget = new StreamingFileTarget(new SingleLineLayout());
        streamingFileTarget.FileNamingParameters.CreationMode = FileCreationMode.AppendIfExisting;
        streamingFileTarget.KeepLogFilesOpenForWrite = false;
        streamingFileTarget.RetainDays = 90;

        LogManagerFactory.DefaultConfiguration.AddTarget(LogLevel.Trace, LogLevel.Fatal, streamingFileTarget);

        Log = LogManagerFactory.DefaultLogManager.GetLogger<App>();
    }

For the rest, I have a lot of classes that have a static Logger instance, like this:

    private static ILogger Log = LogManagerFactory.DefaultLogManager.GetLogger(typeof(FlowSensor));

or:

    private static readonly ILogger Log = LogManagerFactory.DefaultLogManager.GetLogger<CloudClient>();

and usage of these instances is straight forward like this:

            try
            {
               // do stuff
            }
            catch (Exception e)
            {
                Log.Error($"'{nameof(GetEntityAsync)}' ran into an exception (retry counter = {i}): {e}");

                if (i == MaxRetries)
                {
                    throw;
                }

                await Task.Delay(30);
            }

The example above causes the logger to stop completely, it retries a couple of times, and I can see the log messages in the logging, and then nothing else gets logged.

Any idea how to troubleshoot this? I really have no clue whatsoever what is the cause of this weird behaviour.

Again. the App continues to run, and 100% sure code gets executes that contains log statements, so it seems that the logger died / stops flushing to disk?

[MMalikKhan]

@basprins its hard to tell what might be the problem, but can you try these options. Sometime the file is locked and not released and other process cannot access it .

streamingFileTarget.IncludeLogger = true; this should create a different file for each logger and you will find which logger is not working...

Also, what i notice is if you have any Dependency injection or different projects where you are using the logger, then make sure you initialize the logger in each project.

Also worth trouble shooting if the configuration code is executed when the logger tries to log..?

Try those let us know if you go any further

[basprins]

@MMalikKhan that's very helpful commenting! Thanks a lot for that.

I left our machine in production for a day, and I can at least confirm that loggings is continued when a day is passed (and thus a new log file is created). So your suggestion of a file lock issue makes sense.

I will start with creating a file per logger, and when I learn more I will share it here.

Thanks again !

[basprins]

@MMalikKhan

I added the "includelogger" in order to see which logs do continue to run. I made a copy of the directory listing, which indeed shows that a few loggers have stopped logging:

36bb0\LocalState\MetroLogs> ls | sort LastWriteTime -Descending

Directory: \\minwinpc\c$\Data\Users\DefaultAccount\AppData\Local\Packages\Durocan_ns7r26fq36bb0\LocalState\MetroLog
s

Mode LastWriteTime Length Name

---

-a---- 10-3-2017 10:55 64130 Log - PulseDetector - 20170310.log
-a---- 10-3-2017 07:58 640 Log - Heater3(pin=21 - 20170310.log
-a---- 10-3-2017 07:58 640 Log - Heater2(pin=20 - 20170310.log
-a---- 10-3-2017 07:58 640 Log - Heater1(pin=16 - 20170310.log
-a---- 10-3-2017 00:44 1065 Log - Heater3(pin=21 - 20170309.log
-a---- 10-3-2017 00:44 1065 Log - Heater2(pin=20 - 20170309.log
-a---- 10-3-2017 00:44 1065 Log - Heater1(pin=16 - 20170309.log
-a---- 10-3-2017 00:44 144423 Log - PulseDetector - 20170309.log
-a---- 8-3-2017 22:03 135316 Log - PulseDetector - 20170308.log
-a---- 8-3-2017 21:29 111 Log - StateMachine - 20170308.log
-a---- 8-3-2017 21:29 1268990 Log - ExecutingScheme - 20170308.log
-a---- 8-3-2017 21:29 9661 Log - 20170308.log
-a---- 8-3-2017 21:29 8970 Log - CloudClient - 20170308.log
-a---- 8-3-2017 17:26 1366 Log - Heater3(pin=21 - 20170308.log
-a---- 8-3-2017 17:26 1366 Log - Heater2(pin=20 - 20170308.log
-a---- 8-3-2017 17:26 1366 Log - Heater1(pin=16 - 20170308.log
-a---- 8-3-2017 00:59 17761 Log - PulseDetector - 20170307.log
-a---- 8-3-2017 00:59 175469 Log - ExecutingScheme - 20170307.log
-a---- 8-3-2017 00:17 104 Log - Heater3(pin=21 - 20170307.log
-a---- 8-3-2017 00:17 104 Log - Heater2(pin=20 - 20170307.log
-a---- 8-3-2017 00:17 104 Log - Heater1(pin=16 - 20170307.log
-a---- 7-3-2017 22:05 276 Log - 20170307.log
-a---- 7-3-2017 22:05 1206 Log - StateMachine - 20170307.log
-a---- 7-3-2017 22:05 644 Log - I2CChannel - 20170307.log
-a---- 7-3-2017 22:05 168 Log - Arduino - 20170307.log
-a---- 7-3-2017 22:05 2608 Log - LoadConfiguration - 20170307.log
-a---- 7-3-2017 22:05 194 Log - App - 20170307.log

As you can see these three stop logging around 21:29

-a---- 8-3-2017 21:29 111 Log - StateMachine - 20170308.log
-a---- 8-3-2017 21:29 1268990 Log - ExecutingScheme - 20170308.log
-a---- 8-3-2017 21:29 9661 Log - 20170308.log
-a---- 8-3-2017 21:29 8970 Log - CloudClient - 20170308.log

An (user handled) exception occurred at that time (the server connection failed, which recovered later). No sure why that would cause any trouble. The catch is nothing special either, just log and handle the exception....

You mentioned two other points:
Also, what i notice is if you have any Dependency injection or different projects where you are using the logger, then make sure you initialize the logger in each project.

Also worth trouble shooting if the configuration code is executed when the logger tries to log..?

Can you elaborate on both? How do I initialize the logger in another project (other than LogManagerFactory.GetLogger)? And how exactly do I see if configuration code is executed when the logger tries to log?

Hope you can clarify a few parts for me, or maybe you have other ideas that might help me further.

Many thanks again.