fixing log messages for L2 (#1070)

* fix log to log 0 for empty cache

* add milliseconds instead of ticks

* fix msal verbose log

* use debug instead of trace

Author: jennyf19

src/Microsoft.Identity.Web/TokenAcquisition.cs

@@ -759,7 +759,7 @@ private void Log(
                     _logger.LogInformation(message);
                     break;
                 case Client.LogLevel.Verbose:
-                    _logger.LogInformation(message);
+                    _logger.LogDebug(message);
                     break;
                 default:
                     break;

src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapter.cs

@@ -90,7 +90,7 @@ protected override async Task<byte[]> ReadCacheBytesAsync(string cacheKey)
         {
             // check memory cache first
             byte[]? result = (byte[])_memoryCache.Get(cacheKey);
-            _logger.LogDebug($"[MsIdWeb] MemoryCache: Read {cacheKey} cache size: {result?.Length}. ");
+            _logger.LogDebug($"[MsIdWeb] MemoryCache: Read {cacheKey} cache size: {result?.Length ?? 0}. ");
 
             if (result == null)
             {
@@ -103,7 +103,7 @@ protected override async Task<byte[]> ReadCacheBytesAsync(string cacheKey)
                         cacheKey).ConfigureAwait(false);
                 }).Measure().ConfigureAwait(false);
 
-                _logger.LogDebug($"[MsIdWeb] DistributedCache: Read time in Ticks: {measure.Ticks}");
+                _logger.LogDebug($"[MsIdWeb] DistributedCache: Read time in MilliSeconds: {measure.MilliSeconds}. ");
 
                 // back propagate to memory cache
                 if (result != null)
@@ -114,9 +114,9 @@ protected override async Task<byte[]> ReadCacheBytesAsync(string cacheKey)
                         Size = result?.Length,
                     };
 
-                    _logger.LogDebug($"[MsIdWeb] Back propagate from Distributed to Memory, cache size: {result?.Length}");
+                    _logger.LogDebug($"[MsIdWeb] Back propagate from Distributed to Memory, cache size: {result?.Length ?? 0}. ");
                     _memoryCache.Set(cacheKey, result, memoryCacheEntryOptions);
-                    _logger.LogDebug($"[MsIdWeb] MemoryCache: Count: {_memoryCache.Count}");
+                    _logger.LogDebug($"[MsIdWeb] MemoryCache: Count: {_memoryCache.Count}. ");
                 }
             }
             else
@@ -148,10 +148,10 @@ protected override async Task WriteCacheBytesAsync(string cacheKey, byte[] bytes
 
             // write in both
             _memoryCache.Set(cacheKey, bytes, memoryCacheEntryOptions);
-            _logger.LogDebug($"[MsIdWeb] MemoryCache: Write cacheKey {cacheKey} cache size: {bytes?.Length}. ");
-            _logger.LogDebug($"[MsIdWeb] MemoryCache: Count: {_memoryCache.Count}");
+            _logger.LogDebug($"[MsIdWeb] MemoryCache: Write cacheKey {cacheKey} cache size: {bytes?.Length ?? 0}. ");
+            _logger.LogDebug($"[MsIdWeb] MemoryCache: Count: {_memoryCache.Count}. ");
 
-            var measure = await L2OperationWithRetryOnFailureAsync(
+            await L2OperationWithRetryOnFailureAsync(
                 "Write",
                 (cacheKey) => _distributedCache.SetAsync(cacheKey, bytes, _distributedCacheOptions),
                 cacheKey).Measure().ConfigureAwait(false);
@@ -167,11 +167,11 @@ private async Task L2OperationWithRetryOnFailureAsync(
             try
             {
                 var measure = await cacheOperation(cacheKey).Measure().ConfigureAwait(false);
-                _logger.LogDebug($"[MsIdWeb] DistributedCache: {operation} cacheKey {cacheKey} cache size {bytes?.Length} InRetry? {inRetry} Time in Ticks: {measure.Ticks}. ");
+                _logger.LogDebug($"[MsIdWeb] DistributedCache: {operation} cacheKey {cacheKey} cache size {bytes?.Length ?? 0} InRetry? {inRetry} Time in MilliSeconds: {measure.MilliSeconds}. ");
             }
             catch (Exception ex)
             {
-                _logger.LogError($"[MsIdWeb] DistributedCache: Connection issue. InRetry? {inRetry} Error message: {ex.Message} ");
+                _logger.LogError($"[MsIdWeb] DistributedCache: Connection issue. InRetry? {inRetry} Error message: {ex.Message}. ");
 
                 if (_distributedCacheOptions.OnL2CacheFailure != null && _distributedCacheOptions.OnL2CacheFailure(ex) && !inRetry)
                 {
@@ -196,11 +196,11 @@ await L2OperationWithRetryOnFailureAsync(
             try
             {
                 result = await cacheOperation(cacheKey).ConfigureAwait(false);
-                _logger.LogDebug($"[MsIdWeb] DistributedCache: {operation} cacheKey {cacheKey} cache size {result?.Length} InRetry? {inRetry}. ");
+                _logger.LogDebug($"[MsIdWeb] DistributedCache: {operation} cacheKey {cacheKey} cache size {result?.Length ?? 0} InRetry? {inRetry}. ");
             }
             catch (Exception ex)
             {
-                _logger.LogError($"[MsIdWeb] DistributedCache: Connection issue. InRetry? {inRetry} Error message: {ex.Message} ");
+                _logger.LogError($"[MsIdWeb] DistributedCache: Connection issue. InRetry? {inRetry} Error message: {ex.Message}. ");
 
                 if (_distributedCacheOptions.OnL2CacheFailure != null && _distributedCacheOptions.OnL2CacheFailure(ex) && !inRetry)
                 {

src/Microsoft.Identity.Web/TokenCacheProviders/MeasureDurationResult.cs

@@ -1,6 +1,8 @@
 // Copyright (c) Microsoft Corporation. All rights reserved.
 // Licensed under the MIT License.
 
+using System.Diagnostics;
+
 namespace Microsoft.Identity.Web.TokenCacheProviders
 {
     internal struct MeasureDurationResult
@@ -11,6 +13,14 @@ public MeasureDurationResult(long ticks)
         }
 
         public long Ticks { get; }
+
+        public double MilliSeconds
+        {
+            get
+            {
+                return (double)Ticks / (double)Stopwatch.Frequency * 1000.0;
+            }
+        }
     }
 
     internal struct MeasureDurationResult<TResult>

tests/Microsoft.Identity.Web.Test/UtilityTests.cs

@@ -18,6 +18,7 @@ public async Task Measurements_Tests()
             var epsilon = TimeSpan.FromMilliseconds(30).Ticks;
             var measure = await Task.Delay(taskDuration).Measure().ConfigureAwait(false);
             Assert.True(Math.Abs(measure.Ticks - taskDuration.Ticks) < epsilon, $"{(measure.Ticks - taskDuration.Ticks) / TimeSpan.TicksPerMillisecond}ms exceeds epsilon of 30ms");
+            Assert.Equal(measure.Ticks * 1000.0, measure.MilliSeconds);
 
             // measure task with a result
             var test = "test";