Add additional verbose logging

govert · govert · commit 6b46f19eff13 · 2017-10-03T21:28:41.000+02:00
diff --git a/Source/ExcelDna.IntelliSense/IntellisenseHelper.cs b/Source/ExcelDna.IntelliSense/IntellisenseHelper.cs
@@ -55,9 +55,11 @@ void Provider_Invalidate(object sender, EventArgs e)
         void RefreshProvider(object providerObj)
         {
             Debug.Assert(Thread.CurrentThread.ManagedThreadId == 1);
+            Logger.Provider.Verbose($"IntelliSenseHelper.RefreshProvider - Begin Refresh for {providerObj.GetType().Name}");
             IIntelliSenseProvider provider = (IIntelliSenseProvider)providerObj;
             provider.Refresh();
             UpdateDisplay(provider);
+            Logger.Provider.Verbose($"IntelliSenseHelper.RefreshProvider - End");
         }
 
         void UpdateDisplay(IIntelliSenseProvider provider)
diff --git a/Source/ExcelDna.IntelliSense/Providers/WorkbookIntelliSenseProvider.cs b/Source/ExcelDna.IntelliSense/Providers/WorkbookIntelliSenseProvider.cs
@@ -40,17 +40,20 @@ public void Refresh()
                 var wb = app.Workbooks[_name];
                 _path = wb.Path;
 
+                Logger.Provider.Verbose($"WorkbookRegistrationInfo.Refresh - Workbook {_name} at {_path}");
                 try
                 {
                     var ws = wb.Sheets[intelliSenseWorksheetName];
-
+                    Logger.Provider.Verbose($"WorkbookRegistrationInfo.Refresh - IntelliSense sheet found");
                     var info = ws.UsedRange.Value;
                     _regInfo = info as object[,];
+                    Logger.Provider.Verbose($"WorkbookRegistrationInfo.Refresh - Read {_regInfo.GetLength(0) - 1} registrations");
                 }
                 catch (Exception ex)
                 {
                     // We expect this if there is no sheet.
                     Debug.Print("WorkbookIntelliSenseProvider.Refresh Error : " + ex.Message);
+                    Logger.Provider.Verbose($"WorkbookRegistrationInfo.Refresh - No IntelliSense sheet found");
                     _regInfo = null;
                 }
                 _lastUpdate = DateTime.Now;
@@ -141,12 +144,15 @@ public void Initialize()
             xlApp.WorkbookBeforeClose += Excel_WorkbookBeforeClose;
             xlApp.WorkbookAddinInstall += Excel_WorkbookAddinInstall;
             xlApp.WorkbookAddinUninstall += Excel_WorkbookAddinUninstall;
+            Logger.Provider.Verbose("WorkbookIntelliSenseProvider.Initialize - Installed event listeners");
 
             lock (_workbookRegistrationInfos)
             {
+                Logger.Provider.Verbose("WorkbookIntelliSenseProvider.Initialize - Starting Workbooks loop");
                 foreach (Workbook wb in xlApp.Workbooks)
                 {
                     var name = wb.Name;
+                    Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.Initialize - Adding registration for {name}");
                     if (!_workbookRegistrationInfos.ContainsKey(name))
                     {
                         WorkbookRegistrationInfo regInfo = new WorkbookRegistrationInfo(name);
@@ -189,6 +195,8 @@ public void Initialize()
                 //    }
                 //}
 
+                Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.Initialize - Checking Add-Ins");
+
                 var loadedAddIns = Integration.XlCall.Excel(Integration.XlCall.xlfDocuments, 2) as object[,];
                 if (loadedAddIns == null)
                 {
@@ -199,6 +207,7 @@ public void Initialize()
                 for (int i = 0; i < loadedAddIns.GetLength(1); i++)
                 {
                     var addInName = loadedAddIns[0, i] as string;
+                    Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.Initialize - Checking Add-In {addInName}");
                     if (addInName != null && Path.GetExtension(addInName) != ".xll")    // We don't actually expect the .xll add-ins here - and they're taken care of elsewhere
                     {
                         // Can it be "Open" and not be loaded?
@@ -215,6 +224,8 @@ public void Initialize()
                             continue;
                         }
 
+                        Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.Initialize - Adding registration for add-in {name}");
+
                         WorkbookRegistrationInfo regInfo = new WorkbookRegistrationInfo(name);
                         _workbookRegistrationInfos[name] = regInfo;
 
@@ -330,16 +341,26 @@ void Excel_WorkbookAddinUninstall(Workbook wb)
 
         void RegisterWithXmlProvider(Workbook wb)
         {
+            Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.RegisterWithXmlProvider");
+
             var path = wb.FullName;
             var xmlPath = GetXmlPath(path);
             _xmlProvider.RegisterXmlFunctionInfo(xmlPath);  // Will check if file exists
 
+            Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.RegisterWithXmlProvider - Checking CustomXMLParts");
+
             var customXmlParts = wb.CustomXMLParts.SelectByNamespace(XmlIntelliSense.Namespace);
             if (customXmlParts.Count > 0)
             {
+                Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.RegisterWithXmlProvider - CustomXMLPart found");
                 // We just take the first one - register against the Bworkbook name
                 _xmlProvider.RegisterXmlFunctionInfo(path, customXmlParts[1].XML);
             }
+            else
+            {
+                Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.RegisterWithXmlProvider - No CustomXMLPart found");
+            }
+
         }
 
         void UnregisterWithXmlProvider(Workbook wb)
diff --git a/Source/ExcelDna.IntelliSense/Providers/XmlIntelliSenseProvider.cs b/Source/ExcelDna.IntelliSense/Providers/XmlIntelliSenseProvider.cs
@@ -3,6 +3,7 @@
 using System.IO;
 using System.Linq;
 using System.Text;
+using System.Threading;
 using System.Xml;
 using System.Xml.Serialization;
 using ExcelDna.Integration;
@@ -89,16 +90,22 @@ public XmlIntelliSenseProvider()
         public void RegisterXmlFunctionInfo(string fileName, string xmlIntelliSense = null)
         {
             if (!File.Exists(fileName) && xmlIntelliSense == null)
+            {
+                Logger.Provider.Verbose($"XmlIntelliSenseProvider.RegisterXmlFunctionInfo - Not IntelliSense file at {fileName}");
                 return;
+            }
             
             var regInfo = new XmlRegistrationInfo(fileName, xmlIntelliSense);
+            Logger.Provider.Verbose($"XmlIntelliSenseProvider.RegisterXmlFunctionInfo - Created XmlRegistrationInfo info for {fileName}");
             lock (_xmlRegistrationInfos)
             {
+                Logger.Provider.Verbose($"XmlIntelliSenseProvider.RegisterXmlFunctionInfo - Recording XmlRegistrationInfo info");
                 _xmlRegistrationInfos.Add(fileName, regInfo);
 
                 if (!_isDirty)
                 {
                     _isDirty = true;
+                    Logger.Provider.Verbose($"XmlIntelliSenseProvider.RegisterXmlFunctionInfo - Posting OnInvalidate to Excel SyncContext");
                     _syncContextExcel.Post(OnInvalidate, null);
                 }
             }
@@ -135,22 +142,25 @@ public void Refresh()
         // May be called from any thread
         public IList<FunctionInfo> GetFunctionInfos()
         {
+            Logger.Provider.Verbose($"XmlIntelliSenseProvider.GetFunctionInfos - Enter on Thread {Thread.CurrentThread.ManagedThreadId}");
+
             IList<FunctionInfo> functionInfos;
             lock (_xmlRegistrationInfos)
             {
                 functionInfos = _xmlRegistrationInfos.Values.SelectMany(ri => ri.GetFunctionInfos()).ToList();
             }
-            Logger.Provider.Verbose("XmlIntelliSenseProvider.GetFunctionInfos Begin");
+            Logger.Provider.Verbose("XmlIntelliSenseProvider.GetFunctionInfos - Begin");
             foreach (var info in functionInfos)
             {
                 Logger.Provider.Verbose($"\t{info.Name}({info.ArgumentList.Count}) - {info.Description} ");
             }
-            Logger.Provider.Verbose("XmlIntelliSenseProvider.GetFunctionInfos End");
+            Logger.Provider.Verbose("XmlIntelliSenseProvider.GetFunctionInfos - End");
             return functionInfos;
         }
         
         void OnInvalidate(object _unused_)
         {
+            Logger.Provider.Verbose($"XmlIntelliSenseProvider.ROnInvalidate - Invoking Invalidate event");
             Invalidate?.Invoke(this, EventArgs.Empty);
         }
 

Original file line number	Diff line number	Diff line change
`@@ -55,9 +55,11 @@ void Provider_Invalidate(object sender, EventArgs e)`
`55`	`55`	`void RefreshProvider(object providerObj)`
`56`	`56`	`{`
`57`	`57`	`Debug.Assert(Thread.CurrentThread.ManagedThreadId == 1);`
	`58`	`+ Logger.Provider.Verbose($"IntelliSenseHelper.RefreshProvider - Begin Refresh for {providerObj.GetType().Name}");`
`58`	`59`	`IIntelliSenseProvider provider = (IIntelliSenseProvider)providerObj;`
`59`	`60`	`provider.Refresh();`
`60`	`61`	`UpdateDisplay(provider);`
	`62`	`+ Logger.Provider.Verbose($"IntelliSenseHelper.RefreshProvider - End");`
`61`	`63`	`}`
`62`	`64`
`63`	`65`	`void UpdateDisplay(IIntelliSenseProvider provider)`
Original file line number	Diff line number	Diff line change
`@@ -40,17 +40,20 @@ public void Refresh()`
`40`	`40`	`var wb = app.Workbooks[_name];`
`41`	`41`	`_path = wb.Path;`
`42`	`42`
	`43`	`+ Logger.Provider.Verbose($"WorkbookRegistrationInfo.Refresh - Workbook {_name} at {_path}");`
`43`	`44`	`try`
`44`	`45`	`{`
`45`	`46`	`var ws = wb.Sheets[intelliSenseWorksheetName];`
`46`		`-`
	`47`	`+ Logger.Provider.Verbose($"WorkbookRegistrationInfo.Refresh - IntelliSense sheet found");`
`47`	`48`	`var info = ws.UsedRange.Value;`
`48`	`49`	`_regInfo = info as object[,];`
	`50`	`+ Logger.Provider.Verbose($"WorkbookRegistrationInfo.Refresh - Read {_regInfo.GetLength(0) - 1} registrations");`
`49`	`51`	`}`
`50`	`52`	`catch (Exception ex)`
`51`	`53`	`{`
`52`	`54`	`// We expect this if there is no sheet.`
`53`	`55`	`Debug.Print("WorkbookIntelliSenseProvider.Refresh Error : " + ex.Message);`
	`56`	`+ Logger.Provider.Verbose($"WorkbookRegistrationInfo.Refresh - No IntelliSense sheet found");`
`54`	`57`	`_regInfo = null;`
`55`	`58`	`}`
`56`	`59`	`_lastUpdate = DateTime.Now;`
`@@ -141,12 +144,15 @@ public void Initialize()`
`141`	`144`	`xlApp.WorkbookBeforeClose += Excel_WorkbookBeforeClose;`
`142`	`145`	`xlApp.WorkbookAddinInstall += Excel_WorkbookAddinInstall;`
`143`	`146`	`xlApp.WorkbookAddinUninstall += Excel_WorkbookAddinUninstall;`
	`147`	`+ Logger.Provider.Verbose("WorkbookIntelliSenseProvider.Initialize - Installed event listeners");`
`144`	`148`
`145`	`149`	`lock (_workbookRegistrationInfos)`
`146`	`150`	`{`
	`151`	`+ Logger.Provider.Verbose("WorkbookIntelliSenseProvider.Initialize - Starting Workbooks loop");`
`147`	`152`	`foreach (Workbook wb in xlApp.Workbooks)`
`148`	`153`	`{`
`149`	`154`	`var name = wb.Name;`
	`155`	`+ Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.Initialize - Adding registration for {name}");`
`150`	`156`	`if (!_workbookRegistrationInfos.ContainsKey(name))`
`151`	`157`	`{`
`152`	`158`	`WorkbookRegistrationInfo regInfo = new WorkbookRegistrationInfo(name);`
`@@ -189,6 +195,8 @@ public void Initialize()`
`189`	`195`	`// }`
`190`	`196`	`//}`
`191`	`197`
	`198`	`+ Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.Initialize - Checking Add-Ins");`
	`199`	`+`
`192`	`200`	`var loadedAddIns = Integration.XlCall.Excel(Integration.XlCall.xlfDocuments, 2) as object[,];`
`193`	`201`	`if (loadedAddIns == null)`
`194`	`202`	`{`
`@@ -199,6 +207,7 @@ public void Initialize()`
`199`	`207`	`for (int i = 0; i < loadedAddIns.GetLength(1); i++)`
`200`	`208`	`{`
`201`	`209`	`var addInName = loadedAddIns[0, i] as string;`
	`210`	`+ Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.Initialize - Checking Add-In {addInName}");`
`202`	`211`	`if (addInName != null && Path.GetExtension(addInName) != ".xll") // We don't actually expect the .xll add-ins here - and they're taken care of elsewhere`
`203`	`212`	`{`
`204`	`213`	`// Can it be "Open" and not be loaded?`
`@@ -215,6 +224,8 @@ public void Initialize()`
`215`	`224`	`continue;`
`216`	`225`	`}`
`217`	`226`
	`227`	`+ Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.Initialize - Adding registration for add-in {name}");`
	`228`	`+`
`218`	`229`	`WorkbookRegistrationInfo regInfo = new WorkbookRegistrationInfo(name);`
`219`	`230`	`_workbookRegistrationInfos[name] = regInfo;`
`220`	`231`
`@@ -330,16 +341,26 @@ void Excel_WorkbookAddinUninstall(Workbook wb)`
`330`	`341`
`331`	`342`	`void RegisterWithXmlProvider(Workbook wb)`
`332`	`343`	`{`
	`344`	`+ Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.RegisterWithXmlProvider");`
	`345`	`+`
`333`	`346`	`var path = wb.FullName;`
`334`	`347`	`var xmlPath = GetXmlPath(path);`
`335`	`348`	`_xmlProvider.RegisterXmlFunctionInfo(xmlPath); // Will check if file exists`
`336`	`349`
	`350`	`+ Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.RegisterWithXmlProvider - Checking CustomXMLParts");`
	`351`	`+`
`337`	`352`	`var customXmlParts = wb.CustomXMLParts.SelectByNamespace(XmlIntelliSense.Namespace);`
`338`	`353`	`if (customXmlParts.Count > 0)`
`339`	`354`	`{`
	`355`	`+ Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.RegisterWithXmlProvider - CustomXMLPart found");`
`340`	`356`	`// We just take the first one - register against the Bworkbook name`
`341`	`357`	`_xmlProvider.RegisterXmlFunctionInfo(path, customXmlParts[1].XML);`
`342`	`358`	`}`
	`359`	`+ else`
	`360`	`+ {`
	`361`	`+ Logger.Provider.Verbose($"WorkbookIntelliSenseProvider.RegisterWithXmlProvider - No CustomXMLPart found");`
	`362`	`+ }`
	`363`	`+`
`343`	`364`	`}`
`344`	`365`
`345`	`366`	`void UnregisterWithXmlProvider(Workbook wb)`
Original file line number	Diff line number	Diff line change
`@@ -3,6 +3,7 @@`
`3`	`3`	`using System.IO;`
`4`	`4`	`using System.Linq;`
`5`	`5`	`using System.Text;`
	`6`	`+using System.Threading;`
`6`	`7`	`using System.Xml;`
`7`	`8`	`using System.Xml.Serialization;`
`8`	`9`	`using ExcelDna.Integration;`
`@@ -89,16 +90,22 @@ public XmlIntelliSenseProvider()`
`89`	`90`	`public void RegisterXmlFunctionInfo(string fileName, string xmlIntelliSense = null)`
`90`	`91`	`{`
`91`	`92`	`if (!File.Exists(fileName) && xmlIntelliSense == null)`
	`93`	`+ {`
	`94`	`+ Logger.Provider.Verbose($"XmlIntelliSenseProvider.RegisterXmlFunctionInfo - Not IntelliSense file at {fileName}");`
`92`	`95`	`return;`
	`96`	`+ }`
`93`	`97`
`94`	`98`	`var regInfo = new XmlRegistrationInfo(fileName, xmlIntelliSense);`
	`99`	`+ Logger.Provider.Verbose($"XmlIntelliSenseProvider.RegisterXmlFunctionInfo - Created XmlRegistrationInfo info for {fileName}");`
`95`	`100`	`lock (_xmlRegistrationInfos)`
`96`	`101`	`{`
	`102`	`+ Logger.Provider.Verbose($"XmlIntelliSenseProvider.RegisterXmlFunctionInfo - Recording XmlRegistrationInfo info");`
`97`	`103`	`_xmlRegistrationInfos.Add(fileName, regInfo);`
`98`	`104`
`99`	`105`	`if (!_isDirty)`
`100`	`106`	`{`
`101`	`107`	`_isDirty = true;`
	`108`	`+ Logger.Provider.Verbose($"XmlIntelliSenseProvider.RegisterXmlFunctionInfo - Posting OnInvalidate to Excel SyncContext");`
`102`	`109`	`_syncContextExcel.Post(OnInvalidate, null);`
`103`	`110`	`}`
`104`	`111`	`}`
`@@ -135,22 +142,25 @@ public void Refresh()`
`135`	`142`	`// May be called from any thread`
`136`	`143`	`public IList<FunctionInfo> GetFunctionInfos()`
`137`	`144`	`{`
	`145`	`+ Logger.Provider.Verbose($"XmlIntelliSenseProvider.GetFunctionInfos - Enter on Thread {Thread.CurrentThread.ManagedThreadId}");`
	`146`	`+`
`138`	`147`	`IList<FunctionInfo> functionInfos;`
`139`	`148`	`lock (_xmlRegistrationInfos)`
`140`	`149`	`{`
`141`	`150`	`functionInfos = _xmlRegistrationInfos.Values.SelectMany(ri => ri.GetFunctionInfos()).ToList();`
`142`	`151`	`}`
`143`		`- Logger.Provider.Verbose("XmlIntelliSenseProvider.GetFunctionInfos Begin");`
	`152`	`+ Logger.Provider.Verbose("XmlIntelliSenseProvider.GetFunctionInfos - Begin");`
`144`	`153`	`foreach (var info in functionInfos)`
`145`	`154`	`{`
`146`	`155`	`Logger.Provider.Verbose($"\t{info.Name}({info.ArgumentList.Count}) - {info.Description} ");`
`147`	`156`	`}`
`148`		`- Logger.Provider.Verbose("XmlIntelliSenseProvider.GetFunctionInfos End");`
	`157`	`+ Logger.Provider.Verbose("XmlIntelliSenseProvider.GetFunctionInfos - End");`
`149`	`158`	`return functionInfos;`
`150`	`159`	`}`
`151`	`160`
`152`	`161`	`void OnInvalidate(object _unused_)`
`153`	`162`	`{`
	`163`	`+ Logger.Provider.Verbose($"XmlIntelliSenseProvider.ROnInvalidate - Invoking Invalidate event");`
`154`	`164`	`Invalidate?.Invoke(this, EventArgs.Empty);`
`155`	`165`	`}`
`156`	`166`