recording tv just stopped :( HELP!!! (3 Viewers)

[lewiskingy]

Managed to reproduce the error again, this time with debug version of TVService.exe (16Nov) this evening. Took a fair while longer to reproduce this time around (thought I was clear for a moment). Logs attached anyway.

I'll be trying tidy-up of channels to avoid duplicates in XMLTV file. See if that helps.

Thanks again all.

 

[mm1352000]

Thanks David

The outermost thread should catch and log any exceptions in the scheduler loop:
https://github.com/MediaPortal/Medi...Library/TvService/Scheduler/Scheduler.cs#L344

I don't see that logged, so unless it is an unmanaged exception ???

 

[mm1352000]

Thanks lewiskingy

So, looks like the same stall position as robbo100:

[2013-12-16 20:11:21,362] [Log ] [scheduler thread] [INFO ] - debug: scheduler worker loop start
[2013-12-16 20:11:36,365] [Log ] [scheduler thread] [INFO ] - debug: stop any due recordings
[2013-12-16 20:11:36,367] [Log ] [scheduler thread] [INFO ] - debug: start any due recordings
[2013-12-16 20:11:36,383] [Log ] [scheduler thread] [INFO ] - debug: check and delete orphaned recordings
[2013-12-16 20:11:36,393] [Log ] [scheduler thread] [INFO ] - debug: got card list

This is good information, even if it doesn't immediately tell us the cause of the problem...

 

[davidf]

mm - good problem

Started reading the code this evening and it appears that there is no way of causing an error on that line of code... Wish I had a TV card with me (I'm working away from home), as it looks like an interesting problem. There seem to be a few ways of causing an exception there - but none that I can see are unmanaged so the outer try should catch it...

Might be worth trying this:

catch(SEHException sehException)
{
  //Get the error code
  int errcode = sehException.ErrorCode; 
  Log(errcode); //bet money it says E_FAIL :)
}
catch(Exception otherException)
{
  //other exceptions can be trapped and get exception details
  Exception excep = otherException.InnerException;
}
catch
{
  Log... //gods knows what to log as this exception is not marshallable and could be anything, and there is no way of telling what it is and where it came from
}

There's also a few things which won't get caught by those three: out of memory or stack overflow. Although if the extra catches do something you know that you can get a debugger on it.

 

[mm1352000]

Thanks again David

New build of TvService.exe attached. I've added the exception catching and logging as suggested:

  private void CheckAndDeleteOrphanedRecordings()
  {
    try
    {
      Log.Write("debug: grabbing recording card list");
      List<VirtualCard> vCards = _tvController.GetAllRecordingCards();
      Log.Write("debug: got card list");
      if (vCards == null)
      {
        Log.Write("debug: vCards is NULL!!!");
      }
      else
      {
        Log.Write("debug: card list count = {0}", vCards.Count);
      }

      foreach (VirtualCard vCard in vCards)
      {
        Log.Write("debug: card {0}", vCard.Name);
        int schedId = vCard.RecordingScheduleId;
        Log.Write("debug: schedule {0}", schedId);
        if (schedId > 0)
        {
          Log.Write("debug: get schedule");
          Schedule sc = Schedule.Retrieve(schedId);
          Log.Write("debug: got schedule");
          if (sc == null)
          {
            //seems like the schedule has disappeared  stop the recording also.
            Log.Debug("Scheduler: Orphaned Recording found {0} - removing", schedId);
            StopRecordingSchedule(schedId);
          }
          Log.Write("debug: done stop");
        }
        Log.Write("debug: done check");
      }
      Log.Write("debug: reached end of loop, returning");
    }
    catch (SEHException ex)
    {
      Log.Write("debug: caught SEH exception!!!");
      Log.Write(ex);
    }
    catch (Exception ex)
    {
      Log.Write("debug: caught base exception!!!");
      Log.Write(ex);
    }
    catch
    {
      Log.Write("debug: caught something!!!");
    }
  }

There are versions for MP 1.5 and 1.6 PR. Hoping that this enables more people to test...

I had a thought...
I wonder if we're not seeing the full picture due to log buffering.
I also wonder whether the problem is triggered by something in GetAllRecordingCards(), and the thread falls over after execution of something in that code.

mm

 

[lewiskingy]

Thanks for the updated code. I'm now running with latest 1.5 v3 debug service. Will post results shortly. (Excited.)

For info, I tidied up the channels being grabbed to avoid a duplicate entry in EPG data, and that didn't help. (Doesn't look related to the logs / code you're focussed on anyway.)

Given my setup has a dedicated TV server, do you reckon MP2 Alpha 4 would actually provide a more stable option on Windows 8?

Thanks again (and merry Christmas!)

 

[lewiskingy]

Hopefully this is helpful.

Sorry but logs go back to before service upgrade (which was about 8pm 23rd Dec).

Don't know if this is the most useful section, but I was interested that the "card list count" drops from 1 to 0 in this short section. Unsure if that is to be expected.

[2013-12-23 22:59:56,608] [Log    ] [scheduler thread] [INFO ] - debug: check and delete orphaned recordings
[2013-12-23 22:59:56,609] [Log    ] [scheduler thread] [INFO ] - debug: grabbing recording card list
[2013-12-23 22:59:56,613] [Log    ] [scheduler thread] [INFO ] - debug: got card list
[2013-12-23 22:59:56,614] [Log    ] [scheduler thread] [INFO ] - debug: card list count = 1
[2013-12-23 22:59:56,616] [Log    ] [scheduler thread] [INFO ] - debug: card TBS 6981 BDA DVBS/S2 A Tuner/Demod
[2013-12-23 22:59:56,618] [Log    ] [scheduler thread] [INFO ] - debug: schedule 119
[2013-12-23 22:59:56,619] [Log    ] [scheduler thread] [INFO ] - debug: get schedule
[2013-12-23 22:59:56,620] [Log    ] [scheduler thread] [INFO ] - debug: got schedule
[2013-12-23 22:59:56,622] [Log    ] [scheduler thread] [INFO ] - debug: done stop
[2013-12-23 22:59:56,623] [Log    ] [scheduler thread] [INFO ] - debug: done check
[2013-12-23 22:59:56,624] [Log    ] [scheduler thread] [INFO ] - debug: reached end of loop, returning
[2013-12-23 22:59:56,626] [Log    ] [scheduler thread] [INFO ] - debug: check and delete orphaned once schedules
[2013-12-23 22:59:56,627] [Log    ] [scheduler thread] [INFO ] - debug: handle sleep mode
[2013-12-23 22:59:56,628] [Log    ] [scheduler thread] [INFO ] - debug: work complete
[2013-12-23 22:59:56,630] [Log    ] [scheduler thread] [INFO ] - debug: scheduler worker loop end
[2013-12-23 22:59:56,632] [Log    ] [scheduler thread] [INFO ] - debug: scheduler worker loop start
[2013-12-23 23:00:11,634] [Log    ] [scheduler thread] [INFO ] - debug: stop any due recordings
[2013-12-23 23:00:11,636] [Log    ] [scheduler thread] [INFO ] - Scheduler: stop record Channel 4 23/12/2013 21:53:08-23/12/2013 22:50:00 Fresh Meat
[2013-12-23 23:00:11,638] [Log    ] [scheduler thread] [INFO ] - card: StopRecording card=3, user=scheduler119
[2013-12-23 23:00:11,641] [Log    ] [scheduler thread] [INFO ] - basesubchannel.StopRecording 0
[2013-12-23 23:00:11,643] [Log    ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch=0, subch index=0
[2013-12-23 23:00:11,644] [Log    ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch:0-0 tswriter StopRecording...
[2013-12-23 23:00:11,652] [Log    ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2013-12-23 23:00:11,654] [Log    ] [scheduler thread] [INFO ] - DVB subch:0 Decompose()
[2013-12-23 23:00:11,665] [Log    ] [scheduler thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2013-12-23 23:00:11,666] [Log    ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2013-12-23 23:00:11,669] [Log    ] [scheduler thread] [INFO ] - dvb:StopGraph called
[2013-12-23 23:00:11,671] [Log    ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2013-12-23 23:00:11,672] [Log    ] [scheduler thread] [INFO ] - dvb:StopGraph
[2013-12-23 23:00:11,683] [Log    ] [scheduler thread] [DEBUG] - usermanagement.RemoveUser: scheduler119, subch: 0 of 0, card: 3
[2013-12-23 23:00:11,686] [Log    ] [scheduler thread] [INFO ] - user:scheduler119 remove
[2013-12-23 23:00:11,689] [Log    ] [scheduler thread] [INFO ] - dvb:StopGraph called
[2013-12-23 23:00:11,690] [Log    ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2013-12-23 23:00:11,692] [Log    ] [scheduler thread] [INFO ] - dvb:StopGraph filterstate already stopped, returning.
[2013-12-23 23:00:11,696] [Log    ] [Channel state thread] [DEBUG] - Controller: DoSetChannelStates for 40 channels
[2013-12-23 23:00:11,697] [Log    ] [Channel state thread] [INFO ] - ChannelStates.DoSetChannelStates took 1 msec
[2013-12-23 23:00:11,698] [Log    ] [scheduler thread] [INFO ] - Controller: epg start
[2013-12-23 23:00:11,701] [EPG    ] [scheduler thread] [INFO ] - EPG: grabber disabled
[2013-12-23 23:00:11,724] [Log    ] [scheduler thread] [INFO ] - diskmanagement: recording Fresh Meat ended. type:Once max episodes:2147483647
[2013-12-23 23:00:11,745] [Log    ] [scheduler thread] [DEBUG] - ThumbProcessor.OnTvServerEvent: Enqueue recording E:\Recorded TV\Channel 4\Fresh Meat\Fresh Meat - 2013-12-23.ts
[2013-12-23 23:00:11,747] [Log    ] [scheduler thread] [INFO ] - debug: start any due recordings
[2013-12-23 23:00:11,748] [Log    ] [14      ] [INFO ] - ThumbProcessor.DoWork: Creating thumb for E:\Recorded TV\Channel 4\Fresh Meat\Fresh Meat - 2013-12-23.ts
[2013-12-23 23:00:11,750] [Log    ] [14      ] [DEBUG] - TvThumbnails.VideoThumbCreator: preGapSec: 60
[2013-12-23 23:00:11,771] [Log    ] [scheduler thread] [INFO ] - debug: check and delete orphaned recordings
[2013-12-23 23:00:11,772] [Log    ] [scheduler thread] [INFO ] - debug: grabbing recording card list
[2013-12-23 23:00:11,773] [Log    ] [scheduler thread] [INFO ] - debug: got card list
[2013-12-23 23:00:11,775] [Log    ] [scheduler thread] [INFO ] - debug: card list count = 0
[2013-12-23 23:00:11,776] [Log    ] [scheduler thread] [INFO ] - debug: reached end of loop, returning
[2013-12-23 23:00:11,778] [Log    ] [scheduler thread] [INFO ] - debug: check and delete orphaned once schedules
[2013-12-23 23:00:11,780] [Log    ] [scheduler thread] [INFO ] - debug: handle sleep mode
[2013-12-23 23:00:11,782] [Log    ] [scheduler thread] [INFO ] - debug: work complete
[2013-12-23 23:00:11,783] [Log    ] [scheduler thread] [INFO ] - debug: scheduler worker loop end
[2013-12-23 23:00:11,786] [Log    ] [scheduler thread] [INFO ] - debug: scheduler worker loop start
[2013-12-23 23:00:11,949] [Log    ] [14      ] [DEBUG] - MediaInfoWrapper.MediaInfoWrapper: Inspecting media : E:\Recorded TV\Channel 4\Fresh Meat\Fresh Meat - 2013-12-23.ts
[2013-12-23 23:00:11,950] [Log    ] [14      ] [DEBUG] - MediaInfoWrapper.MediaInfoWrapper: VideoDuration    : 4022440
[2013-12-23 23:00:11,952] [Log    ] [14      ] [DEBUG] - E:\Recorded TV\Channel 4\Fresh Meat\Fresh Meat - 2013-12-23.ts duration is 4022, TimeIntBwThumbs is 1981
[2013-12-23 23:00:12,537] [Log    ] [14      ] [DEBUG] - TvThumbnails.VideoThumbCreator: thumb creation -loglevel quiet -ss 60 -i "E:\Recorded TV\Channel 4\Fresh Meat\Fresh Meat - 2013-12-23.ts" -y -ss 3 -vf yadif=0:-1:0,scale=600:337,setsar=1:1,tile=1x1 -vframes 1 -vsync 0 -an "C:\Windows\TEMP\Fresh Meat - 2013-12-23_0.jpg"
[2013-12-23 23:00:12,550] [Log    ] [14      ] [DEBUG] - CreateTileThumb: before Saving thumb! tmpFile: C:\Windows\TEMP\tmp886B.tmp
[2013-12-23 23:00:12,556] [Log    ] [14      ] [DEBUG] - CreateTileThumb: Saving thumb!
[2013-12-23 23:00:12,588] [Log    ] [14      ] [DEBUG] - CreateTileThumb: after Saving thumb!
[2013-12-23 23:00:12,691] [Log    ] [14      ] [DEBUG] - TvThumbnails.VideoThumbCreator: thumb creation success C:\Windows\TEMP\Fresh Meat - 2013-12-23.jpg
[2013-12-23 23:00:13,227] [Log    ] [14      ] [INFO ] - ThumbProcessor.DoWork: Thumbnail successfully created for - E:\Recorded TV\Channel 4\Fresh Meat\Fresh Meat - 2013-12-23.ts
[2013-12-23 23:00:26,788] [Log    ] [scheduler thread] [INFO ] - debug: stop any due recordings
[2013-12-23 23:00:26,788] [Log    ] [scheduler thread] [INFO ] - debug: start any due recordings
[2013-12-23 23:00:26,820] [Log    ] [scheduler thread] [INFO ] - debug: check and delete orphaned recordings
[2013-12-23 23:00:26,821] [Log    ] [scheduler thread] [INFO ] - debug: grabbing recording card list
[2013-12-23 23:00:26,823] [Log    ] [scheduler thread] [INFO ] - debug: got card list
[2013-12-23 23:00:26,824] [Log    ] [scheduler thread] [INFO ] - debug: card list count = 0
[2013-12-23 23:00:26,825] [Log    ] [scheduler thread] [INFO ] - debug: reached end of loop, returning

Thanks again

 

[mm1352000]

Big thanks lewiskingy - your persistence really is much appreciated!

Don't know if this is the most useful section, but I was interested that the "card list count" drops from 1 to 0 in this short section. Unsure if that is to be expected.

The card count is the number of tuners which are recording. As you can see, a recording is stopped between those two checks. Hence the change in count.

What I look for is the last reference to "debug: " (case sensitive). I find that here:

[2013-12-24 12:36:32,235] [Log ] [scheduler thread] [INFO ] - debug: scheduler worker loop start
[2013-12-24 12:36:47,236] [Log ] [scheduler thread] [INFO ] - debug: stop any due recordings
[2013-12-24 12:36:47,238] [Log ] [scheduler thread] [INFO ] - debug: start any due recordings
[2013-12-24 12:36:47,353] [Log ] [scheduler thread] [INFO ] - debug: check and delete orphaned recordings
[2013-12-24 12:36:47,354] [Log ] [scheduler thread] [INFO ] - debug: grabbing recording card list
[2013-12-24 12:36:47,584] [Log ] [scheduler thread] [INFO ] - debug: got card list
[2013-12-24 12:36:47,586] [Log ] [scheduler thread] [INFO ] - debug: card list count = 2
[2013-12-24 12:36:47,588] [Log ] [scheduler thread] [INFO ] - debug: card TBS 6981 BDA DVBS/S2 A Tuner/Demod
[2013-12-24 12:36:47,590] [Log ] [scheduler thread] [INFO ] - debug: schedule 107
[2013-12-24 12:36:47,591] [Log ] [scheduler thread] [INFO ] - debug: get schedule
[2013-12-24 12:36:47,593] [Log ] [scheduler thread] [INFO ] - debug: got schedule
[2013-12-24 12:36:47,594] [Log ] [scheduler thread] [INFO ] - debug: done stop
[2013-12-24 12:36:47,595] [Log ] [scheduler thread] [INFO ] - debug: done check
[2013-12-24 12:36:47,598] [Log ] [scheduler thread] [INFO ] - debug: card TBS 6981 BDA DVBS/S2 B Tuner/Demod
[2013-12-24 12:36:47,599] [Log ] [scheduler thread] [INFO ] - debug: schedule 104
[2013-12-24 12:36:47,601] [Log ] [scheduler thread] [INFO ] - debug: get schedule
[2013-12-24 12:36:47,602] [Log ] [scheduler thread] [INFO ] - debug: got schedule
[2013-12-24 12:36:47,603] [Log ] [scheduler thread] [INFO ] - debug: done stop
[2013-12-24 12:36:47,605] [Log ] [scheduler thread] [INFO ] - debug: done check
[2013-12-24 12:36:47,606] [Log ] [scheduler thread] [INFO ] - debug: reached end of loop, returning
[2013-12-24 12:36:47,607] [Log ] [scheduler thread] [INFO ] - debug: check and delete orphaned once schedules
[2013-12-24 12:36:47,608] [Log ] [scheduler thread] [INFO ] - debug: handle sleep mode
[2013-12-24 12:36:47,610] [Log ] [scheduler thread] [INFO ] - debug: work complete
[2013-12-24 12:36:47,611] [Log ] [scheduler thread] [INFO ] - debug: scheduler worker loop end
[2013-12-24 12:36:47,617] [Log ] [scheduler thread] [INFO ] - debug: scheduler worker loop start
[2013-12-24 12:37:02,618] [Log ] [scheduler thread] [INFO ] - debug: stop any due recordings
[2013-12-24 12:37:02,622] [Log ] [scheduler thread] [INFO ] - debug: start any due recordings
[2013-12-24 12:37:02,705] [Log ] [scheduler thread] [INFO ] - debug: check and delete orphaned recordings
[2013-12-24 12:37:02,706] [Log ] [scheduler thread] [INFO ] - debug: grabbing recording card list
[2013-12-24 12:37:02,944] [Log ] [scheduler thread] [INFO ] - debug: got card list
[2013-12-24 12:37:02,945] [Log ] [scheduler thread] [INFO ] - debug: card list count = 2
[2013-12-24 12:38:05,118] [Log ] [12 ] [DEBUG] - Debug: SSDPClientController: Problem parsing incoming multicast UDP packet. Error message: 'Invalid HTTP header line '''
[2013-12-24 12:39:01,762] [Log ] [11 ] [DEBUG] - Debug: SSDPClientController: Problem parsing incoming multicast UDP packet. Error message: 'Invalid HTTP header line '''
[2013-12-24 12:43:03,736] [Log ] [11 ] [DEBUG] - Debug: SSDPClientController: Problem parsing incoming multicast UDP packet. Error message: 'Invalid HTTP header line '''
[2013-12-24 12:44:00,964] [Log ] [11 ] [DEBUG] - Debug: SSDPClientController: Problem parsing incoming multicast UDP packet. Error message: 'Invalid HTTP header line '''
[2013-12-24 12:45:01,693] [Log ] [12 ] [DEBUG] - Debug: SSDPClientController: Problem parsing incoming multicast UDP packet. Error message: 'Invalid HTTP header line '''
[2013-12-24 12:45:01,699] [Log ] [18 ] [DEBUG] - Detecting BDA/WDM devices...
[2013-12-24 12:45:01,701] [Log ] [18 ] [DEBUG] - Detect legacy AM filter devices
[2013-12-24 12:45:02,382] [Log ] [18 ] [DEBUG] - Detect AM KS crossbar devices
[2013-12-24 12:45:02,488] [Log ] [18 ] [DEBUG] - Detect AM KS TV tuner devices
[2013-12-24 12:45:02,549] [Log ] [18 ] [DEBUG] - Detect BDA source devices

(PS: Ignore the "problem parsing incoming..." messages.)

So, last entry is:

[2013-12-24 12:37:02,945] [Log ] [scheduler thread] [INFO ] - debug: card list count = 2

This is just bizarre!
I think we can say that the log buffering is not a factor now. I should have realised previously that the same logger continues to be used by the main TV service thread, so that would flush all the entries from the scheduler thread.

I find the code for the VirtualCard class interesting. All the functions/properties use RemoteControl. Take the Name function for example:

  [XmlIgnore]
  public string Name
  {
    get
    {
      try
      {
        if (User.CardId < 0)
        {
          return "";
        }
        RemoteControl.HostName = _server;
        return RemoteControl.Instance.CardName(User.CardId);
      }
      catch (Exception)
      {
        HandleFailure();
      }
      return "";
    }
  }

I wonder if there could be something network related in this problem... or whether that log entry I added is actually distorting the problem.

mm

 

[lewiskingy]

Since there are no log messages after that, are you thinking the scheduler thread is hanging on one of two statements below?

foreach (VirtualCard vCard in vCards)
      {
        Log.Write("debug: card {0}",vCard.Name)

 

[mm1352000]

Since there are no log messages after that, are you thinking the scheduler thread is hanging on one of two statements below?

Yes, exactly.