Additional logging to diagnose bultins issue (microsoft#1720)

* Remove stale reference

* More logging

Author: Mikhail Arkhipov

src/Analysis/Ast/Impl/Caching/StubCache.cs

@@ -110,7 +110,7 @@ public void WriteCachedModule(string filePath, string code) {
             if (!string.IsNullOrEmpty(cache)) {
                 _log?.Log(TraceEventType.Verbose, "Writing cached module: ", cache);
                 // Don't block analysis on cache writes.
-                CacheWritingTask = Task.Run(() => _fs.WriteTextWithRetry(cache, code));
+                CacheWritingTask = Task.Run(() => _fs.WriteTextWithRetry(cache, code, _log));
                 CacheWritingTask.DoNotWait();
             }
         }

src/Analysis/Ast/Impl/Modules/BuiltinsPythonModule.cs

@@ -15,12 +15,14 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using Microsoft.Python.Analysis.Specializations;
 using Microsoft.Python.Analysis.Types;
 using Microsoft.Python.Analysis.Values;
 using Microsoft.Python.Core;
 using Microsoft.Python.Core.IO;
+using Microsoft.Python.Core.Logging;
 using Microsoft.Python.Parsing;
 using Microsoft.Python.Parsing.Ast;
 
@@ -52,10 +54,19 @@ protected override void OnAnalysisComplete() {
             foreach (var n in GetMemberNames()) {
                 GetMember(n).GetPythonType<PythonType>()?.MakeReadOnly();
             }
-
             base.OnAnalysisComplete();
         }
 
+        protected override string LoadContent() {
+            var content = base.LoadContent();
+            if (string.IsNullOrEmpty(content)) {
+                const string message = "Unable continue, no builtins module content.";
+                Services.GetService<ILogger>()?.Log(TraceEventType.Error, message);
+                throw new InvalidOperationException(message);
+            }
+            return content;
+        }
+
         private void SpecializeTypes() {
             var isV3 = Interpreter.LanguageVersion.Is3x();
 

src/Analysis/Ast/Impl/Modules/CompiledPythonModule.cs

@@ -100,7 +100,9 @@ private string ScrapeModule() {
 
                     output = process.StandardOutput.ReadToEnd();
                 }
-            } catch (Exception ex) when (!ex.IsCriticalException()) { }
+            } catch (Exception ex) when (!ex.IsCriticalException()) {
+                Log?.Log(TraceEventType.Verbose, "Exception scraping module", Name, ex.Message);
+            }
 
             return output;
         }

src/Analysis/Ast/Impl/Modules/Resolution/MainModuleResolution.cs

@@ -164,11 +164,11 @@ public IPythonModule GetSpecializedModule(string fullName, bool allowCreation =
         public bool IsSpecializedModule(string fullName, string modulePath = null)
             => _specialized.ContainsKey(fullName);
 
-        internal async Task AddBuiltinTypesToPathResolverAsync(CancellationToken cancellationToken = default) {
+        private async Task AddBuiltinTypesToPathResolverAsync(CancellationToken cancellationToken = default) {
             var analyzer = Services.GetService<IPythonAnalyzer>();
-            await analyzer.GetAnalysisAsync(BuiltinsModule, -1, cancellationToken);
+            await analyzer.GetAnalysisAsync(BuiltinsModule, Timeout.Infinite, cancellationToken);
 
-            Check.InvalidOperation(!(BuiltinsModule.Analysis is EmptyAnalysis), "After await");
+            Check.InvalidOperation(!(BuiltinsModule.Analysis is EmptyAnalysis), "Builtins analysis did not complete correctly.");
 
             // Add built-in module names
             var builtinModuleNamesMember = BuiltinsModule.GetAnyMember("__builtin_module_names__");

src/Core/Impl/Extensions/IOExtensions.cs

@@ -14,10 +14,12 @@
 // permissions and limitations under the License.
 
 using System;
+using System.Diagnostics;
 using System.IO;
 using System.Linq;
 using System.Text;
 using System.Threading;
+using Microsoft.Python.Core.Logging;
 
 namespace Microsoft.Python.Core.IO {
     public static class IOExtensions {
@@ -79,7 +81,7 @@ public static bool DeleteDirectoryWithRetries(this IFileSystem fs, string path,
             return !fs.DirectoryExists(path);
         }
 
-        public static FileStream OpenWithRetry(this IFileSystem fs, string file, FileMode mode, FileAccess access, FileShare share) {
+        public static FileStream OpenWithRetry(this IFileSystem fs, string file, FileMode mode, FileAccess access, FileShare share, ILogger log = null) {
             // Retry for up to one second
             var create = mode != FileMode.Open;
             for (var retries = 100; retries > 0; --retries) {
@@ -89,20 +91,23 @@ public static FileStream OpenWithRetry(this IFileSystem fs, string file, FileMod
                     return null;
                 } catch (DirectoryNotFoundException) when (!create) {
                     return null;
-                } catch (UnauthorizedAccessException) {
+                } catch (UnauthorizedAccessException uaex) {
+                    log?.Log(TraceEventType.Verbose, "Unable to open file ", file, uaex.Message);
                     Thread.Sleep(10);
                 } catch (IOException) {
                     if (create) {
                         var dir = Path.GetDirectoryName(file);
                         try {
                             fs.CreateDirectory(dir);
-                        } catch (IOException) {
-                            // Cannot create directory for DB, so just bail out
-                            return null;
+                        } catch (IOException ioex) {
+                            log?.Log(TraceEventType.Verbose, "Unable to create directory ", dir, ioex.Message);
+                            Thread.Sleep(10);
                         }
+                    } else {
+                        Thread.Sleep(10);
                     }
-                    Thread.Sleep(10);
-                } catch (NotSupportedException) {
+                } catch (NotSupportedException nsx) {
+                    log?.Log(TraceEventType.Verbose, "Unable to open file ", file, nsx.Message);
                     return null;
                 }
             }
@@ -121,21 +126,27 @@ public static string ReadTextWithRetry(this IFileSystem fs, string file) {
             return null;
         }
 
-        public static void WriteTextWithRetry(this IFileSystem fs, string filePath, string text) {
+        public static void WriteTextWithRetry(this IFileSystem fs, string filePath, string text, ILogger log = null) {
+            Exception ex = null;
             for (var retries = 100; retries > 0; --retries) {
                 try {
-                    using (var stream = fs.OpenWithRetry(filePath, FileMode.Create, FileAccess.Write, FileShare.Read)) {
+                    using (var stream = fs.OpenWithRetry(filePath, FileMode.Create, FileAccess.Write, FileShare.Read, log)) {
                         if (stream != null) {
                             var bytes = Encoding.UTF8.GetBytes(text);
                             stream.Write(bytes, 0, bytes.Length);
                             return;
                         }
                     }
-                } catch (IOException) { } catch (UnauthorizedAccessException) {
-                    Thread.Sleep(10);
+                } catch (IOException ioex) {
+                    ex = ioex;
+                } catch (UnauthorizedAccessException uaex) {
+                    ex = uaex;
                 }
+                Thread.Sleep(10);
             }
 
+            log?.Log(TraceEventType.Verbose, "Unable to write to ", filePath, ex?.Message ?? "Unknown exception");
+
             try {
                 fs.DeleteFile(filePath);
             } catch (IOException) { } catch (UnauthorizedAccessException) { }