BUGS in logging. Also reproducible in http://smf.cloudapp.net/healthmonitor

May 31, 2012 at 9:44 AM
Edited May 31, 2012 at 9:45 AM

Hello,

I am having a big problem with the logging.

It stops working after the Playlist on SMFPlayer is set few times.

I am subscribing to LoggingService's LogReceived event 

 

LoggingService.Current.LogReceived += new EventHandler<LogReceivedEventArgs>(Current_LogReceived);

 

I am testing on a simple application with just a SMFPlayer, a textbox to enter the URL and a button to create and set the Playlist for SMFPlayer.

The problem is after setting Playlist few times, I do not receive any events by LogReceived event handler.

This is reproducible in HealthMonitor sample application which also uses LoggingService's LogReceived event to update statistics. Here are the steps to reproduce the issue:

  1. Go to http://smf.cloudapp.net/healthmonitor
  2. Press Play button to start playing. Notice the graphs and stream information statistics updating.
  3. Copy and paste the URL: http://playready.directtaps.net/smoothstreaming/TTLSS720VC1/To_The_Limit_720.ism/Manifest  This is from Microsoft's own playready test servers(http://playready.directtaps.net/smoothstreaming/), so nothing special about it.
  4. Press Play button to start playing. If when pressing the Play button, it does not start playing the new URL, delete the last character and press Enter. There are clearly some bugs in the UI.

      5. Notice the graphs and stream information statistics. If they update, set again the stream URL to previous one: http://video3.smoothhd.com.edgesuite.net/ondemand/Big%20Buck%20Bunny%20Adaptive.ism/Manifest

      6. You should start to see the graphs and stream info not updating.

 

I really hope someone can help with this as I've spent alot of hours on this without finding a solution.

Thanks!

Andrew

 

 

Coordinator
May 31, 2012 at 9:59 AM

Thanks Andrew. We'll take a look at this and see what's going wrong.

- Mike

May 31, 2012 at 10:02 AM

Thanks Mike. I am anxious to see what you can find, it's very important to me.

May 31, 2012 at 10:15 AM

Things I tried but without any success:

- calling LoggingService.Current.StopMonitoring() and LoggingService.Current.StartMonitoring() before setting the Playlist

 - creating SMFPlayer control on the fly each time I want to play a new URL

May 31, 2012 at 11:02 AM
Edited May 31, 2012 at 11:41 AM

OK, I think I know what is going on but it still don't know how to fix this issue

I debugged the source code of different plugins from the media framework.

Short story:

SmoothStreamingMediaElement does not always fire the ManifestReady when streaming source is changed.

Long story(it makes more sense probably if you read it in the reversed direction):

1. LogReceived event handler is called by LoggingService.Current.Log( ) 

2. This in turn is called by HealthMonitorLogger::FlushLogs() and by  HealthMonitorLogger::SendLog() . HealthMonitorLogger is a class from Microsoft.SilverlightMediaFramework.Plugins.Monitoring.dll

 HealthMonitorLogger calls FlushLogs() on the HealthMonitor::EdgeServerCompleted event handler. HealthMonitor is a class from Microsoft.SilverlightMediaFramework.Diagnostics.dll

 HealthMonitorLogger calls HealthMonitorLogger::SendLog() only when  HealthMonitor::IsEdgeServerComplete is true(see below how it's set)

3. EdgeServerCompleted is fired by the HealthMonitor::SmoothStreamingSourceChanged() method 

  This method sets synchronously or asynchronously(depending on edgeserverrules in config) the  HealthMonitor::IsEdgeServerComplete to true 

4. HealthMonitor::SmoothStreamingSourceChanged() method is in turn called by   HealthMonitor::mediaElement_ManifestReady event handler

5.  HealthMonitor::mediaElement_ManifestReady is the ManifestReady event handler of the SmoothStreamingMediaElement class.

It looks like SmoothStreamingMediaElement does not fire the ManifestReady when streaming source is changed.

 

Any ideas, any workarounds?

May 31, 2012 at 11:13 AM

Currently, the way logging/monitoring framework works is it relies on the ManifestReady event being fired. Why does it not fire?

Is this event fired when manifest file is downloaded by the SmoothStreamingMediaElement?

If that's the case, is it possible that the manifest file is not actually downloaded sometimes because it is in cache(webbrowser cache maybe)? 

May 31, 2012 at 11:41 AM

I made some important modifications in the steps description.

May 31, 2012 at 12:13 PM

My assumptions were correct, HealthMonitor does not receive the ManifestReady event from SmoothStreamingMediaElement because the manifest is cached.

So the fix is to check for SmoothStreamingMediaElement.ManifestInfo property:

 void AttachEvents()       

{

  .....

  if (mediaElement.ManifestInfo != null)       

  {

                mediaElement_ManifestReady(this.mediaElement, new EventArgs());           

  }

  else

  {               

          mediaElement.ManifestReady += new EventHandler<EventArgs>(mediaElement_ManifestReady);           

   }

 .....

}

 

I hope this is useful for other people, might save them for many hours of frustration

Coordinator
Jun 1, 2012 at 9:35 PM

nitescua, thanks for reporting this.

The first issue with the healthmonitor not updating the stream turns out to be a binding bug in the Silverlight AutoCompleteTextBox. I am changing this to a regular textbox to workaround the issue.

Regarding ManifestReady not firing, I have not been unable to repro this. However, I can confirm that we only start listening for ManifestReady once CurrentState = Opening fires. From my tests: cached or uncached, currentstate consistently fires with 'Opening' before ManifestReady. Nevertheless, it's certainly possible that there is a race condition and I can't confidently say that it is always guaranteed to happen in that order. Therefore, I'm going to go ahead and add the code you have above to help add more confidence that the code path will get triggered. Sorry you had to fight with this but glad to hear you were able to resolve it.

Regards,

Tim

Jun 1, 2012 at 9:57 PM

Thanks for your comment. 

I think the issue does not always reproduce from just playing again the same stream. I think you need to switch to another stream URL first.

If it helps, I'm on Win7 32 Ultimate, running latest Silverlight 5, it's reproducible on both latest IE 9 and Chrome. I tested it on another Win7 with Silverlight 5 and using a previous version 5.0.61118.0, but it's still the same issue.

Hope I am right but I think I looked with Reflector and it looks like ManifestReady is fired based on an DownloadStringComplete event.

I am not sure however how the ManifestInfo is setup.

Coordinator
Jun 5, 2012 at 8:16 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.
Coordinator
Jun 5, 2012 at 8:20 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.