[confirm] MP frozen (1 Viewer)

[c 4]

Hi all,

I am running 2 PCs: a client&server (HTPC) with MP 1.5.0 Pre and the patches listed below and a client (PC) running MP 1.4.0.
Today I used the client to check and schedule some recordings. That went well, but when I tried switching on Live-TV, I could not get an image - no error message. After that MP 1.4.0 seemed frozen and I could not close it - the window did not react so I had to use the windows task manager.

Next I had a look at the HTPC and found that MP 1.5.0 Pre GUI was frozen - it displayed 5:32, 7.Oct although it was 21:39 on the same day. It was in standby before, so that is functioning, but after 5:32 it did not wake up for any of the scheduled recordings.

After I had killed MP on the HTPC, I tried starting MP, but it loaded only until it reached "Starting Plugins..." after some minutes without change, I killed the MP task again (I have no plugins installed).
From the windows taskmanager, there seemed to be no problem with TVService, but when I tried 'net stop tvservice', I got the response "TVService could not be stopped" (this is my translation of the error message, I am not sure what the equivalent english message would be), so I had to restart the HTPC. After this it worked again - but how long till the next freeze ?

I am using these patches by mm1352000 on the HTPC with 1.5.0Pre:
- TsWriter_mm_deadlock_v6_[mp_1.5pr].zip [containing TVLibrary.dll, TvService.exe] from https://forum.team-mediaportal.com/...ock-potential-fix.114898/page-22#post-1027148
- TsWriter_mm_deadlock_v5_[mp_1.5pr].zip [containing TsWriter.ax] from https://forum.team-mediaportal.com/...ock-potential-fix.114898/page-21#post-1026741

I tried to make a useful selection of the logfiles, it would be too much for my connection otherwise. If you need anything else, please ask.

[attachment removed]

 

[mm1352000]

First, thanks for reporting c4.
I'd prefer it if you had posted in the TsWriter deadlock thread where you got the patch from... because unfortunately it seems the problem here is related.

I think the start of the problem is here:

[2013-10-07 00:44:24,085] [EPG ] [20 ] [INFO ] - Epg: card:3 received epg for 17 channels
[2013-10-07 00:44:24,085] [EPG ] [EPG Update thread] [INFO ] - Epg: card:3 Updating database with new programs
...
[2013-10-07 00:44:33,117] [EPG ] [EPG Update thread] [INFO ] - Epg: card:3 Finished updating the database.
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - EPG: database updated for #0 ServusTV Deutschland
[2013-10-07 00:44:33,117] [EPG ] [EPG Update thread] [INFO ] - EpgCard: card: 3 stop grabbing
[2013-10-07 00:44:33,117] [EPG ] [EPG Update thread] [INFO ] - EpgGrabbing: Stop - user epg
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - user:epg remove
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - DVB subch:0 Decompose()
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - dvbtopGraph called
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - tvcard:FreeAllSubChannels
[2013-10-07 00:44:33,117] [Log ] [EPG Update thread] [INFO ] - dvbtopGraph

07-10-2013 00:44:33.117 debug: DeleteChannel()
07-10-2013 00:44:33.117 del m_pVideoAnalyzer
07-10-2013 00:44:33.117 analyzer: reset
07-10-2013 00:44:33.117 del m_pPmtGrabber
07-10-2013 00:44:33.117 del m_pRecorder
07-10-2013 00:44:33.117 del m_pTimeShifting
07-10-2013 00:44:33.117 del m_pTeletextGrabber
07-10-2013 00:44:33.117 del m_pCaGrabber
07-10-2013 00:44:33.117 del done...
07-10-2013 00:44:33.117 epg: reset
07-10-2013 00:44:33.117 epg:ResetEPG()
07-10-2013 00:44:33.117 mhw reset
07-10-2013 00:44:33.117 CMpTsFilter:ause()
07-10-2013 00:44:33.117 Pause filter...
07-10-2013 00:44:33.117 HRESULT = 0x0
07-10-2013 00:44:33.179 CMpTsFilter:top()
07-10-2013 00:44:33.179 Stop streaming...
07-10-2013 00:44:33.179 Stop filter...
07-10-2013 00:44:33.179 HRESULT = 0x0

It appears like the TsWriter filter is stopped successfully, but we know the graph itself is not completely and successfully stopped because we don't see the expected "debug: IMediaControl stopped! hr = 0x0 " entry at the end of the first set of entries. This issue could be caused by failure to stop any upstream filter, or deadlock in the filter graph manager.

Soon after this your PC attempts to suspend:

[2013-10-07 00:46:31,162] [Log ] [PowerEventThread] [DEBUG] - OnPowerEvent: PowerStatus: Suspend
[2013-10-07 00:46:31,162] [Log ] [PowerEventThread] [DEBUG] - OnPowerEventHandler: PowerStatus: Suspend
[2013-10-07 00:46:31,162] [Log ] [PowerEventThread] [INFO ] - TvController.OnSuspend()
[2013-10-07 00:46:31,178] [Log ] [PowerEventThread] [INFO ] - Scheduler: stopped
[2013-10-07 00:46:31,194] [Log ] [PowerEventThread] [DEBUG] - Scheduler: thread stopped.
[2013-10-07 00:46:31,209] [Log ] [PowerEventThread] [INFO ] - Stopcard
[2013-10-07 00:46:31,209] [Log ] [PowerEventThread] [INFO ] - Stopcard
[2013-10-07 00:46:31,209] [Log ] [PowerEventThread] [INFO ] - dvbtopGraph called
[2013-10-07 00:46:31,209] [Log ] [PowerEventThread] [INFO ] - tvcard:FreeAllSubChannels

Unless I'm mistaken, it seems the attempt to free all subchannels gets caught in a deadlock... but this is very strange because there shouldn't be any subchannels left to free. The EPG grabber subchannel was already freed as we see in the above TsWriter log excerpt.

...but this is very very strange because we don't see any attempt to call DeleteChannel() in the TsWriter log - there is no "debug: DeleteChannel()". Hence it is like execution fails somewhere between the C# and C++ realms... or else the _graphbuilder is null, which would be just as strange:

 public override void StopGraph()
 {
   Log.Log.WriteFile("dvb:StopGraph called");
   if (!CheckThreadId())
     return;
   _epgGrabbing = false;
   _isScanning = false;
   FreeAllSubChannels();
   if (_mdplugs != null)
   {
     _mdplugs.FreeAllChannels();
   }
   if (_graphBuilder == null)
     return;
   if (_conditionalAccess.AllowedToStopGraph)
   {
     FilterState state;
     ((IMediaControl)_graphBuilder).GetState(10, out state);
     if (state == FilterState.Stopped)
     {
       Log.Log.WriteFile("dvb:StopGraph filterstate already stopped, returning.");
       return;
     }
     Log.Log.WriteFile("dvb:StopGraph");

What on earth is going on here...

Some time later we see that TV service attempts to start a recording:

[2013-10-07 01:49:04,095] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record ServusTV HD Deutschland 01:49-02:48 Hubble Mission Universum

What is most interesting is this:

[2013-10-07 01:49:04,126] [EPG ] [scheduler thread] [INFO ] - epg cancelled due to start recording
[2013-10-07 01:49:04,126] [EPG ] [scheduler thread] [INFO ] - epg grabber:epg cancelled
[2013-10-07 01:49:04,126] [EPG ] [scheduler thread] [INFO ] - EpgCard: card: 3 stop grabbing
[2013-10-07 01:49:04,126] [EPG ] [scheduler thread] [INFO ] - EpgGrabbing: Stop - user epg
[2013-10-07 01:49:04,126] [Log ] [scheduler thread] [INFO ] - user:epg remove
[2013-10-07 01:49:04,126] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 0 subch#0
[2013-10-07 01:49:04,126] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel :0 - sub channel not found
[2013-10-07 01:49:04,126] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2013-10-07 01:49:04,126] [Log ] [scheduler thread] [INFO ] - dvbtopGraph called
[2013-10-07 01:49:04,126] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels

I think this tells us that the service thought the EPG grabber was still running with subchannel 0.

It is all down-hill from there...
It will take some time to fully digest this information and figure out what could be happening. Please be patient with me...

 

[breese]

MM,
You might want to look at the Application Event Log. I go not read what looks to be german but...

"20.07.2013 20:55:02";"WinMgmt";"(0)";"Error";"Die Beschreibung für Ereignis-ID -1073741814 in Quelle WinMgmt wurde nicht gefunden. Der lokale Computer hat möglicherweise nicht die notwendigen Registrierungsinformationen oder Meldungs-DLL-Dateien, um die Meldung anzuzeigen, oder Sie sind nicht berechtigt, darauf zuzugreifen. Die folgenden Informationen sind Teil des Ereignisses:'//./root/CIMV2', 'SELECT * FROM __InstanceModificationEvent WITHIN 60 WHERE TargetInstance ISA "Win32_Processor" AND TargetInstance.LoadPercentage > 99', '0x80041003'";"3221225482"
"20.07.2013 20:56:01";"Software Protection Platform Service";"(0)";"Information";"Der Softwareschutzdienst wird gestartet. ";"1073742724"
"20.07.2013 20:56:02";"SecurityCenter";"(0)";"Information";"Der Windows-Sicherheitscenterdienst wurde gestartet.";"1"
"20.07.2013 20:56:06";"Software Protection Platform Service";"(0)";"Information";"Initialisierungsstatus für Dienstobjekte. C:\Windows\system32\sppwinob.dll, msft:spp/windowsfunctionality/agent/7.0, 0x00000000, 0x00000000
C:\Windows\system32\sppobjs.dll, msft:rm/algorithm/phone/1.0, 0x00000000, 0x00000000
C:\Windows\system32\sppobjs.dll, msft:rm/algorithm/pkey/2005, 0x00000000, 0x00000000
C:\Windows\system32\sppobjs.dll, msft:spp/TaskScheduler/1.0, 0x00000000, 0x00000000
C:\Windows\system32\sppobjs.dll, msft:spp/volume/services/kms/1.0, 0x00000000, 0x00000000
C:\Windows\system32\sppobjs.dll, msft:spp/volume/services/kms/licenserenewal/1.0, 0x00000000, 0x00000000
";"1073742890"

 

[Vasilich]

Breese there is nothing strange here just start of SPP.

 

[c 4]

Happened again - same patches/versions/settings etc:
MP GUI frozen, forced quit
Restart of MP: program stops responding at "Initializing input devices"
taskmgr stop TVService - no reaction
cmd net stop TVService - "TVService is being started or stopped. Please try again later" (my translation of the message) (same results multiple times)
taskmgr TVService status: stopping...

So I restarted the HTPC and here are the logs (partially shortened), hopefully helping you to pinpoint the cause of the problem:

[attachment removed]

 

[mm1352000]

Hello again c 4

These log files are interesting.
First, I should say that this looks like a different problem... but maybe related. We can see that suddenly the tuner starts to reject tune requests:

[2013-10-19 17:59:17,553] [Log ] [scheduler thread] [INFO ] - dvbubmit tunerequest calling put_TuneRequest
[2013-10-19 17:59:17,615] [Log ] [scheduler thread] [INFO ] - dvbubmitTuneRequest failed - subchannel: 0

So this seems to clearly be a problem with the tuner driver. Maybe TV Server is somehow causing it, but that is not clear. I note that @mcraenz is also having trouble with TBS tuners even though he is using this patch. Hmmmm...

In the application event log I also see lots of power events happen on the 19th:

"19.10.2013 15:20:27";"TV Server";"(0)";"Information";"PowerEvent wurde vom Dienst erfolgreich verarbeitet.";"0"

I wonder if the tuner driver has issues after many standby + resume cycles.

Unfortunately we don't actually log the HRESULT value from the put_TuneRequest() call so we could say "TBS, we think there is a problem with your drivers" but we have nothing to help them find or fix the problem. I'm not even convinced that the previous tune request is successful because there is a PMT timeout (maybe the driver was unable to start streaming). I will try to provide an updated TVLibrary.dll which logs the tuning HRESULT. Then we'll just have to wait and see if the problem occurs again. Which version of MP should I build the DLL for? I see you're still using MP 1.5 PR. Do you intend to upgrade to the final release?

mm

 

[c 4]

Hi mm,

since I don't have much time at the moment, I would rather stay with 1.5PR unless it would make it harder for you to find the problem.