Profiler notifications (#640)

* Initial changes for adding lost event notifications

* Handling polling errors by notifying listeners

* Restructuring lost events & testing

* Minor fixes to tests

* Add back in filtering

* Changing how lost events are found

* Cleaning up tests

src/Microsoft.SqlTools.ServiceLayer/Profiler/Contracts/ProfilerEventsAvailableNotification.cs

@@ -14,6 +14,8 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler.Contracts
         public string OwnerUri { get; set; }
 
         public List<ProfilerEvent> Events { get; set; }
+
+        public bool EventsLost { get; set; }
     }
 
     public class ProfilerEventsAvailableNotification

src/Microsoft.SqlTools.ServiceLayer/Profiler/Contracts/ProfilerSessionStoppedNotification.cs

@@ -0,0 +1,25 @@
+//
+// Copyright (c) Microsoft. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+//
+
+using System.Collections.Generic;
+using Microsoft.SqlTools.Hosting.Protocol.Contracts;
+using Microsoft.SqlTools.ServiceLayer.Utility;
+
+namespace Microsoft.SqlTools.ServiceLayer.Profiler.Contracts
+{
+    public class ProfilerSessionStoppedParams
+    {
+        public string OwnerUri { get; set; }
+
+        public int SessionId { get; set; }
+    }
+
+    public class ProfilerSessionStoppedNotification
+    {
+        public static readonly
+            EventType<ProfilerSessionStoppedParams> Type =
+            EventType<ProfilerSessionStoppedParams>.Create("profiler/sessionstopped");
+    }
+}

src/Microsoft.SqlTools.ServiceLayer/Profiler/IProfilerSessionListener.cs

@@ -10,6 +10,8 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
 {
     public interface IProfilerSessionListener
     {
-        void EventsAvailable(string sessionId, List<ProfilerEvent> events);
+        void EventsAvailable(string sessionId, List<ProfilerEvent> events, bool eventsLost);
+
+        void SessionStopped(string viewerId, int sessionId);
     }
 }

src/Microsoft.SqlTools.ServiceLayer/Profiler/ProfilerService.cs

@@ -268,7 +268,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
         /// <summary>
         /// Callback when profiler events are available
         /// </summary>
-        public void EventsAvailable(string sessionId, List<ProfilerEvent> events)
+        public void EventsAvailable(string sessionId, List<ProfilerEvent> events, bool eventsLost)
         {
             // pass the profiler events on to the client
             this.ServiceHost.SendEvent(
@@ -276,7 +276,23 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
                 new ProfilerEventsAvailableParams()
                 {
                     OwnerUri = sessionId,
-                    Events = events
+                    Events = events,
+                    EventsLost = eventsLost
+                });
+        }
+
+        /// <summary>
+        /// Callback when the XEvent session is closed unexpectedly
+        /// </summary>
+        public void SessionStopped(string viewerId, int sessionId)
+        {
+            // notify the client that their session closed
+            this.ServiceHost.SendEvent(
+                ProfilerSessionStoppedNotification.Type,
+                new ProfilerSessionStoppedParams()
+                {
+                    OwnerUri = viewerId,
+                    SessionId = sessionId
                 });
         }
 

src/Microsoft.SqlTools.ServiceLayer/Profiler/ProfilerSession.cs

@@ -24,6 +24,9 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
         private TimeSpan pollingDelay = DefaultPollingDelay;
         private ProfilerEvent lastSeenEvent = null;
 
+        private bool eventsLost = false;
+        int lastSeenId = -1;
+
         public bool pollImmediatly = false;
 
         /// <summary>
@@ -87,6 +90,17 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
             }
         }
 
+        /// <summary>
+        /// Could events have been lost in the last poll
+        /// </summary>
+        public bool EventsLost
+        {
+            get
+            {
+                return this.eventsLost;
+            }
+        }
+
         /// <summary>
         /// Determine if an event was caused by the XEvent polling queries
         /// </summary>
@@ -129,13 +143,19 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
         /// </summary>
         public void FilterOldEvents(List<ProfilerEvent> events)
         {
-            if (lastSeenEvent != null)
+            this.eventsLost = false;
+            
+            if (lastSeenId != -1)
             {
                 // find the last event we've previously seen
                 bool foundLastEvent = false;
                 int idx = events.Count;
+                int earliestSeenEventId = int.Parse(events.LastOrDefault().Values["event_sequence"]);
                 while (--idx >= 0)
                 {
+                    // update the furthest back event we've found so far
+                    earliestSeenEventId = Math.Min(earliestSeenEventId, int.Parse(events[idx].Values["event_sequence"]));
+
                     if (events[idx].Equals(lastSeenEvent))
                     {
                         foundLastEvent = true;
@@ -148,11 +168,18 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
                 {
                     events.RemoveRange(0, idx + 1);
                 }
+                else if(earliestSeenEventId > (lastSeenId + 1))
+                {
+                    // if there's a gap between the expected next event sequence
+                    // and the furthest back event seen, we know we've lost events
+                    this.eventsLost = true;
+                }
 
                 // save the last event so we know where to clean-up the list from next time
                 if (events.Count > 0)
                 {
                     lastSeenEvent = events.LastOrDefault();
+                    lastSeenId = int.Parse(lastSeenEvent.Values["event_sequence"]);
                 }
             }
             else    // first poll at start of session, all data is old
@@ -161,6 +188,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
                 if (events.Count > 0)
                 {
                     lastSeenEvent = events.LastOrDefault();
+                    lastSeenId = int.Parse(lastSeenEvent.Values["event_sequence"]);
                 }
 
                 // ignore all events before the session began

src/Microsoft.SqlTools.ServiceLayer/Profiler/ProfilerSessionMonitor.cs

@@ -233,7 +233,8 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
                 Task.Factory.StartNew(() =>
                 {
                     var events = PollSession(session);
-                    if (events.Count > 0)
+                    bool eventsLost = session.EventsLost;
+                    if (events.Count > 0 || eventsLost)
                     {
                         // notify all viewers for the polled session
                         List<string> viewerIds = this.sessionViewers[session.XEventSession.Id];
@@ -241,7 +242,7 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
                         {
                             if (allViewers[viewerId].active)
                             {
-                                SendEventsToListeners(viewerId, events);
+                                SendEventsToListeners(viewerId, events, eventsLost);
                             }
                         }
                     }
@@ -274,9 +275,15 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
                     }
                 }
             }
+            catch (XEventException)
+            {
+                SendStoppedSessionInfoToListeners(session.XEventSession.Id);
+                ProfilerSession tempSession;
+                RemoveSession(session.XEventSession.Id, out tempSession);
+            }
             catch (Exception ex)
             {
-                Logger.Write(LogLevel.Warning, "Failed to pool session. error: " + ex.Message);
+                Logger.Write(LogLevel.Warning, "Failed to poll session. error: " + ex.Message);
             }
             finally
             {
@@ -288,15 +295,32 @@ namespace Microsoft.SqlTools.ServiceLayer.Profiler
         }
 
         /// <summary>
-        /// Notify listeners when new profiler events are available
+        /// Notify listeners about closed sessions
         /// </summary>
-        private void SendEventsToListeners(string sessionId, List<ProfilerEvent> events)
+        private void SendStoppedSessionInfoToListeners(int sessionId)
         {
             lock (listenersLock)
             {
                 foreach (var listener in this.listeners)
                 {
-                    listener.EventsAvailable(sessionId, events);
+                    foreach(string viewerId in sessionViewers[sessionId])
+                    {
+                        listener.SessionStopped(viewerId, sessionId);
+                    }
+                }
+            }
+        }
+
+        /// <summary>
+        /// Notify listeners when new profiler events are available
+        /// </summary>
+        private void SendEventsToListeners(string sessionId, List<ProfilerEvent> events, bool eventsLost)
+        {
+            lock (listenersLock)
+            {
+                foreach (var listener in this.listeners)
+                {
+                    listener.EventsAvailable(sessionId, events, eventsLost);
                 }
             }
         }

test/Microsoft.SqlTools.ServiceLayer.UnitTests/Profiler/ProfilerServiceTests.cs

@@ -46,7 +46,7 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
 
             // capture listener event notifications
             var mockListener = new Mock<IProfilerSessionListener>();
-            mockListener.Setup(p => p.EventsAvailable(It.IsAny<string>(), It.IsAny<List<ProfilerEvent>>())).Callback(() =>
+            mockListener.Setup(p => p.EventsAvailable(It.IsAny<string>(), It.IsAny<List<ProfilerEvent>>(), It.IsAny<bool>())).Callback(() =>
                 {
                     recievedEvents = true;
                 });
@@ -166,7 +166,7 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
 
             // capture listener event notifications
             var mockListener = new Mock<IProfilerSessionListener>();
-            mockListener.Setup(p => p.EventsAvailable(It.IsAny<string>(), It.IsAny<List<ProfilerEvent>>())).Callback(() =>
+            mockListener.Setup(p => p.EventsAvailable(It.IsAny<string>(), It.IsAny<List<ProfilerEvent>>(), It.IsAny<bool>())).Callback(() =>
                 {
                     recievedEvents = true;
                 });
@@ -235,5 +235,52 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
 
             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);
+        }
     }
 }

test/Microsoft.SqlTools.ServiceLayer.UnitTests/Profiler/ProfilerSessionTests.cs

@@ -34,6 +34,7 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
 
             // add a new event
             var newEvent = new ProfilerEvent("new event", "1/1/2017");
+            newEvent.Values.Add("event_sequence", "4");
             allEvents.Add(newEvent);
 
             // poll all events
@@ -52,7 +53,6 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             Assert.Equal(profilerEvents.Count, 0);
         }
 
-
         /// <summary>
         /// Test the FilterProfilerEvents method
         /// </summary>
@@ -68,6 +68,7 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             // add a new "Profiler Polling" event
             var newEvent = new ProfilerEvent("sql_batch_completed", "1/1/2017");
             newEvent.Values.Add("batch_text", "SELECT target_data FROM sys.dm_xe_session_targets");
+            newEvent.Values.Add("event_sequence", "4");
             profilerEvents.Add(newEvent);
 
             // verify that the polling event is removed
@@ -76,6 +77,53 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             Assert.Equal(newProfilerEvents.Count, expectedEventCount);           
         }
 
+        /// <summary>
+        /// Test notifications for lost events
+        /// </summary>
+        [Fact]
+        public void TestEventsLost()
+        {
+            // create a profiler session and get some test events
+            var profilerSession = new ProfilerSession();
+            var profilerEvents = ProfilerTestObjects.TestProfilerEvents;
+
+            // filter all the results from the first poll
+            // these events happened before the profiler began
+            profilerSession.FilterOldEvents(profilerEvents);
+            Assert.Equal(profilerEvents.Count, 0);
+            // No events should be lost
+            Assert.False(profilerSession.EventsLost);
+
+            // test all events are overwritten, but no events are lost
+            profilerEvents.Clear();
+            ProfilerEvent newEvent = new ProfilerEvent("event4", "6/18/2018");
+            newEvent.Values.Add("event_sequence", "4");
+
+            profilerEvents.Add(newEvent);         
+            profilerSession.FilterOldEvents(profilerEvents);
+
+            // should not show event loss
+            Assert.False(profilerSession.EventsLost);
+
+            // test all events are overwritten, and events are lost
+            profilerEvents.Clear();
+            newEvent = new ProfilerEvent("event7", "6/18/2018");
+            newEvent.Values.Add("event_sequence", "7");
+
+            profilerEvents.Add(newEvent);         
+            profilerSession.FilterOldEvents(profilerEvents);
+
+            // should show event loss
+            Assert.True(profilerSession.EventsLost);
+
+            //poll again with previously seen events
+            profilerEvents.Add(newEvent);
+
+            // old events were seen, no event loss occured
+            profilerSession.FilterOldEvents(profilerEvents);           
+            Assert.False(profilerSession.EventsLost);    
+        }
+
         /// <summary>
         /// Test the TryEnterPolling method
         /// </summary>

test/Microsoft.SqlTools.ServiceLayer.UnitTests/Profiler/ProfilerTestObjects.cs

@@ -25,11 +25,18 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
         {
             get
             {
+                ProfilerEvent event1 = new ProfilerEvent("event1", "1/1/2017");
+                event1.Values.Add("event_sequence", "1");
+                ProfilerEvent event2 = new ProfilerEvent("event2", "1/2/2017");
+                event2.Values.Add("event_sequence", "2");
+                ProfilerEvent event3 = new ProfilerEvent("event3", "1/3/2017");
+                event3.Values.Add("event_sequence", "3");
+                
                 return new List<ProfilerEvent>
                 {
-                    new ProfilerEvent("event1", "1/1/2017"),
+                    event1,
-                    new ProfilerEvent("event2", "1/2/2017"),
+                    event2,
-                    new ProfilerEvent("event3", "1/3/2017")
+                    event3
                 };
             }
         }
@@ -41,11 +48,18 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
 
         public List<ProfilerEvent> PreviousEvents { get; set; }
 
-        public void EventsAvailable(string sessionId, List<ProfilerEvent> events)
+        public bool Stopped { get; set; }
+
+        public void EventsAvailable(string sessionId, List<ProfilerEvent> events, bool eventsLost)
         {
             this.PreviousSessionId = sessionId;
             this.PreviousEvents = events;
         }
+
+        public void SessionStopped(string viewerId, int sessionId)
+        {
+            Stopped = true;
+        }
     }
 
     public class TestXEventSession : IXEventSession
@@ -210,6 +224,10 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>1</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>1</value>" +
+            "		</data>" +
             "	</event>" +
             "</RingBufferTarget>";
 
@@ -220,12 +238,20 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>1</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>1</value>" +
+            "       </data>" +
             "	</event>" +
             "	<event name=\"existing_connection\" package=\"sqlserver\" timestamp=\"2017-10-08T07:46:53.579Z\">" +
             "		<data name=\"session_id\">" +
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>1</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>2</value>" +
+            "       </data>" +
             "	</event>" +
             "</RingBufferTarget>";
 
@@ -236,18 +262,30 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>1</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>1</value>" +
+            "       </data>" +
             "	</event>" +
             "	<event name=\"existing_connection\" package=\"sqlserver\" timestamp=\"2017-10-08T07:46:53.579Z\">" +
             "		<data name=\"session_id\">" +
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>1</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>2</value>" +
+            "       </data>" +
             "	</event>" +
             "	<event name=\"existing_connection\" package=\"sqlserver\" timestamp=\"2017-11-08T07:46:53.579Z\">" +
             "		<data name=\"session_id\">" +
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>1</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>3</value>" +
+            "       </data>" +
             "	</event>" +
             "</RingBufferTarget>";
 
@@ -277,6 +315,10 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>2</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>1</value>" +
+            "       </data>" +
             "	</event>" +
             "</RingBufferTarget>";
 
@@ -287,12 +329,20 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>2</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>1</value>" +
+            "       </data>" +
             "	</event>" +
             "	<event name=\"existing_connection\" package=\"sqlserver\" timestamp=\"2017-10-08T07:46:53.579Z\">" +
             "		<data name=\"session_id\">" +
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>2</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>2</value>" +
+            "       </data>" +
             "	</event>" +
             "</RingBufferTarget>";
 
@@ -303,18 +353,30 @@ namespace Microsoft.SqlTools.ServiceLayer.UnitTests.Profiler
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>2</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>1</value>" +
+            "       </data>" +
             "	</event>" +
             "	<event name=\"existing_connection\" package=\"sqlserver\" timestamp=\"2017-10-08T07:46:53.579Z\">" +
             "		<data name=\"session_id\">" +
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>2</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>2</value>" +
+            "       </data>" +
             "	</event>" +
             "	<event name=\"existing_connection\" package=\"sqlserver\" timestamp=\"2017-11-08T07:46:53.579Z\">" +
             "		<data name=\"session_id\">" +
             "			<type name=\"int16\" package=\"package0\"></type>" +
             "			<value>2</value>" +
             "		</data>" +
+            "       <data name=\"event_sequence\">" +
+            "			<type name=\"int16\" package=\"package0\"></type>" +
+            "			<value>3</value>" +
+            "       </data>" +
             "	</event>" +
             "</RingBufferTarget>";