Files
sqltoolsservice/test/Microsoft.SqlTools.ServiceLayer.UnitTests/Profiler/ProfilerServiceTests.cs
ranasaria 09652cccd1 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
2018-09-24 23:55:59 -07:00

286 lines
11 KiB
C#

//
// Copyright (c) Microsoft. All rights reserved.
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
//
using System;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using System.Collections.Generic;
using Microsoft.SqlServer.Management.XEvent;
using Microsoft.SqlTools.Hosting.Protocol;
using Microsoft.SqlTools.ServiceLayer.Connection;
using Microsoft.SqlTools.ServiceLayer.Profiler;
using Microsoft.SqlTools.ServiceLayer.Profiler.Contracts;
using Microsoft.SqlTools.ServiceLayer.UnitTests.Utility;
using Moq;
using Xunit;
namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
{
/// <summary>
/// Unit tests for ProfilerService
/// </summary>
public class ProfilerServiceTests
{
/// <summary>
/// Test starting a profiling session and receiving event callback
/// </summary>
/// <returns></returns>
// TODO: Fix flaky test. See https://github.com/Microsoft/sqltoolsservice/issues/459
//[Fact]
public async Task TestStartProfilingRequest()
{
string sessionId = null;
bool recievedEvents = false;
string testUri = "profiler_uri";
var requestContext = new Mock<RequestContext<StartProfilingResult>>();
requestContext.Setup(rc => rc.SendResult(It.IsAny<StartProfilingResult>()))
.Returns<StartProfilingResult>((result) =>
{
// capture the session id for sending the stop message
return Task.FromResult(0);
});
// capture Listener event notifications
var mockListener = new Mock<IProfilerSessionListener>();
mockListener.Setup(p => p.EventsAvailable(It.IsAny<string>(), It.IsAny<List<ProfilerEvent>>(), It.IsAny<bool>())).Callback(() =>
{
recievedEvents = true;
});
var profilerService = new ProfilerService();
profilerService.SessionMonitor.AddSessionListener(mockListener.Object);
profilerService.ConnectionServiceInstance = TestObjects.GetTestConnectionService();
ConnectionInfo connectionInfo = TestObjects.GetTestConnectionInfo();
profilerService.ConnectionServiceInstance.OwnerToConnectionMap.Add(testUri, connectionInfo);
profilerService.XEventSessionFactory = new TestXEventSessionFactory();
var requestParams = new StartProfilingParams();
requestParams.OwnerUri = testUri;
requestParams.SessionName = "Standard";
// start profiling session
await profilerService.HandleStartProfilingRequest(requestParams, requestContext.Object);
profilerService.SessionMonitor.PollSession(1);
// simulate a short polling delay
Thread.Sleep(200);
profilerService.SessionMonitor.PollSession(1);
// wait for polling to finish, or for timeout
System.Timers.Timer pollingTimer = new System.Timers.Timer();
pollingTimer.Interval = 10000;
pollingTimer.Start();
bool timeout = false;
pollingTimer.Elapsed += new System.Timers.ElapsedEventHandler((s_, e_) => {timeout = true;});
while (sessionId == null && !timeout)
{
Thread.Sleep(250);
}
pollingTimer.Stop();
requestContext.VerifyAll();
// Check that the correct XEvent session was started
Assert.Equal(sessionId, "1");
// check that the proper owner Uri was used
Assert.True(recievedEvents);
}
/// <summary>
/// Test stopping a session and receiving event callback
/// </summary>
/// <returns></returns>
[Fact]
public async Task TestStopProfilingRequest()
{
bool success = false;
bool stopped = false;
string testUri = "test_session";
// capture stopping results
var requestContext = new Mock<RequestContext<StopProfilingResult>>();
requestContext.Setup(rc => rc.SendResult(It.IsAny<StopProfilingResult>()))
.Returns<StopProfilingResult>((result) =>
{
success = true;
return Task.FromResult(0);
});
// capture if session was stopped
var mockSession = new Mock<IXEventSession>();
mockSession.Setup(p => p.Stop()).Callback(() =>
{
stopped = true;
});
var sessionListener = new TestSessionListener();
var profilerService = new ProfilerService();
profilerService.SessionMonitor.AddSessionListener(sessionListener);
profilerService.ConnectionServiceInstance = TestObjects.GetTestConnectionService();
ConnectionInfo connectionInfo = TestObjects.GetTestConnectionInfo();
profilerService.ConnectionServiceInstance.OwnerToConnectionMap.Add(testUri, connectionInfo);
profilerService.XEventSessionFactory = new TestXEventSessionFactory();
var requestParams = new StopProfilingParams();
requestParams.OwnerUri = testUri;
profilerService.SessionMonitor.StartMonitoringSession(testUri, mockSession.Object);
await profilerService.HandleStopProfilingRequest(requestParams, requestContext.Object);
requestContext.VerifyAll();
// check that session was succesfully stopped and stop was called
Assert.True(success);
Assert.True(stopped);
// should not be able to remove the session, it should already be gone
ProfilerSession ps;
Assert.False(profilerService.SessionMonitor.StopMonitoringSession(testUri, out ps));
}
/// <summary>
/// Test pausing then resuming a session
/// </summary>
/// <returns></returns>
[Fact]
public async Task TestPauseProfilingRequest()
{
bool success = false;
string testUri = "test_session";
bool recievedEvents = false;
// capture pausing results
var requestContext = new Mock<RequestContext<PauseProfilingResult>>();
requestContext.Setup(rc => rc.SendResult(It.IsAny<PauseProfilingResult>()))
.Returns<PauseProfilingResult>((result) =>
{
success = true;
return Task.FromResult(0);
});
// capture Listener event notifications
var mockListener = new Mock<IProfilerSessionListener>();
mockListener.Setup(p => p.EventsAvailable(It.IsAny<string>(), It.IsAny<List<ProfilerEvent>>(), It.IsAny<bool>())).Callback(() =>
{
recievedEvents = true;
});
// setup profiler service
var profilerService = new ProfilerService();
profilerService.SessionMonitor.AddSessionListener(mockListener.Object);
profilerService.ConnectionServiceInstance = TestObjects.GetTestConnectionService();
ConnectionInfo connectionInfo = TestObjects.GetTestConnectionInfo();
profilerService.ConnectionServiceInstance.OwnerToConnectionMap.Add(testUri, connectionInfo);
var requestParams = new PauseProfilingParams();
requestParams.OwnerUri = testUri;
// begin monitoring session
profilerService.SessionMonitor.StartMonitoringSession(testUri, new TestXEventSession1());
// poll the session
profilerService.SessionMonitor.PollSession(1);
Thread.Sleep(500);
profilerService.SessionMonitor.PollSession(1);
// wait for polling to finish, or for timeout
System.Timers.Timer pollingTimer = new System.Timers.Timer();
pollingTimer.Interval = 10000;
pollingTimer.Start();
bool timeout = false;
pollingTimer.Elapsed += new System.Timers.ElapsedEventHandler((s_, e_) => {timeout = true;});
while (!recievedEvents && !timeout)
{
Thread.Sleep(250);
}
pollingTimer.Stop();
// confirm that polling works
Assert.True(recievedEvents);
// pause viewer
await profilerService.HandlePauseProfilingRequest(requestParams, requestContext.Object);
Assert.True(success);
recievedEvents = false;
success = false;
profilerService.SessionMonitor.PollSession(1);
// confirm that no events were sent to paused Listener
Assert.False(recievedEvents);
// unpause viewer
await profilerService.HandlePauseProfilingRequest(requestParams, requestContext.Object);
Assert.True(success);
profilerService.SessionMonitor.PollSession(1);
// wait for polling to finish, or for timeout
timeout = false;
pollingTimer.Start();
while (!recievedEvents && !timeout)
{
Thread.Sleep(250);
}
// check that events got sent to Listener
Assert.True(recievedEvents);
requestContext.VerifyAll();
}
/// <summary>
/// Test notifications for stopped sessions
/// </summary>
[Fact]
public async Task TestStoppedSessionNotification()
{
bool sessionStopped = false;
string testUri = "profiler_uri";
// capture Listener event notifications
var mockSession = new Mock<IXEventSession>();
mockSession.Setup(p => p.GetTargetXml()).Callback(() =>
{
throw new XEventException();
});
var mockListener = new Mock<IProfilerSessionListener>();
mockListener.Setup(p => p.SessionStopped(It.IsAny<string>(), It.IsAny<int>())).Callback(() =>
{
sessionStopped = true;
});
var profilerService = new ProfilerService();
profilerService.SessionMonitor.AddSessionListener(mockListener.Object);
profilerService.ConnectionServiceInstance = TestObjects.GetTestConnectionService();
ConnectionInfo connectionInfo = TestObjects.GetTestConnectionInfo();
profilerService.ConnectionServiceInstance.OwnerToConnectionMap.Add(testUri, connectionInfo);
// start monitoring test session
profilerService.SessionMonitor.StartMonitoringSession(testUri, mockSession.Object);
// wait for polling to finish, or for timeout
System.Timers.Timer pollingTimer = new System.Timers.Timer();
pollingTimer.Interval = 10000;
pollingTimer.Start();
bool timeout = false;
pollingTimer.Elapsed += new System.Timers.ElapsedEventHandler((s_, e_) => {timeout = true;});
while (sessionStopped == false && !timeout)
{
Thread.Sleep(250);
}
pollingTimer.Stop();
// check that a stopped session notification was sent
Assert.True(sessionStopped);
}
}
}