Logging to AzureBlogStorage for level Info not working

[sev-22]

Writing logs to my Azure Blob Storage works in my first tests fine but for log level Info. I loaded the newest version: <PackageReference Include="NLog.Extensions.AzureBlobStorage" Version="4.2.0" />

There is just no information contained in the log for this level. What's wrong?

` string blobName = $"{this.AzureStorageBlobNamePrefix}${{shortdate}}${{level}}.log";

            // Azure Blob Storage-Target erstellen
            BlobStorageTarget blobStorageTarget = new()
            {
                Name = blobStorageTargetName,
                ConnectionString = this.AzureStorageConnectionString,
                Container = this.AzureStorageContainerName,
                BlobName = blobName,
                Layout = layout,
            };

            // Azure Blob Storage-Target zur LoggingConfiguration hinzufügen
            config.AddTarget(blobStorageTargetName, blobStorageTarget);

            // Regel erstellen, um das Ziel mit den gewünschten Protokollereignissen zu verknüpfen
            var rule = new LoggingRule("*", LogLevel.Trace, blobStorageTarget);
            config.LoggingRules.Add(rule);`

[snakefoot]

Try activate https://github.com/NLog/NLog/wiki/Internal-Logging and look for clues / issues.

[sev-22]

Thanks for the hint. The Log looks fine for me. But the Info level is still not logged.

Internal Log;

2023-06-30 10:57:50.1848 Debug Adding target NLog.Targets.BlobStorageTarget(Name=_blubb_nlog_blob_target_name) 2023-06-30 10:57:50.1848 Info Registered target NLog.Targets.BlobStorageTarget(Name=_blubb_nlog_blob_target_name) 2023-06-30 10:57:50.1848 Debug Adding target NLog.Targets.ConsoleTarget(Name=_blubb_nlog_console_target_name) 2023-06-30 10:57:50.1848 Info Registered target NLog.Targets.ConsoleTarget(Name=_blubb_nlog_console_target_name) 2023-06-30 10:57:50.1848 Debug Adding target NLog.Targets.Wrappers.AsyncTargetWrapper(Name=_blubb_nlog_console_target_nameAsync) 2023-06-30 10:57:50.1848 Info Registered target NLog.Targets.Wrappers.AsyncTargetWrapper(Name=_blubb_nlog_console_target_nameAsync) 2023-06-30 10:57:50.1848 Debug No file exists at candidate config file location: C:\Users\Bla\AppData\Local\JetBrains\Installations\ReSharperPlatformVs17_21cb8e27_000\TestRunner\netcoreapp3.0\ReSharperTestRunner.exe.nlog 2023-06-30 10:57:50.1848 Debug No file exists at candidate config file location: C:\Users\Bla\AppData\Local\JetBrains\Installations\ReSharperPlatformVs17_21cb8e27_000\TestRunner\netcoreapp3.0\ReSharperTestRunner.dll.nlog 2023-06-30 10:57:50.1848 Debug No file exists at candidate config file location: C:\Users\Bla\Source\Repos\BlubbUtils\UnitTestsNew\bin\Debug\net6.0\NLog.config 2023-06-30 10:57:50.1848 Debug No file exists at candidate config file location: C:\Users\Bla\AppData\Local\JetBrains\Installations\ReSharperPlatformVs17_21cb8e27_000\TestRunner\netcoreapp3.0\NLog.config 2023-06-30 10:57:50.1972 Debug No file exists at candidate config file location: C:\Users\Bla\Source\Repos\BlubbUtils\UnitTestsNew\bin\Debug\net6.0\NLog.dll.nlog 2023-06-30 10:57:50.1972 Debug Targets not configured for Logger: NLogLogger 2023-06-30 10:57:50.1972 Info NLog Configuration has not been loaded. 2023-06-30 10:57:50.1972 Debug LogFactory Flush with timeout=15 secs 2023-06-30 10:57:50.1972 Debug No file exists at candidate config file location: C:\Users\Bla\AppData\Local\JetBrains\Installations\ReSharperPlatformVs17_21cb8e27_000\TestRunner\netcoreapp3.0\ReSharperTestRunner.exe.nlog 2023-06-30 10:57:50.1972 Debug No file exists at candidate config file location: C:\Users\Bla\AppData\Local\JetBrains\Installations\ReSharperPlatformVs17_21cb8e27_000\TestRunner\netcoreapp3.0\ReSharperTestRunner.dll.nlog 2023-06-30 10:57:50.1972 Debug No file exists at candidate config file location: C:\Users\Bla\Source\Repos\BlubbUtils\UnitTestsNew\bin\Debug\net6.0\NLog.config 2023-06-30 10:57:50.1972 Debug No file exists at candidate config file location: C:\Users\Bla\AppData\Local\JetBrains\Installations\ReSharperPlatformVs17_21cb8e27_000\TestRunner\netcoreapp3.0\NLog.config 2023-06-30 10:57:50.1972 Debug No file exists at candidate config file location: C:\Users\Bla\Source\Repos\BlubbUtils\UnitTestsNew\bin\Debug\net6.0\NLog.dll.nlog 2023-06-30 10:57:50.1972 Debug Adding target NLog.Targets.BlobStorageTarget(Name=_blubb_nlog_blob_target_name) 2023-06-30 10:57:50.1972 Info Registered target NLog.Targets.BlobStorageTarget(Name=_blubb_nlog_blob_target_name) 2023-06-30 10:57:50.1972 Debug Adding target NLog.Targets.ConsoleTarget(Name=_blubb_nlog_console_target_name) 2023-06-30 10:57:50.1972 Info Registered target NLog.Targets.ConsoleTarget(Name=_blubb_nlog_console_target_name) 2023-06-30 10:57:50.1972 Debug Adding target NLog.Targets.Wrappers.AsyncTargetWrapper(Name=_blubb_nlog_console_target_nameAsync) 2023-06-30 10:57:50.1972 Info Registered target NLog.Targets.Wrappers.AsyncTargetWrapper(Name=_blubb_nlog_console_target_nameAsync) 2023-06-30 10:57:50.1972 Debug --- NLog configuration dump --- 2023-06-30 10:57:50.1972 Debug Targets: 2023-06-30 10:57:50.1972 Debug AzureBlobStorageTarget(Name=_blubb_nlog_blob_target_name) 2023-06-30 10:57:50.1972 Debug ConsoleTarget(Name=_blubb_nlog_console_target_name) 2023-06-30 10:57:50.1972 Debug AsyncWrapper_ConsoleTarget(Name=_blubb_nlog_console_target_nameAsync) 2023-06-30 10:57:50.1972 Debug Rules: 2023-06-30 10:57:50.2124 Debug logNamePattern: (:All) levels: [ Trace Debug Info Warn Error Fatal ] writeTo: [ _blubb_nlog_blob_target_name ] 2023-06-30 10:57:50.2124 Debug logNamePattern: (:All) levels: [ ] writeTo: [ _blubb_nlog_console_target_nameAsync ] 2023-06-30 10:57:50.2124 Debug --- End of NLog configuration dump --- 2023-06-30 10:57:50.2124 Debug Object reflection needed for unknown type: NLog.Targets.BlobStorageTarget 2023-06-30 10:57:50.2124 Debug Object reflection needed for unknown type: NLog.Targets.TargetWithContext+TargetWithContextLayout 2023-06-30 10:57:50.2124 Info Validating config: TargetNames=_blubb_nlog_blob_target_name, _blubb_nlog_console_target_nameAsync, ConfigItems=34 2023-06-30 10:57:50.2124 Debug Unused target checking is started... Rule Count: 2, Target Count: 3 2023-06-30 10:57:50.2124 Debug Unused target checking is completed. Total Rule Count: 2, Total Target Count: 3, Unused Target Count: 0 2023-06-30 10:57:50.2512 Debug AzureBlobStorageTarget(Name=_blubb_nlog_blob_target_name): Initialized 2023-06-30 10:57:50.2512 Debug Targets configured when LogLevel >= Trace for Logger: NLogLogger 2023-06-30 10:57:50.2512 Debug Logger NLogLogger [Trace] => _blubb_nlog_blob_target_name 2023-06-30 10:57:50.2512 Debug Logger NLogLogger [Debug] => _blubb_nlog_blob_target_name 2023-06-30 10:57:50.2512 Debug Logger NLogLogger [Info] => _blubb_nlog_blob_target_name 2023-06-30 10:57:50.2512 Debug Logger NLogLogger [Warn] => _blubb_nlog_blob_target_name 2023-06-30 10:57:50.2512 Debug Logger NLogLogger [Error] => _blubb_nlog_blob_target_name 2023-06-30 10:57:50.2512 Debug Logger NLogLogger [Fatal] => _blubb_nlog_blob_target_name 2023-06-30 10:57:50.3356 Info AppDomain Shutting down. LogFactory closing... 2023-06-30 10:57:50.3387 Debug AzureBlobStorageTarget(Name=_blubb_nlog_blob_target_name): Flushing pending queue items 2023-06-30 10:57:50.6613 Debug Flush completed 2023-06-30 10:57:50.6613 Debug Targets not configured for Logger: NLogLogger 2023-06-30 10:57:50.6613 Debug Closing logging configuration... 2023-06-30 10:57:50.6613 Debug AzureBlobStorageTarget(Name=_blubb_nlog_blob_target_name): Closing... 2023-06-30 10:57:50.6613 Debug AzureBlobStorageTarget(Name=_blubb_nlog_blob_target_name): Closed. 2023-06-30 10:57:50.6613 Debug AsyncWrapper_ConsoleTarget(Name=_blubb_nlog_console_target_nameAsync): Closing... 2023-06-30 10:57:50.6613 Debug AsyncWrapper_ConsoleTarget(Name=_blubb_nlog_console_target_nameAsync): Closed. 2023-06-30 10:57:50.6613 Debug ConsoleTarget(Name=_blubb_nlog_console_target_name): Closing... 2023-06-30 10:57:50.6613 Debug ConsoleTarget(Name=_blubb_nlog_console_target_name): Closed. 2023-06-30 10:57:50.6613 Debug Finished closing logging configuration. 2023-06-30 10:57:50.6613 Info LogFactory has been closed.

Blob storage:

[snakefoot]

Maybe just missing flush. Ex. NLog.LogManager.Flush()

[sev-22]

I flush at the end of the code.

But when I flush after every log I get all messages so it seems like there is a flush issue. Any ideas on this behaviour?

            LogManager.Flush();
            log.Debug($"Debug msg at {DateTime.UtcNow:O}");
            LogManager.Flush();
            log.Info($"Info msg at {DateTime.UtcNow:O}");
            LogManager.Flush();
            log.Warn($"Warn msg at {DateTime.UtcNow:O}");
            LogManager.Flush();
            log.Error($"Error msg at {DateTime.UtcNow:O}");
            LogManager.Flush();

When I wrap the target into an AutoFlushTargetWrapper I get all entries too.

[snakefoot]

I'm guessing it is caused by the BlobStorageTarget only keeps track of the lastest blob-name.

So when changing to a new blob-name, then it fails to wait for flush to complete for any previous-blob-names.

Pull-request to improve on this are ofcourse wellcome.

[sev-22]

I got closer to the issue. The problem occurs when I log a more complex string that was produced by a function call.

logger.Info(GetMyString(p)) is resulting in an empty log. logger.Info(() => GetMyString(p)) is working and produces the expected log.

[sev-22]

It depends on the length of the string to log. In my case the limit is exactly at 639 chars.

If the message to log is 638 characters (or less), the log file will contain the message (like expected). If the message to log is 639 characters (or more), the log file stays empty.

Any ideas what could be the reason for this?

[snakefoot]

And no errors in the NLog InternalLogger, or output when doing doing explicit flush ?

[sev-22]

No Errors or Warnings in the internal log file.

[snakefoot]

I don't have any good ideas, besides using a debugger or contacting Microsoft-support.

It sounds really weird with such a limit, as it would make it hard to write Json-Documents that are new-line-delimited.