Enhanced Logging for sqltoolsservice (#695)

This change modifies the logging framework within sqltoolservice.
Moves away from custom Logger object to start using .Net tracing framework. It supports for the static Trace and TraceSource way of logging. For all new code it is recommend that we log the log messages using the existing static Logger class, while the code changes will continue to route the older Trace.Write* calls from the process to same log listeners (and thus the log targets) as used by the Logger class. Thus tracing in SMO code that uses Trace.Write* methods gets routed to the same file as the messages from rest of SQLTools Service code.
Make changes to start using .Net Frameworks codebase for all logging to unify our logging story.
Allows parameter to set tracingLevel filters that controls what kinds of message make it to the log file.
Allows a parameter to set a specific log file name so if these gets set by external code (the UI code using the tools service for example) then the external code is aware of the current log file in use.
Adding unittests to test out the existing and improved logging capabilities.


Sequences of checkins in development branch:
* Saving v1 of logging to prepare for code review. Minor cleanup and some end to end testing still remains
* Removing local launchSettings.json files
* added support for lazy listener to sqltoolsloglistener and removed incorrect changes to comments across files in previous checkin
* Converting time to local time when writing entries to the log
* move the hosting.v2 to new .net based logging code
* removing *.dgml files and addding them to .gitignore
* fixing typo of defaultTraceSource
* Addressing pull request feedback
* Adding a test to verify logging from SMO codebase
* propogating changes to v1 sqltools.hosting commandoptions.cs to the v2 version
* Fixing comments on start and stop callstack methods and whitespaces
* Commenting a test that got uncommented by mistake
* addding .gitattributes file as .sql file was observed to be misconstrued as a binary file
This commit is contained in:
ranasaria
2018-09-24 23:55:59 -07:00
committed by GitHub
parent 0c1648b1c4
commit 09652cccd1
112 changed files with 2262 additions and 831 deletions

View File

@@ -21,6 +21,7 @@ using Microsoft.SqlTools.ServiceLayer.LanguageServices;
using Microsoft.SqlTools.ServiceLayer.LanguageServices.Contracts;
using Microsoft.SqlTools.ServiceLayer.Utility;
using Microsoft.SqlTools.Utility;
using System.Diagnostics;
namespace Microsoft.SqlTools.ServiceLayer.Connection
{
@@ -333,7 +334,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection
}
catch (Exception ex)
{
Logger.Write(LogLevel.Normal, "Failed to close temporary connections. error: " + ex.Message);
Logger.Write(TraceEventType.Information, "Failed to close temporary connections. error: " + ex.Message);
}
}
@@ -982,7 +983,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection
ConnectParams connectParams,
RequestContext<bool> requestContext)
{
Logger.Write(LogLevel.Verbose, "HandleConnectRequest");
Logger.Write(TraceEventType.Verbose, "HandleConnectRequest");
try
{
@@ -1032,7 +1033,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection
CancelConnectParams cancelParams,
RequestContext<bool> requestContext)
{
Logger.Write(LogLevel.Verbose, "HandleCancelConnectRequest");
Logger.Write(TraceEventType.Verbose, "HandleCancelConnectRequest");
try
{
@@ -1052,7 +1053,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection
DisconnectParams disconnectParams,
RequestContext<bool> requestContext)
{
Logger.Write(LogLevel.Verbose, "HandleDisconnectRequest");
Logger.Write(TraceEventType.Verbose, "HandleDisconnectRequest");
try
{
@@ -1073,7 +1074,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection
ListDatabasesParams listDatabasesParams,
RequestContext<ListDatabasesResponse> requestContext)
{
Logger.Write(LogLevel.Verbose, "ListDatabasesRequest");
Logger.Write(TraceEventType.Verbose, "ListDatabasesRequest");
try
{
@@ -1409,7 +1410,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection
catch (Exception e)
{
Logger.Write(
LogLevel.Error,
TraceEventType.Error,
string.Format(
"Exception caught while trying to change database context to [{0}] for OwnerUri [{1}]. Exception:{2}",
newDatabaseName,
@@ -1477,7 +1478,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection
}
catch (Exception ex)
{
Logger.Write(LogLevel.Verbose, "Could not send Connection telemetry event " + ex.ToString());
Logger.Write(TraceEventType.Verbose, "Could not send Connection telemetry event " + ex.ToString());
}
}
}
@@ -1522,7 +1523,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection
string error = string.Format(CultureInfo.InvariantCulture,
"Failed opening a SqlConnection: error:{0} inner:{1} stacktrace:{2}",
ex.Message, ex.InnerException != null ? ex.InnerException.Message : string.Empty, ex.StackTrace);
Logger.Write(LogLevel.Error, error);
Logger.Write(TraceEventType.Error, error);
}
return null;

View File

@@ -5,6 +5,7 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Reflection;
using Microsoft.SqlTools.Utility;
@@ -350,13 +351,13 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
public void TraceSettings()
{
// NOTE: logging as warning so we can get this data in the IEService DacFx logs
Logger.Write(LogLevel.Warning, Resources.LoggingAmbientSettings);
Logger.Write(TraceEventType.Warning, Resources.LoggingAmbientSettings);
foreach (KeyValuePair<string, AmbientValue> setting in _configuration)
{
// Log Ambient Settings
Logger.Write(
LogLevel.Warning,
TraceEventType.Warning,
string.Format(
Resources.AmbientSettingFormat,
setting.Key,
@@ -406,7 +407,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
}
else
{
Logger.Write(LogLevel.Error, string.Format(Resources.UnableToAssignValue, value.GetType().FullName, _type.FullName));
Logger.Write(TraceEventType.Error, string.Format(Resources.UnableToAssignValue, value.GetType().FullName, _type.FullName));
}
}
}

View File

@@ -7,6 +7,7 @@ using System;
using System.Collections.Concurrent;
using System.Data;
using System.Data.SqlClient;
using System.Diagnostics;
using System.Linq;
using Microsoft.SqlTools.Utility;
@@ -270,7 +271,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
}
catch
{
Logger.Write(LogLevel.Error, String.Format(Resources.FailedToParseConnectionString, connection.ConnectionString));
Logger.Write(TraceEventType.Error, String.Format(Resources.FailedToParseConnectionString, connection.ConnectionString));
return null;
}
}

View File

@@ -429,7 +429,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
Validate.IsNotNull(nameof(connection), connection);
if (!(connection.State == ConnectionState.Open))
{
Logger.Write(LogLevel.Warning, Resources.ConnectionPassedToIsCloudShouldBeOpen);
Logger.Write(TraceEventType.Warning, Resources.ConnectionPassedToIsCloudShouldBeOpen);
}
Func<string, bool> executeCommand = commandText =>
@@ -540,7 +540,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
return true;
}
Logger.Write(LogLevel.Error, ex.ToString());
Logger.Write(TraceEventType.Error, ex.ToString());
return false;
}
@@ -612,14 +612,13 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
if (!string.IsNullOrWhiteSpace(filePath))
{
// Remove filename from the filePath
Uri pathUri;
if (!Uri.IsWellFormedUriString(filePath, UriKind.Absolute))
{
// In linux "file://" is required otehrwise the Uri cannot parse the path
//this should be fixed in dotenet core 2.0
filePath = $"file://{filePath}";
}
if (!Uri.TryCreate(filePath, UriKind.Absolute, out pathUri))
if (!Uri.TryCreate(filePath, UriKind.Absolute, out Uri pathUri))
{
// Invalid Uri
return null;
@@ -668,7 +667,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
},
(ex) =>
{
Logger.Write(LogLevel.Error, ex.ToString());
Logger.Write(TraceEventType.Error, ex.ToString());
return StandardExceptionHandler(ex); // handled
},
useRetry: true);
@@ -701,8 +700,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
public static bool TryGetServerVersion(string connectionString, out ServerInfo serverInfo)
{
serverInfo = null;
SqlConnectionStringBuilder builder;
if (!TryGetConnectionStringBuilder(connectionString, out builder))
if (!TryGetConnectionStringBuilder(connectionString, out SqlConnectionStringBuilder builder))
{
return false;
}
@@ -739,7 +737,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
Validate.IsNotNull(nameof(connection), connection);
if (!(connection.State == ConnectionState.Open))
{
Logger.Write(LogLevel.Error, "connection passed to GetServerVersion should be open.");
Logger.Write(TraceEventType.Error, "connection passed to GetServerVersion should be open.");
}
Func<string, ServerInfo> getServerInfo = commandText =>
@@ -788,8 +786,8 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
{
//we don't want to fail the normal flow if any unexpected thing happens
//during caching although it's unlikely. So we just log the exception and ignore it
Logger.Write(LogLevel.Error, Resources.FailedToCacheIsCloud);
Logger.Write(LogLevel.Error, ex.ToString());
Logger.Write(TraceEventType.Error, Resources.FailedToCacheIsCloud);
Logger.Write(TraceEventType.Error, ex.ToString());
}
});
@@ -892,7 +890,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
if (handledEx != null)
{
Logger.Write(LogLevel.Error, String.Format(Resources.ErrorParsingConnectionString, handledEx));
Logger.Write(TraceEventType.Error, String.Format(Resources.ErrorParsingConnectionString, handledEx));
return false;
}

View File

@@ -360,18 +360,18 @@ SET NUMERIC_ROUNDABORT OFF;";
}
/// <summary>
/// Adds an info message event listener.
/// Adds an info message event Listener.
/// </summary>
/// <param name="handler">An info message event listener.</param>
/// <param name="handler">An info message event Listener.</param>
public void AddInfoMessageHandler(SqlInfoMessageEventHandler handler)
{
_underlyingConnection.InfoMessage += handler;
}
/// <summary>
/// Removes an info message event listener.
/// Removes an info message event Listener.
/// </summary>
/// <param name="handler">An info message event listener.</param>
/// <param name="handler">An info message event Listener.</param>
public void RemoveInfoMessageHandler(SqlInfoMessageEventHandler handler)
{
_underlyingConnection.InfoMessage -= handler;
@@ -436,7 +436,7 @@ SET NUMERIC_ROUNDABORT OFF;";
string sessionId = (string)command.ExecuteScalar();
if (!Guid.TryParse(sessionId, out _azureSessionId))
{
Logger.Write(LogLevel.Error, Resources.UnableToRetrieveAzureSessionId);
Logger.Write(TraceEventType.Error, Resources.UnableToRetrieveAzureSessionId);
}
}
}
@@ -444,7 +444,7 @@ SET NUMERIC_ROUNDABORT OFF;";
}
catch (Exception exception)
{
Logger.Write(LogLevel.Error, Resources.UnableToRetrieveAzureSessionId + exception.ToString());
Logger.Write(TraceEventType.Error, Resources.UnableToRetrieveAzureSessionId + exception.ToString());
}
}

View File

@@ -4,6 +4,7 @@
//
using System.Data.SqlClient;
using System.Diagnostics;
using Microsoft.SqlTools.Utility;
namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
@@ -30,7 +31,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
RetryPolicyUtils.AppendThrottlingDataIfIsThrottlingError(sqlException, err);
if (RetryPolicyUtils.IsNonRetryableDataTransferError(err.Number))
{
Logger.Write(LogLevel.Error, string.Format(Resources.ExceptionCannotBeRetried, err.Number, err.Message));
Logger.Write(TraceEventType.Error, string.Format(Resources.ExceptionCannotBeRetried, err.Number, err.Message));
return false;
}
}

View File

@@ -244,7 +244,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
bool shouldRetry = canRetry
&& ShouldRetryImpl(retryState);
Logger.Write(LogLevel.Error,
Logger.Write(TraceEventType.Error,
string.Format(
CultureInfo.InvariantCulture,
"Retry requested: Retry count = {0}. Delay = {1}, SQL Error Number = {2}, Can retry error = {3}, Will retry = {4}",
@@ -267,7 +267,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
{
bool shouldIgnoreError = ErrorDetectionStrategy.ShouldIgnoreError(retryState.LastError);
Logger.Write(LogLevel.Error,
Logger.Write(TraceEventType.Error,
string.Format(
CultureInfo.InvariantCulture,
"Ignore Error requested: Retry count = {0}. Delay = {1}, SQL Error Number = {2}, Should Ignore Error = {3}",

View File

@@ -392,7 +392,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
internal static void DataConnectionFailureRetry(RetryState retryState)
{
Logger.Write(LogLevel.Normal, string.Format(CultureInfo.InvariantCulture,
Logger.Write(TraceEventType.Information, string.Format(CultureInfo.InvariantCulture,
"Connection retry number {0}. Delaying {1} ms before retry. Exception: {2}",
retryState.RetryCount,
retryState.Delay.TotalMilliseconds.ToString(CultureInfo.InvariantCulture),
@@ -403,7 +403,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
internal static void CommandFailureRetry(RetryState retryState, string commandKeyword)
{
Logger.Write(LogLevel.Normal, string.Format(
Logger.Write(TraceEventType.Information, string.Format(
CultureInfo.InvariantCulture,
"{0} retry number {1}. Delaying {2} ms before retry. Exception: {3}",
commandKeyword,
@@ -416,7 +416,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
internal static void CommandFailureIgnore(RetryState retryState, string commandKeyword)
{
Logger.Write(LogLevel.Normal, string.Format(
Logger.Write(TraceEventType.Information, string.Format(
CultureInfo.InvariantCulture,
"{0} retry number {1}. Ignoring failure. Exception: {2}",
commandKeyword,

View File

@@ -6,6 +6,7 @@
using System;
using System.Collections.Generic;
using System.Data.SqlClient;
using System.Diagnostics;
using System.Runtime.InteropServices;
using Microsoft.SqlTools.Utility;
@@ -344,7 +345,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Connection.ReliableConnection
{
if (azureSessionId != Guid.Empty)
{
Logger.Write(LogLevel.Warning, string.Format(
Logger.Write(TraceEventType.Warning, string.Format(
"Retry occurred: session: {0}; attempt - {1}; delay - {2}; exception - \"{3}\"",
azureSessionId,
retryState.RetryCount,