Add logging to semantic tokens (#6118)

* Add logging to semantic tokens

* Review feedback

src/Razor/src/Microsoft.AspNetCore.Razor.LanguageServer/Semantic/SemanticTokensCache.cs

@@ -1,13 +1,13 @@
 // Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the MIT license. See License.txt in the project root for license information.
 
-using System;
 using System.Collections.Generic;
 using System.Collections.Immutable;
 using System.Diagnostics.CodeAnalysis;
 using System.Linq;
 using Microsoft.CodeAnalysis;
 using Microsoft.CodeAnalysis.Razor;
+using Microsoft.Extensions.Logging;
 using OmniSharp.Extensions.LanguageServer.Protocol;
 using OmniSharp.Extensions.LanguageServer.Protocol.Models;
 
@@ -84,6 +84,7 @@ public void CacheTokens(
         /// <param name="uri">The URI associated with the cached tokens.</param>
         /// <param name="semanticVersion">The semantic version associated with the cached tokens.</param>
         /// <param name="requestedRange">The requested range for the desired tokens.</param>
+        /// <param name="logger">Optional logger to record outcome of cache lookup.</param>
         /// <param name="cachedTokens">If found, contains the cached range and cached tokens.</param>
         /// <returns>
         /// True if at least a partial match for the range was found. The 'Range' out var specifies the subset of
@@ -94,6 +95,7 @@ public bool TryGetCachedTokens(
             DocumentUri uri,
             VersionStamp semanticVersion,
             Range requestedRange,
+            ILogger? logger,
             [NotNullWhen(true)] out (Range Range, ImmutableArray<int> Tokens)? cachedTokens)
         {
             // Don't return results for partial lines, we don't handle them currently due to
@@ -107,6 +109,11 @@ public bool TryGetCachedTokens(
             if (!_cache.TryGetValue(uri, out var documentCache) ||
                 !documentCache.TryGetValue(semanticVersion, out var lineToTokensDict))
             {
+                if (logger is not null)
+                {
+                    logger.LogInformation($"No cached results found for range: {requestedRange}");
+                }
+
                 // No cached results found
                 cachedTokens = null;
                 return false;
@@ -115,6 +122,11 @@ public bool TryGetCachedTokens(
             var tokens = GetCachedTokens(requestedRange, lineToTokensDict, out var cachedRangeStart, out var numLinesInCachedRange);
             if (tokens.Length == 0)
             {
+                if (logger is not null)
+                {
+                    logger.LogInformation($"No cached results found for range: {requestedRange}");
+                }
+
                 // We couldn't find any tokens associated with the passed-in range
                 cachedTokens = null;
                 return false;
@@ -134,7 +146,8 @@ public bool TryGetCachedTokens(
         /// Given the tokens, place them in the lineToTokensDict according to the line they belong on.
         /// </summary>
         /// <param name="range">The range within the document that these tokens represent.</param>
-        /// <param name="tokens">The tokens for the document within the given range. line count begins at the begining of the document regardless of the area the range represents</param>
+        /// <param name="tokens">The tokens for the document within the given range.
+        /// Line count begins at the begining of the document regardless of the area the range represents.</param>
         /// <param name="lineToTokensDict">A dictionary onto which to add tokens.</param>
         private void CacheTokensPerLine(Range range, int[] tokens, Dictionary<int, ImmutableArray<int>> lineToTokensDict)
         {

src/Razor/src/Microsoft.AspNetCore.Razor.LanguageServer/Semantic/Services/DefaultRazorSemanticTokensInfoService.cs

@@ -92,7 +92,7 @@ public DefaultRazorSemanticTokensInfoService(
             var semanticVersion = await GetDocumentSemanticVersionAsync(documentSnapshot).ConfigureAwait(false);
 
             // See if we can use our cache to at least partially avoid recomputation.
-            if (!_tokensCache.TryGetCachedTokens(textDocumentIdentifier.Uri, semanticVersion, range, out var cachedResult))
+            if (!_tokensCache.TryGetCachedTokens(textDocumentIdentifier.Uri, semanticVersion, range, _logger, out var cachedResult))
             {
                 // No cache results found, so we'll recompute tokens for the entire range and then hopefully cache the
                 // results to use next time around.
@@ -347,6 +347,7 @@ private static async Task<VersionStamp> GetDocumentSemanticVersionAsync(Document
             // We return null (which to the LSP is a no-op) to prevent flashing of CSharp elements.
             if (combinedSemanticRanges is null)
             {
+                _logger.LogWarning("Incomplete view of document. C# may be ahead of us in document versions.");
                 return null;
             }
 
@@ -421,6 +422,7 @@ internal virtual async Task<SemanticRangeResponse> GetCSharpSemanticRangesAsync(
             // Unrecoverable, return default to indicate no change. It will retry in a bit.
             if (csharpResponse is null)
             {
+                _logger.LogWarning($"Issue with retrieving C# response for Razor range: {razorRange}");
                 return SemanticRangeResponse.Default;
             }
 

src/Razor/test/Microsoft.AspNetCore.Razor.LanguageServer.Test/Semantic/SemanticTokensCacheTest.cs

@@ -31,7 +31,7 @@ public void TryGetCachedTokens_ReturnsStoredResults()
         semanticTokensCache.CacheTokens(uri, semanticVersion, requestedRange, tokens);
 
         // Act
-        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, requestedRange, out var cachedResult))
+        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, requestedRange, logger: null, out var cachedResult))
         {
             Assert.True(false, "Cached Tokens were not found");
             throw new NotImplementedException();
@@ -59,7 +59,7 @@ public void TryGetCachedTokens_OmitBegining()
         semanticTokensCache.CacheTokens(uri, semanticVersion, requestedRange, tokens);
 
         // Act
-        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, new Range(startLine: 2, startCharacter: 0, endLine: 8, endCharacter: 0), out var cachedResult))
+        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, new Range(startLine: 2, startCharacter: 0, endLine: 8, endCharacter: 0), logger: null, out var cachedResult))
         {
             Assert.True(false, "Cached Tokens were not found");
             throw new NotImplementedException();
@@ -90,7 +90,7 @@ public void TryGetCachedTokens_OmitEnding()
         semanticTokensCache.CacheTokens(uri, semanticVersion, requestedRange, tokens);
 
         // Act
-        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, requestedRange, out var cachedResult))
+        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, requestedRange, logger: null, out var cachedResult))
         {
             Assert.True(false, "Cached Tokens were not found");
             throw new NotImplementedException();
@@ -111,7 +111,7 @@ public void TryGetCachedTokens_WhenBeginingMissing()
         semanticTokensCache.CacheTokens(uri, semanticVersion, new Range(startLine: 4, startCharacter: 0, endLine: 5, endCharacter: 0), new int[] { 4, 5, 6, 7, 0, });
 
         // Act
-        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, new Range(startLine: 0, startCharacter: 0, endLine: 9, endCharacter: 0), out var cachedResult))
+        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, new Range(startLine: 0, startCharacter: 0, endLine: 9, endCharacter: 0), logger: null, out var cachedResult))
         {
             Assert.True(false, "Cached Tokens were not found");
             throw new NotImplementedException();
@@ -134,7 +134,7 @@ public void TryGetCachedTokens_PastEndOfFile()
         semanticTokensCache.CacheTokens(uri, semanticVersion, new Range(startLine: 4, startCharacter: 0, endLine: 4, endCharacter: 20), new int[] { 4, 5, 6, 7, 0, });
 
         // Act
-        if (semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, new Range(startLine: 6, startCharacter: 0, endLine: 8, endCharacter: 20), out var _))
+        if (semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, new Range(startLine: 6, startCharacter: 0, endLine: 8, endCharacter: 20), logger: null, out var _))
         {
             Assert.True(false, "Cached Tokens were found but should not have been.");
             throw new NotImplementedException();
@@ -163,7 +163,7 @@ public void TryGetCachedTokens_MultipleNonContiguousMissingLines()
         semanticTokensCache.CacheTokens(uri, semanticVersion, new Range(startLine: 4, startCharacter: 0, endLine: 5, endCharacter: 0), new int[] { 4, 5, 6, 7, 0, });
 
         // Act
-        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, new Range(startLine: 0, startCharacter: 0, endLine: 9, endCharacter: 0), out var cachedResult))
+        if (!semanticTokensCache.TryGetCachedTokens(uri, semanticVersion, new Range(startLine: 0, startCharacter: 0, endLine: 9, endCharacter: 0), logger: null, out var cachedResult))
         {
             Assert.True(false, "Cached Tokens were not found");
             throw new NotImplementedException();