Add OE verbose logging (#1484)

* Add OE verbose logging

* verbose

src/Microsoft.SqlTools.Hosting/Hosting/IHostedService.cs

@@ -4,7 +4,6 @@
 //
 
 using System;
-using System.Diagnostics;
 using System.Threading.Tasks;
 using Microsoft.SqlTools.Extensibility;
 using Microsoft.SqlTools.Hosting.Protocol;
@@ -70,7 +69,7 @@ namespace Microsoft.SqlTools.Hosting
 
         protected async Task<THandler> HandleRequestAsync<THandler>(Func<Task<THandler>> handler, RequestContext<THandler> requestContext, string requestType)
         {
-            Logger.Write(TraceEventType.Verbose, requestType);
+            Logger.Verbose($"Handling request type {requestType}");
 
             try
             {

src/Microsoft.SqlTools.Hosting/Utility/Logger.cs

@@ -239,6 +239,36 @@ namespace Microsoft.SqlTools.Utility
         /// <param name="logMessage">The message text to be written.</param>
         public static void Write(TraceEventType eventType, string logMessage) => Write(eventType, LogEvent.Default, logMessage);
 
+        /// <summary>
+        /// Writes a message to the log file with the Verbose event level
+        /// </summary>
+        /// <param name="logMessage">The message text to be written.</param>
+        public static void Verbose(string logMessage) => Write(TraceEventType.Verbose, logMessage);
+
+        /// <summary>
+        /// Writes a message to the log file with the Information event level
+        /// </summary>
+        /// <param name="logMessage">The message text to be written.</param>
+        public static void Information(string logMessage) => Write(TraceEventType.Information, logMessage);
+
+        /// <summary>
+        /// Writes a message to the log file with the Warning event level
+        /// </summary>
+        /// <param name="logMessage">The message text to be written.</param>
+        public static void Warning(string logMessage) => Write(TraceEventType.Warning, logMessage);
+
+        /// <summary>
+        /// Writes a message to the log file with the Error event level
+        /// </summary>
+        /// <param name="logMessage">The message text to be written.</param>
+        public static void Error(string logMessage) => Write(TraceEventType.Error, logMessage);
+
+        /// <summary>
+        /// Writes a message to the log file with the Critical event level
+        /// </summary>
+        /// <param name="logMessage">The message text to be written.</param>
+        public static void Critical(string logMessage) => Write(TraceEventType.Critical, logMessage);
+
         /// <summary>
         /// Writes a message to the log file with accompanying callstack.
         /// </summary>

src/Microsoft.SqlTools.ServiceLayer/ObjectExplorer/Nodes/TreeNode.cs

@@ -343,7 +343,9 @@ namespace Microsoft.SqlTools.ServiceLayer.ObjectExplorer.Nodes
                         cancellationToken.ThrowIfCancellationRequested();
                         try
                         {
+                            Logger.Verbose($"Begin populate children for {this.GetNodePath()} using {factory.GetType()} factory");
                             IEnumerable<TreeNode> items = factory.Expand(this, refresh, name, includeSystemObjects, cancellationToken);
+                            Logger.Verbose($"End populate children for {this.GetNodePath()} using {factory.GetType()} factory");
                             if (items != null)
                             {
                                 foreach (TreeNode item in items)

src/Microsoft.SqlTools.ServiceLayer/ObjectExplorer/ObjectExplorerService.cs

@@ -401,17 +401,20 @@ namespace Microsoft.SqlTools.ServiceLayer.ObjectExplorer
             // since we don't need to add any nodes under this section of the tree.
             if (node == null)
             {
+                Logger.Verbose($"No node returned from FindNodeByPath for {nodePath}");
                 response = new ExpandResponse { Nodes = new NodeInfo[] { }, ErrorMessage = string.Empty, SessionId = session.Uri, NodePath = nodePath };
                 response.Nodes = new NodeInfo[0];
                 return response;
             }
             else
             {
+                Logger.Verbose($"Got node from FindNodeByPath for {nodePath}");
                 response = new ExpandResponse { Nodes = new NodeInfo[] { }, ErrorMessage = node.ErrorMessage, SessionId = session.Uri, NodePath = nodePath };
             }
-
+            Logger.Verbose($"Before enter BuildingMetadataLock for {nodePath}");
             if (node != null && Monitor.TryEnter(node.BuildingMetadataLock, LanguageService.OnConnectionWaitTimeout))
             {
+                Logger.Verbose($"After enter BuildingMetadataLock for {nodePath}");
                 try
                 {
                     int timeout = (int)TimeSpan.FromSeconds(settings?.ExpandTimeout ?? ObjectExplorerSettings.DefaultExpandTimeout).TotalMilliseconds;
@@ -423,10 +426,12 @@ namespace Microsoft.SqlTools.ServiceLayer.ObjectExplorer
                            {
                                if (forceRefresh)
                                {
+                                   Logger.Verbose($"Forcing refresh for {nodePath}");
                                    nodes = node.Refresh(cancelToken).Select(x => x.ToNodeInfo()).ToArray();
                                }
                                else
                                {
+                                   Logger.Verbose($"Expanding {nodePath}");
                                    nodes = node.Expand(cancelToken).Select(x => x.ToNodeInfo()).ToArray();
                                }
                                response.Nodes = nodes;
@@ -446,8 +451,9 @@ namespace Microsoft.SqlTools.ServiceLayer.ObjectExplorer
                                }
                                return response;
                            });
-
+                    Logger.Verbose($"Queuing binding operation for {nodePath}");
                     queueItem.ItemProcessed.WaitOne();
+                    Logger.Verbose($"Done with binding operation for {nodePath}");
                     if (queueItem.GetResultAsT<ExpandResponse>() != null)
                     {
                         response = queueItem.GetResultAsT<ExpandResponse>();

src/Microsoft.SqlTools.ServiceLayer/ObjectExplorer/SmoModel/SmoQueryModel.tt

@@ -22,6 +22,7 @@ using System.Composition;
 using System.Linq;
 using Microsoft.SqlServer.Management.Smo;
 using Microsoft.SqlServer.Management.Smo.Broker;
+using Microsoft.SqlTools.Utility;
 using Index = Microsoft.SqlServer.Management.Smo.Index;
 
 namespace Microsoft.SqlTools.ServiceLayer.ObjectExplorer.SmoModel
@@ -67,7 +68,7 @@ namespace Microsoft.SqlTools.ServiceLayer.ObjectExplorer.SmoModel
 		WriteLine("public override  IEnumerable<SqlSmoObject> Query(SmoQueryContext context, string filter, bool refresh, IEnumerable<string> extraProperties)");
 		WriteLine("{");
 		PushIndent(indent);
-
+		WriteLine(string.Format("Logger.Verbose(\"Begin query {0}\");", nodeType));
 		// TODO Allow override of the navigation path
 		foreach(var parentType in parents)
 		{
@@ -94,7 +95,9 @@ namespace Microsoft.SqlTools.ServiceLayer.ObjectExplorer.SmoModel
 				WriteLine(string.Format("retValue.ClearAndInitialize(filter, extraProperties);"));
 				if (string.IsNullOrEmpty(subField) )
 				{
-					WriteLine(string.Format("return new SmoCollectionWrapper<{0}>(retValue).Where(c => PassesFinalFilters({1}, c));", nodeType, parentVar));
+					WriteLine(string.Format("var ret = new SmoCollectionWrapper<{0}>(retValue).Where(c => PassesFinalFilters({1}, c));", nodeType, parentVar));
+					WriteLine(string.Format("Logger.Verbose(\"End query {0}\");", nodeType));
+					WriteLine("return ret;");
 				}
 				else
 				{
@@ -111,7 +114,9 @@ namespace Microsoft.SqlTools.ServiceLayer.ObjectExplorer.SmoModel
 					WriteLine("}");
 					PopIndent();
 					WriteLine("}");
-					WriteLine(string.Format("return subFieldResult.Where(c => PassesFinalFilters({1}, c));", nodeType, parentVar));
+					WriteLine(string.Format("var ret = subFieldResult.Where(c => PassesFinalFilters({1}, c));", nodeType, parentVar));
+					WriteLine(string.Format("Logger.Verbose(\"End query {0}\");", nodeType));
+					WriteLine("return ret;");
 				}
 			}
 			else