TBS: CI/CAM support and other improvements (2 Viewers)

[mm1352000]

Pls. find attached the TV Server log, I have yet to run it again with watchdog for full logs.

Sorry, the TV service log doesn't contain any useful information. I'll need to wait for the watchdog logs.
It is ~11:15 pm here in New Zealand and I have work in the morning, so I'll be going to bed soon. I'll try to remember to check this thread tomorrow.

 

[Syrel]

Sorry for the late reply, I was busy debugging together with TBS.
Based on our findings, it seems that the driver is working properly. With DVBDream the card delivers stream upon resume.
However, TBS found that also on their test environment MediaPortal does exactly the same as on my side (no stream after resume).
Their best guess was that something around initialization MP TV Server does on resume might somehow render the driver unresponsive.

I'll find some time later to collect full logs again and upload them here.

 

[mm1352000]

No problem.
I'm quite busy with a range of things at the moment, but I'll try to find some time to look at your logs when you post them.

 

[madmat17]

Does MP 1.11 still need to be patched in order to get the TBS CI working properly, or has the patch already been applied to the new versions?
Thx, Mat

Edit:
Missed the code freeze message on the previous page - sorry.

 

[Syrel]

No problem.
I'm quite busy with a range of things at the moment, but I'll try to find some time to look at your logs when you post them.

In the meantime I've received another driver version from TBS. They swear it works with all players on their machine, and apparently on my machine as well (e.g. with DvbDream standby/resume works like a charm). They also tried to analyze what MP might be doing differently compared to DvbDream, but could not find anything. So it should be something internal to TVService.

Now, with the newest driver, the symptom is that after resume MP locks up when trying to switch to TV mode. I needed to shut it down from Task Manager.
Again, interesting thing is that when the card is "locked" after resume, if I shut down the TVService, and disable/re-enable the card from Device Manager, everything starts to work fine.

Attached full logs, hopefully you can make something out of them.

 

[mm1352000]

Attached full logs...

I'm not seeing the attachment...

 

[Syrel]

Attached full logs...

I'm not seeing the attachment...

Hahh, this is easy to debug. That's because I'm dumb.
Edited my message, now attachment should be there...

 

[mm1352000]

Thanks, got 'em.

First, apologies for the length of this response. The TV service logs are complex and need a full response.

At 8:48 the PC resumes for the first time after sleeping overnight.
[2015-04-25 22:22:11,450] [Log ] [PowerEventThread] [DEBUG] - PS: Send "EnteringStandby" event
...
[2015-04-26 08:47:51,268] [Log ] [PowerEventThread] [DEBUG] - OnPowerEvent: PowerStatus: ResumeAutomatic

After approximately one minute I see that the TV service is stopped. There were no attempts to tune any channels between resume and stop. If you were having a problem at that time it must have been a MediaPortal [client side] problem. Unfortunately those MediaPortal log files are not preserved so I can't investigate further.
[2015-04-26 08:49:48,780] [Log ] [TVService] [INFO ] - TV Service: stopped

TV service is started again:
[2015-04-26 08:50:28,160] [Log ] [8 ] [INFO ] - TV Service: Starting

You try to tune AXN several times:
[collapse]
[2015-04-26 08:50:52,210] [Log ] [12 ] [INFO ] - Controller: find free card for channel AXN
[2015-04-26 08:50:52,210] [Log ] [12 ] [INFO ] - Controller: find card for channel AXN
[2015-04-26 08:50:52,220] [Log ] [12 ] [INFO ] - Controller: got 1 tuning details for AXN
[2015-04-26 08:50:52,220] [Log ] [12 ] [INFO ] - Controller: channel #1 DVBC:tv:Biatv AXN Freq:402000 ONID:1 TSID:543 SID:301 PMT:0x50 FTA:True LCN:6 SymbolRate:6952 Modulation:Mod256Qam
[2015-04-26 08:50:52,220] [Log ] [12 ] [INFO ] - Controller: card:1 type:RadioWebStream cannot tune to channel
[2015-04-26 08:50:52,230] [Log ] [12 ] [INFO ] - Controller: card:2 typevbIP cannot tune to channel
[2015-04-26 08:50:52,230] [Log ] [12 ] [INFO ] - Controller: found 0 card(s) for channel[/collapse]

The tuner is not available so it fails. Perhaps you had disabled the driver and forgot to enable it, I don't know. This is not TV Server's problem though.

TV service is stopped and started again:
[2015-04-26 08:51:38,944] [Log ] [TVService] [INFO ] - TV Service: stopped
...
[2015-04-26 08:52:21,321] [Log ] [8 ] [INFO ] - TV Service: Starting

This time the tuner is detected:
[2015-04-26 08:52:31,977] [Log ] [TVService] [INFO ] - Detected new digital BDA tuner device TBS 6618 BDA DVBC Tuner @devicenp:\\?\pci#ven_1131&dev_7160&subsys_00016618&rev_03#4&3036a63b&0&00a8#{71985f48-1ca1-11d3-9cc8-00c04f7971e0}\{353e20b5-4b13-4db0-b84e-1e6f00040000}

You successfully tune AXN and AXN Black:
[2015-04-26 08:53:25,765] [Log ] [26 ] [INFO ] - Controller: find free card for channel AXN
...
[2015-04-26 08:53:26,565] [Log ] [26 ] [INFO ] - card: WaitForFile - video and audio are seen after 0.02 seconds
...
[2015-04-26 08:53:39,449] [Log ] [26 ] [INFO ] - Controller: find free card for channel AXN Black
...
[2015-04-26 08:53:40,299] [Log ] [26 ] [INFO ] - card: WaitForFile - video and audio are seen after 0 seconds

You suspend and resume the PC:
[2015-04-26 08:53:59,620] [Log ] [PowerEventThread] [DEBUG] - OnPowerEvent: PowerStatus: Suspend
...
[2015-04-26 08:54:14,030] [Log ] [PowerEventThread] [DEBUG] - OnPowerEvent: PowerStatus: ResumeAutomatic

You try to tune AXN White, but the tuner has not been detected so it fails:
[collapse]
[2015-04-26 08:54:20,347] [Log ] [26 ] [INFO ] - Controller: find free card for channel AXN White
[2015-04-26 08:54:20,347] [Log ] [26 ] [INFO ] - Controller: find card for channel AXN White
[2015-04-26 08:54:20,347] [Log ] [26 ] [INFO ] - Controller: got 1 tuning details for AXN White
[2015-04-26 08:54:20,347] [Log ] [26 ] [INFO ] - Controller: channel #1 DVBC:tv:Biatv AXN White Freq:402000 ONID:1 TSID:543 SID:303 PMT:0x51 FTA:True LCN:7 SymbolRate:6952 Modulation:Mod256Qam
[2015-04-26 08:54:20,347] [Log ] [26 ] [INFO ] - Controller: found 0 card(s) for channel[/collapse]

The tuner was not detected until this time:
[2015-04-26 08:54:29,127] [Log ] [PowerEventThread] [INFO ] - Detected new digital BDA tuner device TBS 6618 BDA DVBC Tuner @devicenp:\\?\pci#ven_1131&dev_7160&subsys_00016618&rev_03#4&3036a63b&0&00a8#{71985f48-1ca1-11d3-9cc8-00c04f7971e0}\{353e20b5-4b13-4db0-b84e-1e6f00040000}

That's because you've added a 10 second delay for tuner detection:
[2015-04-26 08:54:19,097] [Log ] [PowerEventThread] [INFO ] - Controller: delaying device detection for 10 second(s)

So, you need to be more patient.

Shortly after, you try to tune AXN Black successfully... which shows there was nothing wrong with the tuner or TV service:
[2015-04-26 08:54:29,837] [Log ] [27 ] [INFO ] - Controller: find free card for channel AXN Black
...
[2015-04-26 08:54:30,927] [Log ] [27 ] [INFO ] - card: WaitForFile - video and audio are seen after 0.1100002 seconds

Then there's a 5 minute gap in the logs. The next thing I see is TV service restarting:
[2015-04-26 08:59:20,469] [Log ] [8 ] [INFO ] - TV Service: Starting
...
[2015-04-26 08:59:43,479] [Log ] [TVService] [INFO ] - TV Service: stopped
...
[2015-04-26 09:00:08,372] [Log ] [8 ] [INFO ] - TV Service: Starting

You try to tune DOQ:
[2015-04-26 09:00:33,532] [Log ] [7 ] [INFO ] - Controller: find free card for channel DOQ

This fails with a generic error:
[2015-04-26 09:00:33,582] [Log ] [7 ] [INFO ] - dvb: RunGraph returns: 0x8007001F

I presume this error comes from the driver because it doesn't come from TV Server. There's nothing more that I can say about it, so if you want to know more you'll have to ask TBS.

Same error for TV2 and Spektrum... so you enable preloading (IMHO a bad idea) and restart the TV service:
[2015-04-26 09:01:14,362] [Log ] [7 ] [INFO ] - Controller: Initializing TVServer
...
[2015-04-26 09:01:24,532] [Log ] [7 ] [INFO ] - Controller: preloading device

Tuning DOQ still fails with the same tuner driver error:
[2015-04-26 09:01:31,972] [Log ] [7 ] [INFO ] - Controller: find free card for channel DOQ
...
[2015-04-26 09:01:32,022] [Log ] [7 ] [INFO ] - dvb: RunGraph returns: 0x8007001F

Same for M2 HD.

Another 30 second gap in the log files and TV service is starting again:
[2015-04-26 09:02:29,604] [Log ] [8 ] [INFO ] - TV Service: Starting

You try to tune AXN White, but still the same tuner driver error:
[2015-04-26 09:02:53,124] [Log ] [12 ] [INFO ] - Controller: find free card for channel AXN White
...
[2015-04-26 09:02:53,184] [Log ] [12 ] [INFO ] - dvb: RunGraph returns: 0x8007001F

After this you check the CAM menu:
[2015-04-26 09:03:38,024] [Log ] [7 ] [DEBUG] - Turbosight: enter menu

There's no problem with that, so you restart the TV service again (...or maybe you restart the PC or tuner driver):
[2015-04-26 09:05:25,264] [Log ] [TVService] [INFO ] - TV Service: stopped
...
[2015-04-26 09:08:43,768] [Log ] [8 ] [INFO ] - TV Service: Starting

Now tuning DOQ is successful:
[2015-04-26 09:09:02,748] [Log ] [24 ] [INFO ] - Controller: find free card for channel DOQ
...
[2015-04-26 09:09:03,568] [Log ] [24 ] [INFO ] - card: WaitForFile - video and audio are seen after 0.0200001 seconds

Spektrum and Film+ are also fine, so you try to suspend and resume again:
[2015-04-26 09:11:53,400] [Log ] [PowerEventThread] [DEBUG] - OnPowerEvent: PowerStatus: Suspend
...
[2015-04-26 09:12:02,732] [Log ] [PowerEventThread] [DEBUG] - OnPowerEvent: PowerStatus: ResumeAutomatic

Film+ fails with a PMT error:
[2015-04-26 09:12:26,037] [Log ] [26 ] [INFO ] - Controller: find card for channel Film+
...
[2015-04-26 09:12:34,675] [Log ] [31 ] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 4.0012289 seconds. Increase the PMT timeout value?

I can only guess that the tuner was not delivering a stream or your timeout value is too low.

Tuning of CNBC Europe is successful after one timeout:
[2015-04-26 09:12:42,255] [Log ] [7 ] [INFO ] - Controller: find card for channel CNBC Europe
...
[2015-04-26 09:12:47,005] [Log ] [7 ] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 4.0000056 seconds. Increase the PMT timeout value?
...
[2015-04-26 09:12:49,855] [Log ] [7 ] [DEBUG] - WaitForPMT: Found PMT after 2.8500039 seconds.
...
[2015-04-26 09:12:50,045] [Log ] [7 ] [INFO ] - card: WaitForFile - video and audio are seen after 0.1700002 seconds

Another gap in the logs and TV service is restarted again:
[2015-04-26 09:13:55,150] [Log ] [8 ] [INFO ] - TV Service: Starting
...
[2015-04-26 09:15:21,340] [Log ] [TVService] [INFO ] - TV Service: stopped
...
[2015-04-26 09:15:43,260] [Log ] [8 ] [INFO ] - TV Service: Starting

Tuning AXN Black is successful:
[2015-04-26 09:16:05,910] [Log ] [7 ] [INFO ] - Controller: find free card for channel AXN Black
...
[2015-04-26 09:16:06,860] [Log ] [7 ] [INFO ] - card: WaitForFile - video and audio are seen after 0.1000001 seconds

Film+ is good:
[2015-04-26 09:16:57,180] [Log ] [9 ] [INFO ] - Controller: find free card for channel Film+
...
[2015-04-26 09:16:58,040] [Log ] [9 ] [INFO ] - card: WaitForFile - video and audio are seen after 0.0300001 seconds

This corresponds with the first tune request in the MediaPortal log:
[2015-04-26 09:16:57,090] [Log ] [MPMain ] [INFO ] - TVHome.ViewChannelAndCheck(): View channel=Film+
...
[2015-04-26 09:17:00,451] [Log ] [52 ] [DEBUG] - ViewModeSwitcher: OnVideoReceived()

A final suspend + resume:
[2015-04-26 09:17:15,638] [Log ] [PowerEventThread] [DEBUG] - OnPowerEvent: PowerStatus: Suspend
...
[2015-04-26 09:17:29,749] [Log ] [PowerEventThread] [DEBUG] - OnPowerEvent: PowerStatus: ResumeAutomatic

...and now we see the final Film+ test:
[2015-04-26 09:17:53,825] [Log ] [MPMain ] [INFO ] - TVHome.ViewChannelAndCheck(): View channel=Film+

[2015-04-26 09:17:53,825] [Log ] [24 ] [INFO ] - Controller: find free card for channel Film+
...
[2015-04-26 09:17:54,615] [Log ] [4 ] [DEBUG] - WaitForPMT: Waiting for PMT 5A

MediaPortal locks up because the TV service crashes during the tune request. The Windows application event log shows the crash and the cause:
[collapse]
"4/26/2015 9:17:56 AM";".NET Runtime";"(0)";"Error";"Application: TVService.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: exception code c0000005, exception address 06721B8C
";"1026"
"4/26/2015 9:17:57 AM";"Application Error";"Application Crashing Events";"Error";"Faulting application name: TVService.exe, version: 1.10.0.0, time stamp: 0x548c1072 Faulting module name: TBSCiApi0.dll, version: 1.0.1.4, time stamp: 0x52a03063 Exception code: 0xc0000005 Fault offset: 0x00011b8c Faulting process id: 0x16e4 Faulting application start time: 0x01d07ff0ce8d8f80 Faulting application path: C:\Program Files (x86)\Team MediaPortal\MediaPortal TV Server\TVService.exe Faulting module path: C:\Program Files (x86)\Team MediaPortal\MediaPortal TV Server\TBSCiApi0.dll Report Id: 5c4e37de-ebe4-11e4-90fe-08606e7042fa";"1000"
"4/26/2015 9:17:57 AM";"Windows Error Reporting";"(0)";"Information";"Fault bucket , type 0 Event Name: APPCRASH Response: Not available Cab Id: 0 Problem signature: P1: TVService.exe P2: 1.10.0.0 P3: 548c1072 P4: TBSCiApi0.dll P5: 1.0.1.4 P6: 52a03063 P7: c0000005 P8: 00011b8c P9: P10: Attached files: These files may be available here: C:\ProgramData\Microsoft\Windows\WER\ReportQueue\AppCrash_TVService.exe_1e5396df96b3f8e5bee03bafcb5da08bbd6435ce_056c5763 Analysis symbol: Rechecking for solution: 0 Report Id: 5c4e37de-ebe4-11e4-90fe-08606e7042fa Report Status: 4";"1001"
"4/26/2015 9:18:02 AM";"Windows Error Reporting";"(0)";"Information";"Fault bucket , type 0 Event Name: APPCRASH Response: Not available Cab Id: 0 Problem signature: P1: TVService.exe P2: 1.10.0.0 P3: 548c1072 P4: TBSCiApi0.dll P5: 1.0.1.4 P6: 52a03063 P7: c0000005 P8: 00011b8c P9: P10: Attached files: These files may be available here: C:\ProgramData\Microsoft\Windows\WER\ReportQueue\AppCrash_TVService.exe_1e5396df96b3f8e5bee03bafcb5da08bbd6435ce_056c5763 Analysis symbol: Rechecking for solution: 0 Report Id: 5c4e37de-ebe4-11e4-90fe-08606e7042fa Report Status: 0";"1001"[/collapse]

Note the source of the crash is in TBSCiApi0.dll, which is the TBS DLL for CI support. We have no control over the code in that DLL so in most cases you would need to get help from TBS if there are problems with it. The only hint I can offer is that I've seen crashes with that DLL before, and they were caused by the way that the TV service was reinitialised/started/stopped. The DLL fails to unload itself properly in certain cases. You could try to use the attached DLL instead of the one that was included with the patch. If this doesn't help then the problem will have to be raised with TBS.

Regards,
mm

 

[Syrel]

You could try to use the attached DLL instead of the one that was included with the patch.

Wow, you are a magician! I've replaced the DLL, and also based on your suggestion, I've unchecked the "enable preload..." option in TV Server settings. It seems to be working now. I did a couple of standby / resume cycles, and until now there was no freeze, and TV stream was able to restart properly. I hope it stays like this.

I'm truly grateful for your help, thanks a million!

 

[mm1352000]

You're welcome... but don't thank me too quickly.
When you tested, were you testing the tuner before standby and after resume? I hope you were... in which case: YAY, problem solved!