MP 1.6 and HDHomerun Prime - not releasing / deactivating tuners when done. (1 Viewer)

[mm1352000]

Hello again T^2

Good to hear from you again...

So... Still getting some odd behavior even with the firewall turned off. Most of the time the channel changes are quick in MP. However, occasionally the channel change can take an excessive amount of time. Say Tuner 0 is currently active, command a new channel, and it just waits. While waiting Tuner 1 LED will start blinking and will remain blinking for some time after the channel change finally happens (eventually going out). Tuner 0's LED remains steady the whole time.

Okay, so I think I can see what you mean with the attempt to view National Geographic Wild HD (NgeoWildHD channel 81).

Something seems funky there.
It is taking a long time because TV Server is waiting for information about the available streams (video, audio, subtitles etc.). In technical terms this is known as "PMT" - program map table.

In that case:

[2014-01-24 22:07:27,893] [Log ] [24 ] [INFO ] - atsc:Tune:ATSC:tv:Cable WILDH__NATGEOWILD_HD Freq:565250 ONID:18968 TSID:0 SID:2841 PMT:0x31 FTA:False LCN:81 phys:81 maj:914 min:0 mod:Mod256Qam
[2014-01-24 22:07:27,893] [Log ] [24 ] [INFO ] - DRI CC: tune channel 914 "WILDH__NATGEOWILD_HD", sub channel ID 0
[2014-01-24 22:07:27,893] [Log ] [24 ] [DEBUG] - existing subchannel 0
[2014-01-24 22:07:27,893] [Log ] [24 ] [INFO ] - subch:0 OnBeforeTune
[2014-01-24 22:07:27,894] [Log ] [24 ] [DEBUG] - DRI CC: tuning...
[2014-01-24 22:07:27,911] [Log ] [13 ] [INFO ] - DRI CC: device 12 descrambling status update, old status = Possible, new status = Unknown
[2014-01-24 22:07:28,472] [Log ] [13 ] [INFO ] - DRI CC: device 12 descrambling status update, old status = Unknown, new status = Possible
[2014-01-24 22:07:28,579] [Log ] [24 ] [INFO ] - subch:0 OnAfterTune
[2014-01-24 22:07:28,580] [Log ] [24 ] [INFO ] - RunGraph
[2014-01-24 22:07:28,582] [Log ] [24 ] [INFO ] - DRI CC: signal locked immediately
[2014-01-24 22:07:28,582] [Log ] [24 ] [INFO ] - subch:0 OnGraphStart
[2014-01-24 22:07:28,583] [Log ] [24 ] [INFO ] - subch:0 Graph already running - WaitForPMT
[2014-01-24 22:07:28,584] [Log ] [24 ] [INFO ] - subch:0 SetupPmtGrabberid 31 sid:B19
[2014-01-24 22:07:28,585] [Log ] [24 ] [INFO ] - subch:0 set pmt grabber pmt:31 sid:B19
[2014-01-24 22:07:28,586] [Log ] [24 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
[2014-01-24 22:07:28,587] [Log ] [24 ] [DEBUG] - WaitForPMT: Waiting for PMT 31
[2014-01-24 22:07:38,587] [Log ] [24 ] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 10.000572 seconds. Increase the PMT timeout value?
[2014-01-24 22:07:38,588] [Log ] [24 ] [DEBUG] - Setting to 0 to search for new PMT.
[2014-01-24 22:07:38,588] [Log ] [24 ] [INFO ] - subch:0 SetupPmtGrabberid 0 sid:B19
[2014-01-24 22:07:38,589] [Log ] [24 ] [INFO ] - subch:0 set pmt grabber pmt:0 sid:B19
[2014-01-24 22:07:38,590] [Log ] [24 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
[2014-01-24 22:07:38,591] [Log ] [24 ] [DEBUG] - WaitForPMT: Waiting for PMT 0
[2014-01-24 22:07:45,886] [Log ] [9 ] [INFO ] - subch:0 OnPMTReceived() pmt:31 ran:True dynamic:False
[2014-01-24 22:07:45,887] [Log ] [24 ] [DEBUG] - WaitForPMT: Found PMT after 7.2954173 seconds.

TV Server sets up to grab the PMT information:

[2014-01-24 22:07:28,585] [Log ] [24 ] [INFO ] - subch:0 set pmt grabber pmt:31 sid:B19

After 10 seconds it hadn't been seen:

[2014-01-24 22:07:38,587] [Log ] [24 ] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 10.000572 seconds. Increase the PMT timeout value?

...so TV Server goes hunting:

[2014-01-24 22:07:38,588] [Log ] [24 ] [DEBUG] - Setting to 0 to search for new PMT.

...and 7 seconds later TV Server finds PMT where it was previously looking:

[2014-01-24 22:07:45,886] [Log ] [9 ] [INFO ] - subch:0 OnPMTReceived() pmt:31 ran:True dynamic:False
[2014-01-24 22:07:45,887] [Log ] [24 ] [DEBUG] - WaitForPMT: Found PMT after 7.2954173 seconds.

Very very strange!
It should not be taking 17+ seconds to receive PMT. If that were really happening it would indicate a non-compliant broadcast stream from your cable provider.

I wonder if your CableCARD is 100% healthy.
Could you please submit a support request to Silicondust and get them to check your log files and see if everything is A-OK.

mm

 

[T^2]

Very very strange!
It should not be taking 17+ seconds to receive PMT. If that were really happening it would indicate a non-compliant broadcast stream from your cable provider.

I wonder if your CableCARD is 100% healthy.
Could you please submit a support request to Silicondust and get them to check your log files and see if everything is A-OK.

mm

Ok... I posted on their forum here.

Should I also submit a trouble ticket? Or should that forum post be sufficient for something like this?

 

[mm1352000]

Ok... I posted on their forum here.

Thanks.
The comment about the CableCARD not having been validated is interesting. That is the level of detail that I'm not up to speed with and that I was hoping they'd be able to help you with.

Should I also submit a trouble ticket? Or should that forum post be sufficient for something like this?

I'd stick with a forum post for now. As the response says, the guys are really busy this weekend... so lets give them a chance to respond... and if they haven't followed up in say... a week... then I'd submit a trouble ticket.

 

[T^2]

Ok... I posted on their forum here.

Thanks.
The comment about the CableCARD not having been validated is interesting. That is the level of detail that I'm not up to speed with and that I was hoping they'd be able to help you with.

Should I also submit a trouble ticket? Or should that forum post be sufficient for something like this?

I'd stick with a forum post for now. As the response says, the guys are really busy this weekend... so lets give them a chance to respond... and if they haven't followed up in say... a week... then I'd submit a trouble ticket.

Sent a reply in that thread with my answers to the questions asked. We'll see what happens next.

 

[T^2]

Ok... I posted on their forum here.

Thanks.
The comment about the CableCARD not having been validated is interesting. That is the level of detail that I'm not up to speed with and that I was hoping they'd be able to help you with.

CableCard Validation issue has been resolved.

Still having the same channel change issue - occasional excessively long channel change.

 

[mm1352000]

CableCard Validation issue has been resolved.

Great.

Still having the same channel change issue - occasional excessively long channel change.

I'm watching your thread on the SD forum. If MP is doing something wrong I'll be happy to investigate... but to me it looks like the CableCARD is just slow to release the stream... and that is not something I'm able to deal with. SD are much beter CC experts than me so lets see what they say. Suffice to say it is not normal for MP or a PRIME.

 

[T^2]

CableCard Validation issue has been resolved.

Great.

Still having the same channel change issue - occasional excessively long channel change.

I'm watching your thread on the SD forum. If MP is doing something wrong I'll be happy to investigate... but to me it looks like the CableCARD is just slow to release the stream... and that is not something I'm able to deal with. SD are much beter CC experts than me so lets see what they say. Suffice to say it is not normal for MP or a PRIME.

Cool... Thanks...

Just a FYI... Couldn't get free last night long enough to be able to play with this. However, I'll make sure I'll get to it tonight.

 

[T^2]

CableCard Validation issue has been resolved.

Great.

Still having the same channel change issue - occasional excessively long channel change.

I'm watching your thread on the SD forum. If MP is doing something wrong I'll be happy to investigate... but to me it looks like the CableCARD is just slow to release the stream... and that is not something I'm able to deal with. SD are much beter CC experts than me so lets see what they say. Suffice to say it is not normal for MP or a PRIME.

So got a reply on the HDHomerun forum thread ( link ). Here is what he said:

22:31:15, HDHomeRun receives SetChannel command. Channel is tuned successfully and gets CCI unrestricted from the card, all within that same second. 22:31:36, HDHomeRun receives an AVTransport:stop on tuner0. 22:31:38, MP goes through the whole buildup and tuning process on tuner2. At no time was an RTSP Teardown received. The logs show that the stream on tuner0 was stopped due to receiving an ICMP reject from the PC, and based on the timing it looks like around when the AVTransport:stop happened. So, as far as I can tell, the HDHomeRun tuned and streamed successfully until MP stopped listening for it. Same pattern for the second instance. Think you're going to have to get that Wireshark capture and send it over to the MP guys to take a look.

I'm not familiar with Wireshark. Took a quick glance at it and it appears that a significant investment is required to learn how to put it to use. If I need to collect data with it, it might help to have a quick primer on what to do.

 

[mm1352000]

So got a reply on the HDHomerun forum thread ( link ).

Thanks. I've replied over on their forum.

I'm interested to know if this only happens with certain channels.

I'm not familiar with Wireshark. Took a quick glance at it and it appears that a significant investment is required to learn how to put it to use. If I need to collect data with it, it might help to have a quick primer on what to do.

It isn't as hard as it looks - honest!
Install it. Should be fairly straighforward (but ask if you get stuck).
When it first opens you should see something like this:

The first icon on the bar (under file) is the first port of call. That allows you to select your network connector/interface to capture from. You probably only have one, so just select that and click start. You should now be capturing. Not hard.
To stop the capture, click the red square icon.
To save: file > save or save as.
To start a new capture with the same interface click the green wave icon.

Really isn't too hard.

The only thing to keep in mind is that captures could get really big really quickly. So, when you're trying to capture this problem please don't just leave the capture going and tune + tune + tune until you hit the problem, then save and export. Ideally you'd start the capture and tune. If you don't hit the problem, stop MP, stop the capture and start over. If you do hit the problem, wait for MP to finally succeed with that tune request, then stop MP and stop and save the capture. Please also grab the MP/TV Server logs.

I note there are more sophisticated ways to save sections of the capture, but that is somewhat trickier to explain.

mm

 

[T^2]

Ok... Got a good capture.

Time: 09:17 EST
From channel: 876
To channel: 890

From channel (876) was on Tuner1. Tried to switch to channel 890 on Tuner 1 and failed. It then switched to Tuner0 and succeeded.

MP Logs and Wireshark capture attached.

In case it's worth something... the HDHomerun log:

19700101-00:00:00 System: reset reason = headend reset command
19700101-00:00:01 CableCARD: M-CARD inserted
19700101-00:00:02 System: network link 100f
19700101-00:00:05 CableCARD: Motorola card (0000:0625)
19700101-00:00:05 CableCARD: authentication status: authentication in progress
19700101-00:00:05 CableCARD: authentication status: authentication success, validation success
19700101-00:00:06 System: ip address obtained: 192.168.1.2 / 255.255.255.0
20140126-15:18:06 CableCARD: time changed from Thu Jan 01 00:00:44 1970 to Sun Jan 26 15:18:06 2014
20140126-15:18:52 CableCARD: Tuner1: vchannel 224 (135MHz-8) access = subscribed
20140126-15:18:56 CableCARD: Tuner0: vchannel 8 (537MHz-4035) access = subscribed
20140126-15:19:01 CableCARD: Tuner0: vchannel 15 (657MHz-4012) access = subscribed
20140126-15:19:06 CableCARD: Tuner0: vchannel 17 (705MHz-1529) access = subscribed
20140126-15:19:11 CableCARD: Tuner0: vchannel 19 (657MHz-4014) access = subscribed
20140126-15:40:22 CableCARD: Tuner1: vchannel 931 (567MHz-2842) access = subscribed
20140126-16:06:48 CableCARD: Tuner1: vchannel 931 (567MHz-2842) access = subscribed
20140126-16:14:10 CableCARD: Tuner1: vchannel 892 (267MHz-45) access = subscribed
20140126-16:33:10 CableCARD: Tuner1: vchannel 892 (267MHz-45) access = subscribed
20140126-16:37:55 CableCARD: Tuner0: vchannel 877 (267MHz-43) access = subscribed
20140126-16:44:47 CableCARD: Tuner1: vchannel 877 (267MHz-43) access = subscribed
20140126-16:45:04 CableCARD: Tuner1: vchannel 877 (267MHz-43) access = subscribed
20140126-16:45:21 CableCARD: Tuner1: vchannel 876 (477MHz-101) access = subscribed
20140126-17:09:07 CableCARD: Tuner1: vchannel 895 (165MHz-46) access = subscribed
20140126-17:15:26 CableCARD: Tuner0: vchannel 820 (375MHz-27) access = subscribed
20140127-01:30:04 CableCARD: Tuner1: vchannel 812 (729MHz-2) access = subscribed
20140127-01:53:51 CableCARD: Tuner1: vchannel 812 (729MHz-2) access = subscribed
20140127-01:59:41 CableCARD: Tuner0: vchannel 835 (483MHz-56) access = subscribed
20140127-03:12:23 CableCARD: Tuner1: vchannel 869 (135MHz-9) access = subscribed
20140127-03:21:37 CableCARD: Tuner1: vchannel 889 (555MHz-20) access = subscribed
20140127-23:40:46 CableCARD: Tuner1: vchannel 890 (363MHz-85) access = subscribed
20140127-23:40:51 CableCARD: Tuner1: vchannel 899 (477MHz-102) access = subscribed
20140127-23:41:05 CableCARD: Tuner0: vchannel 899 (477MHz-102) access = subscribed
20140127-23:41:15 CableCARD: Tuner1: vchannel 890 (363MHz-85) access = subscribed
20140127-23:46:47 CableCARD: Tuner1: vchannel 890 (363MHz-85) access = subscribed
20140128-01:24:43 CableCARD: Tuner0: vchannel 930 (675MHz-2641) access = subscribed
20140128-01:27:10 CableCARD: Tuner0: vchannel 876 (477MHz-101) access = subscribed
20140128-01:30:31 CableCARD: Tuner0: vchannel 176 (279MHz-1215) access = subscribed
20140128-01:30:55 CableCARD: Tuner2: vchannel 176 (279MHz-1215) access = subscribed
20140128-01:48:17 CableCARD: Tuner0: vchannel 874 (165MHz-47) access = subscribed
20140128-02:00:39 CableCARD: Tuner0: vchannel 876 (477MHz-101) access = subscribed
20140128-11:12:18 CableCARD: Tuner0: vchannel 820 (375MHz-27) access = subscribed
20140129-15:35:43 CableCARD: message: Emergency message on TV - tune to channel 73
20140129-22:28:40 CableCARD: Tuner0: vchannel 864 (465MHz-1541) access = subscribed
20140129-22:30:01 CableCARD: Tuner0: vchannel 876 (477MHz-101) access = subscribed
20140129-22:30:56 CableCARD: Tuner0: vchannel 877 (267MHz-43) access = subscribed
20140129-22:31:15 CableCARD: Tuner0: vchannel 881 (405MHz-23) access = subscribed
20140129-22:31:39 CableCARD: Tuner2: vchannel 881 (405MHz-23) access = subscribed
20140129-22:39:23 CableCARD: Tuner0: vchannel 878 (171MHz-51) access = subscribed
20140129-22:39:33 CableCARD: Tuner0: vchannel 885 (249MHz-33) access = subscribed
20140129-22:40:01 CableCARD: Tuner0: vchannel 889 (555MHz-20) access = subscribed
20140129-22:40:24 CableCARD: Tuner0: vchannel 914 (567MHz-2841) access = subscribed
20140129-22:40:45 CableCARD: Tuner2: vchannel 914 (567MHz-2841) access = subscribed
20140129-22:50:19 CableCARD: Tuner0: vchannel 866 (225MHz-71) access = subscribed
20140129-22:50:39 CableCARD: Tuner0: vchannel 874 (165MHz-47) access = subscribed
20140129-22:51:10 CableCARD: Tuner0: vchannel 849 (555MHz-19) access = subscribed
20140129-22:51:24 CableCARD: Tuner0: vchannel 870 (549MHz-10) access = subscribed
20140129-22:52:54 CableCARD: Tuner0: vchannel 885 (249MHz-33) access = subscribed
20140129-22:53:24 CableCARD: Tuner0: vchannel 892 (267MHz-45) access = subscribed
20140129-23:00:09 CableCARD: Tuner0: vchannel 895 (165MHz-46) access = subscribed
20140129-23:03:26 CableCARD: Tuner1: vchannel 895 (165MHz-46) access = subscribed
20140129-23:03:36 CableCARD: Tuner1: vchannel 893 (249MHz-31) access = subscribed
20140129-23:03:53 CableCARD: Tuner1: vchannel 890 (363MHz-85) access = subscribed
20140129-23:04:04 CableCARD: Tuner1: vchannel 880 (405MHz-22) access = subscribed
20140129-23:04:28 CableCARD: Tuner0: vchannel 880 (405MHz-22) access = subscribed
20140130-01:47:30 CableCARD: Tuner1: vchannel 880 (405MHz-22) access = subscribed
20140130-01:48:48 CableCARD: Tuner1: vchannel 820 (375MHz-27) access = subscribed
20140130-01:49:50 CableCARD: Tuner1: vchannel 868 (549MHz-11) access = subscribed
20140130-01:49:59 CableCARD: Tuner1: vchannel 820 (375MHz-27) access = subscribed
20140130-01:50:06 CableCARD: Tuner1: vchannel 868 (549MHz-11) access = subscribed
20140130-01:51:59 CableCARD: Tuner1: vchannel 865 (429MHz-60) access = subscribed
20140130-01:52:17 CableCARD: Tuner2: vchannel 890 (363MHz-85) access = subscribed
20140130-01:52:19 CableCARD: Tuner1: vchannel 866 (225MHz-71) access = subscribed
20140130-08:35:21 CableCARD: message: Emergency message on TV - tune to channel 73
20140130-11:40:18 CableCARD: Tuner1: vchannel 811 (633MHz-3) access = subscribed
20140131-13:48:37 CableCARD: Tuner0: vchannel 811 (633MHz-3) access = subscribed
20140131-13:49:46 CableCARD: Tuner0: vchannel 813 (729MHz-1) access = subscribed
20140131-13:49:57 CableCARD: Tuner0: vchannel 820 (375MHz-27) access = subscribed
20140131-13:53:40 CableCARD: Tuner0: vchannel 871 (135MHz-8) access = subscribed
20140131-13:54:56 CableCARD: Tuner0: vchannel 876 (477MHz-101) access = subscribed
20140131-14:04:26 CableCARD: Tuner0: vchannel 887 (477MHz-100) access = subscribed
20140131-14:04:51 CableCARD: Tuner0: vchannel 892 (267MHz-45) access = subscribed
20140131-14:05:21 CableCARD: Tuner0: vchannel 876 (477MHz-101) access = subscribed
20140131-14:05:46 CableCARD: Tuner0: vchannel 870 (549MHz-10) access = subscribed
20140131-14:06:15 CableCARD: Tuner0: vchannel 884 (219MHz-62) access = subscribed
20140131-14:06:46 CableCARD: Tuner0: vchannel 853 (447MHz-4801) access = subscribed
20140131-14:07:06 CableCARD: Tuner0: vchannel 880 (405MHz-22) access = subscribed
20140131-14:07:40 CableCARD: Tuner0: vchannel 895 (165MHz-46) access = subscribed
20140131-14:08:02 CableCARD: Tuner0: vchannel 882 (645MHz-841) access = subscribed
20140131-14:08:32 CableCARD: Tuner0: vchannel 881 (405MHz-23) access = subscribed
20140131-14:09:08 CableCARD: Tuner0: vchannel 894 (285MHz-36) access = subscribed
20140131-14:09:36 CableCARD: Tuner0: vchannel 914 (567MHz-2841) access = subscribed
20140131-14:10:09 CableCARD: Tuner0: vchannel 934 (717MHz-2742) access = subscribed
20140131-14:10:35 CableCARD: Tuner0: vchannel 870 (549MHz-10) access = subscribed
20140131-14:14:48 CableCARD: Tuner1: vchannel 811 (633MHz-3) access = subscribed
20140131-14:15:28 CableCARD: Tuner1: vchannel 813 (729MHz-1) access = subscribed
20140131-14:16:16 CableCARD: Tuner1: vchannel 823 (135MHz-7) access = subscribed
20140131-14:17:09 CableCARD: Tuner1: vchannel 876 (477MHz-101) access = subscribed
20140131-14:17:36 CableCARD: Tuner1: vchannel 890 (363MHz-85) access = subscribed
20140131-14:18:00 CableCARD: Tuner0: vchannel 890 (363MHz-85) access = subscribed

[DOUBLEPOST=1391179335][/DOUBLEPOST]Two other anomalies occurred while I was trying to get the above capture. A couple of channel changes failed giving me a "An unknown error occurred" message. I don't remember the channel details but I did save the logs and Wireshark capture. Another issue that I saw was that on some of the channel changes, video from the From channel persisted (in kind of a slow motion stuttering fashion) for several seconds after the channel change was command. Eventually the video would switch over to the newly selected channel. Audio from the newly selected channel was playing while the video was in this intermediate state. I've attached the MP logs (9:10) and a Wireshark capture (Capture 1) captured when I got the error message.