Scheduled recordings fail to start with HDHomerun (1 Viewer)

Fred Fred

Portal Member
September 29, 2015
7
0
54
Home Country
France France
Hi,

I'm running MediaPortal 1.11 with a dual tuner HDHomerun HDHR4-2DT (DVB-T) for over the air HD TV in Europe.
Over the air TV reception is close to perfect in my area (signal at 100%).
As part of my daily schedule, a first recording fails to start with error "Could not lock onto channel - no signal or bad signal".
Once this starts happening, all new scheduled recordings fail to start with the same error and the only way to get back on tracks is to power-cycle the HDHomerun.

The issue seems to be related to repeated recordings on the same channel (or the same "channel group", including channels that can be watched/recorded concurrently on one single tuner).
So I tried the workaround recommended in a similar thread: https://forum.team-mediaportal.com/...intermittently-with-mediaportal-1-6-0.124227/.
In my configuration however, setting the network provider to DVB-T (instead of Generic) does not help.

In the attached log files, the issue occurs at 14:00:06,534. The 2 channels involved ("TF1 HD" and "France 2 HD") are part of the same channel group)
13:55 Stop recording TF1 HD on card 5
14:00 Stop recording France 2 HD on card 5
14:00 Try another recording on France 2 HD
14:00:06,534 "Could not lock onto channel - no signal or bad signal" on card 5
14:00:06,561 Try card 6: Same error

Thanks,
Fred
 

Attachments

  • 09-28.ZIP
    404.7 KB

mm1352000

Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Hello and welcome Fred

    I see what you're talking about. This is definitely an unusual situation. From a MediaPortal TV Server perspective it genuinely looks like the tuner is not able to lock onto signal.

    Have you tried to view the "Les feux de l'amour" recording from TF1 HD?
    If yes, is the recording watchable in full without any apparent signal problems?

    Is there any evidence of problems in the HDHR logs?
    What does the HDHR home page show about the tuner status - tuned frequency, signal strength, signal quality etc. - when the problem is occurring?

    Regards,
    mm
     

    Fred Fred

    Portal Member
    September 29, 2015
    7
    0
    54
    Home Country
    France France
    Thanks mm!

    > Have you tried to view the "Les feux de l'amour" recording from TF1 HD?
    > If yes, is the recording watchable in full without any apparent signal problems?

    Yes, this recording (done just before the error) was fine.
    I had the issue 3 times in 2 days, and each time the recordings that do start complete successfully and with good quality.
    The error always seems to occur on a channel (or channel group) which had a least one successful recording previously.

    > Is there any evidence of problems in the HDHR logs?
    I'm still trying to figure out how to access detailed HDHomerun logs / enable debug mode.
    I also opened a case on the HDHomerun side but have not heard back yet.

    > What does the HDHR home page show about the tuner status - tuned frequency, signal strength, signal quality etc. - when the problem is occurring?
    After the problem occurs, the HDHomerun generally becomes unresponsive.
    If I try to run HDHomeRun Setup tool after this, I get an error "HDHomeRun not detected".

    I was able to temporary resolve the problem once though by manually starting live TV to a different channel:
    - A recording stopped previously on channel X - For some reason causing future tuning requests on channel X to be rejected with error "Could not lock onto channel - no signal or bad signal"
    - One recording in progress on card 5
    - Another recording scheduled to start on channel X
    - Card 6 idle, but the tuner is not able to lock onto signal - Keeps trying, and receiving error "Could not lock onto channel - no signal or bad signal"
    - I manually started live TV on a different channel (making use of card 6)
    - Then the recording started on card 6 on channel X, interrupting live TV

    This makes me think the behavior is not random, but has to do with trying to tune to a channel (or channel group) previously used on the same card...
     

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Thank you for the direct answers. :)

    More questions coming...

    Yes, this recording (done just before the error) was fine.
    To be clear: the "Les feux de l'amour" recording from TF1 HD (same frequency as France 2 HD) started only 5 minutes before the errors with France 2 HD started and ended after 3 PM, when the problem had been going on for at least an hour. If that recording is completely okay, it seems to mean that the problem must have been triggered between 13:55 - 14:00.

    Have you checked the Windows application and system event log files for the corresponding period to see if anything stands out?
    You also had a "Journal" recording on France 2 HD that finished at 14:00:02. Would I be correct to assume that recording was also completely okay right until the end?

    I had the issue 3 times in 2 days, and each time the recordings that do start complete successfully and with good quality.
    The error always seems to occur on a channel (or channel group) which had a least one successful recording previously.
    Okay.

    I'm still trying to figure out how to access detailed HDHomerun logs / enable debug mode.
    I also opened a case on the HDHomerun side but have not heard back yet.
    Okay, please let me know if you find/hear anything. :)

    After the problem occurs, the HDHomerun generally becomes unresponsive.
    If I try to run HDHomeRun Setup tool after this, I get an error "HDHomeRun not detected".
    Ahhh, this problem is more and more interesting! :)
    In all my years working on MediaPortal I have never read a problem report where that happens.

    Are you sure that the network link to the HDHR is not dropping out? (...router/switch failure, DHCP IP address expiry/renewal, security/firewall software failure, high network load???)

    I was able to temporary resolve the problem once though by manually starting live TV to a different channel:
    Yes, that is a good test. :)

    In the case of the failure of "Toute une histoire", tuner 5 was already tuned to the correct frequency (for recording "Les feux de l'amour"). Therefore no tune request was sent; only signal was checked. That is when you see the first "could not lock onto channel - no signal or bad signal" message. On the other hand, tuner 6 was idle so TV Server was definitely sending proper tune requests to that tuner. The time taken for tuning is quite extreme:
    [2015-09-28 14:00:06,562] [Log ] [scheduler thread] [INFO ] - dvb:confused:ubmit tunerequest calling put_TuneRequest
    [2015-09-28 14:00:09,890] [Log ] [scheduler thread] [INFO ] - dvb:confused:ubmit tunerequest done calling put_TuneRequest

    That's more than 3 seconds. Normally it should be much faster - approximately 50 milliseconds. For comparison:
    [2015-09-28 11:45:04,349] [Log ] [scheduler thread] [INFO ] - dvb:confused:ubmit tunerequest calling put_TuneRequest
    [2015-09-28 11:45:04,380] [Log ] [scheduler thread] [INFO ] - dvb:confused:ubmit tunerequest done calling put_TuneRequest

    [2015-09-28 12:00:11,399] [Log ] [scheduler thread] [INFO ] - dvb:confused:ubmit tunerequest calling put_TuneRequest
    [2015-09-28 12:00:11,455] [Log ] [scheduler thread] [INFO ] - dvb:confused:ubmit tunerequest done calling put_TuneRequest

    [2015-09-28 13:00:03,269] [Log ] [scheduler thread] [INFO ] - dvb:confused:ubmit tunerequest calling put_TuneRequest
    [2015-09-28 13:00:03,303] [Log ] [scheduler thread] [INFO ] - dvb:confused:ubmit tunerequest done calling put_TuneRequest

    It seems to me that when the problem happens, something is definitely wrong with the tuner or with the network link...

    Regards,
    mm
     

    Fred Fred

    Portal Member
    September 29, 2015
    7
    0
    54
    Home Country
    France France
    Thanks mm! My replies below between the lines:

    > Have you checked the Windows application and system event log files for the corresponding period to see if anything stands out?
    Nothing unusual there...

    > You also had a "Journal" recording on France 2 HD that finished at 14:00:02. Would I be correct to assume that recording was also completely okay right until the end?
    I watched this program, but not quite through the end (5/10 minutes of commercial...).
    I did not notice anything wrong, but I didn't actually check the program length either before deleting it.

    > Are you sure that the network link to the HDHR is not dropping out? (...router/switch failure, DHCP IP address expiry/renewal, security/firewall software failure, high network load???)
    I did not find any router error / firewall block in the logs.
    I have a wired 1Gbit network, but the HDHomerun maxes out at 100Mbit.
    I'm not quite sure whether this limit could be reached when recording multiple HD programs. I'm not sure whether recording several program in the same group/frequency on one tuner requires extra bandwidth...
    I did not noticed anything wrong, but I'll take a closer look at the network the next time the problem happens.

    > In the case of the failure of "Toute une histoire", tuner 5 was already tuned to the correct frequency (for recording "Les feux de l'amour"). Therefore no tune request was sent; only signal was checked. That is when you see the first "could not lock onto channel - no signal or bad signal" message.
    Is there any option (Debug parameter or other) to make MediaPortal send a tune request anyway? Could this be a workaround for the problem?

    > On the other hand, tuner 6 was idle so TV Server was definitely sending proper tune requests to that tuner. The time taken for tuning is quite extreme:
    May be it is already too late and something has already gone wrong on the HDHomerun side?
    I wish I could have the logs on the HDHomerun device, but they seen to get lost at reboot (and the device was not accessible before the reboot)...
     

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    I'm not quite sure whether this limit could be reached when recording multiple HD programs. I'm not sure whether recording several program in the same group/frequency on one tuner requires extra bandwidth...
    Recording multiple channels from the same frequency does not require extra bandwidth. TV Server always requests the full transport stream from the HDHR. That means that the same (maximum) bandwidth will always be required no matter how many channels you are viewing or recording. AFAIK France has DVB-T transmitters where the transport stream bandwidth is between 20 and 30 Mbps. Therefore if both tuners are in use, it will require between 40 and 60 Mbps. So, the HDHR's 100 Mbps interface/bandwidth should not be a problem.

    Is there any option (Debug parameter or other) to make MediaPortal send a tune request anyway?
    No.

    Could this be a workaround for the problem?
    It depends what the problem actually is... but my guess is that the answer is no. As I said previously, TV Server was sending a tune request when it tried to use tuner 6 but it didn't work/help.

    May be it is already too late and something has already gone wrong on the HDHomerun side?
    Maybe. I can't determine that. Hopefully Silicondust will be able to answer.
     

    Fred Fred

    Portal Member
    September 29, 2015
    7
    0
    54
    Home Country
    France France
    Hello,

    I disabled the HDHomerun tuner and connected a new Elgato EyeTV Diversity (a dual USB tuner).
    I ran into the same issue with the Elgato tuner:
    [2015-10-03 19:57:05,327] [Log ] [scheduler thread] [INFO ] - dvb: LockInOnSignal could not lock onto channel - no signal or bad signal

    The recording scheduled at 19:57 failed to start while only 1 tuner was reported used in the MP GUI.
    All retries after this failed and I had to reboot the PC to fix it.

    I'm attaching a fresh set of MP log files...

    Thanks,
    Fred
     

    Attachments

    • ELGATO.ZIP
      1.5 MB

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Did you get any response from Silicondust?

    In this case the problem seems to be slightly different, because the tuner is not already tuned to the same frequency. Still, I can't see any reason why tuning should fail. The only explanation seems to be that the tuner is telling the truth about the signal. I see many continuity errors in the TsWriter log, and those are often associated with low signal strength/quality...
     

    Fred Fred

    Portal Member
    September 29, 2015
    7
    0
    54
    Home Country
    France France
    Thanks mm!

    The response from Silicondust was that other devices may cause interference, so I moved the HDHR far away from my amplified speakers, but this did not change anything.
    They also sent the logs to Engineering for analysis, but I have not hear back... I have no access to their logs, which are sent directly to their servers, once debug mode is enabled.

    I agree there may be signal strength issues (more so with the Elgato tuner which seems not as strong as the HDHR), but why do all the retries keep failing?
    Especially since the recording in progress on the other tuner continued until I rebooted the system around 20:25. The recording quality for this program ("Diane, femme flic" on Chérie 25) was correct through the end (I watched it). I was successful before in using both tuners concurrently with good recording quality.

    There is also something I don't understand about the sequence of events (see below):
    [2015-10-03 18:55:11,024] [Log ] [scheduler thread] [INFO ] - Scheduler : record to D:\\Diane, femme flic - Chérie 25 - 2015-10-03.ts
    [2015-10-03 18:55:11,152] [Log ] [scheduler thread] [INFO ] - card: SignalTuneEvent card: 8 / subch: 0
    This starts a recording on card 8, keeping it busy until I rebooted the system at 20:25

    [2015-10-03 19:00:05,966] [Log ] [scheduler thread] [INFO ] - Scheduler: stop record NRJ12 10/3/2015 6:20:10 PM-10/3/2015 6:50:00 PM The Middle
    [2015-10-03 19:00:05,968] [Log ] [scheduler thread] [INFO ] - card: StopRecording card=7, user=scheduler289
    This is the last recording in a long sequence of consecutive episodes of this series "The Middle".
    There should be no more users for card 7.

    [2015-10-03 19:57:00,926] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record France 2 7:57 PM-8:40 PM Journal
    [2015-10-03 19:57:01,047] [Log ] [scheduler thread] [INFO ] - Controller: card:7 type:DvbT users: 1
    I don't understand this. There was between 1 and 2 users during the sequence of recordings of "The Middle" episodes, due to a 10 minutes post-recording padding.
    But the last recording completed 1 hour before...

    [2015-10-03 19:57:01,049] [Log ] [scheduler thread] [INFO ] - Controller: card:7 type:DvbT is available
    Why is it available if there is still 1 user?
    Note that the new requested recording "France 2 7:57 PM-8:40 PM Journal" is on a different frequency than previous recordings.

    [2015-10-03 19:57:01,166] [Log ] [scheduler thread] [INFO ] - Scheduler : card is not tuned to the same transponder and not recording, kicking all users. record on card:7 priority:2
    [2015-10-03 19:57:01,169] [Log ] [scheduler thread] [INFO ] - Scheduler : kicking user:X54
    Does this mean live TV was on on card 7?

    [2015-10-03 19:57:02,439] [Log ] [scheduler thread] [INFO ] - card: Tune on card 7 to subchannel France 2
    [2015-10-03 19:57:05,327] [Log ] [scheduler thread] [INFO ] - dvb: LockInOnSignal could not lock onto channel - no signal or bad signal
    If card 7 was really free, I would have expected this tune request to be successful. "France 2" is one of the channels with the best reception.
    Is it possible that card 7 was not properly freed? This would explain why all the retries after this keep failing...

    Regards,
    Fred
     

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Hello again Fred

    I agree there may be signal strength issues (more so with the Elgato tuner which seems not as strong as the HDHR)
    I advise you to disregard the signal strength/quality percentages that you see in MediaPortal and other PC TV software. They're almost useless. 100% doesn't mean "perfect", and comparisons between different models of tuners are invalid (50% for HDHR could be 80% for Elgato... or 100%... or 120%... or 20% - there's no way to know because tuner vendors don't use the same calculations in their drivers).

    If you really want to know if you have adequate signal quality, best idea is to ask a professional to check the signal with professional equipment.

    but why do all the retries keep failing?
    If the problem is signal then then the answer is simple: the signal strength and quality is insufficient for the tuner to lock. The number of retries is irrelevant.

    Especially since the recording in progress on the other tuner continued until I rebooted the system around 20:25.
    Reception can vary for different frequencies due to aerial design, differences in transmitter distance, local interference, differences in weather between your location and the target transmitter etc.

    Also, more signal strength/quality is required when more tuners are active. In other words, you are more likely to have a signal problem with tuner 2 if tuner 1 is active (and vice versa).

    There should be no more users for card 7.
    That is not correct.
    You can see that X54 started time-shifting on channel "NRJ12" at 16:47:40:
    [collapse]
    [2015-10-03 16:47:40,078] [Log ] [7 ] [INFO ] - Controller: find free card for channel NRJ12
    [2015-10-03 16:47:40,080] [Log ] [7 ] [INFO ] - Controller: find card for channel NRJ12
    [2015-10-03 16:47:40,086] [Log ] [7 ] [INFO ] - Controller: got 1 tuning details for NRJ12
    [2015-10-03 16:47:40,088] [Log ] [7 ] [INFO ] - Controller: channel #1 DVBT:tv:confused:MR6 NRJ12 Freq:562000 ONID:8442 TSID:6 SID:1538 PMT:0xD2 FTA:True LCN:12 BandWidth:8
    [2015-10-03 16:47:40,090] [Log ] [7 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2015-10-03 16:47:40,091] [Log ] [7 ] [INFO ] - Controller: card:2 type:DvbIP is disabled
    [2015-10-03 16:47:40,096] [Log ] [7 ] [INFO ] - Controller: card:7 type:DvbT can tune to channel
    [2015-10-03 16:47:40,100] [Log ] [7 ] [INFO ] - Controller: card:7 type:DvbT users: 2
    [2015-10-03 16:47:40,104] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT can tune to channel
    [2015-10-03 16:47:40,111] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT users: 0
    [2015-10-03 16:47:40,113] [Log ] [7 ] [INFO ] - Controller: card:5 type:DvbT is disabled
    [2015-10-03 16:47:40,115] [Log ] [7 ] [INFO ] - Controller: card:6 type:DvbT is disabled
    [2015-10-03 16:47:40,117] [Log ] [7 ] [INFO ] - Controller: found 2 card(s) for channel
    [2015-10-03 16:47:40,118] [Log ] [7 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 38 msec
    [2015-10-03 16:47:40,120] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT is available
    [2015-10-03 16:47:40,121] [Log ] [7 ] [INFO ] - Controller: found 2 free card(s)
    [2015-10-03 16:47:40,123] [Log ] [7 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 45 msec
    [2015-10-03 16:47:40,141] [Log ] [7 ] [INFO ] - Controller: TimeShiftingWouldUseCard NRJ12 65
    [2015-10-03 16:47:40,146] [Log ] [7 ] [INFO ] - Controller: find free card for channel NRJ12
    [2015-10-03 16:47:40,148] [Log ] [7 ] [INFO ] - Controller: find card for channel NRJ12
    [2015-10-03 16:47:40,169] [Log ] [7 ] [INFO ] - Controller: got 1 tuning details for NRJ12
    [2015-10-03 16:47:40,171] [Log ] [7 ] [INFO ] - Controller: channel #1 DVBT:tv:confused:MR6 NRJ12 Freq:562000 ONID:8442 TSID:6 SID:1538 PMT:0xD2 FTA:True LCN:12 BandWidth:8
    [2015-10-03 16:47:40,173] [Log ] [7 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2015-10-03 16:47:40,175] [Log ] [7 ] [INFO ] - Controller: card:2 type:DvbIP is disabled
    [2015-10-03 16:47:40,180] [Log ] [7 ] [INFO ] - Controller: card:7 type:DvbT can tune to channel
    [2015-10-03 16:47:40,183] [Log ] [7 ] [INFO ] - Controller: card:7 type:DvbT users: 2
    [2015-10-03 16:47:40,189] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT can tune to channel
    [2015-10-03 16:47:40,190] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT users: 0
    [2015-10-03 16:47:40,192] [Log ] [7 ] [INFO ] - Controller: card:5 type:DvbT is disabled
    [2015-10-03 16:47:40,193] [Log ] [7 ] [INFO ] - Controller: card:6 type:DvbT is disabled
    [2015-10-03 16:47:40,197] [Log ] [7 ] [INFO ] - Controller: found 2 card(s) for channel
    [2015-10-03 16:47:40,198] [Log ] [7 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 49 msec
    [2015-10-03 16:47:40,200] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT is available
    [2015-10-03 16:47:40,202] [Log ] [7 ] [INFO ] - Controller: found 2 free card(s)
    [2015-10-03 16:47:40,203] [Log ] [7 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 56 msec
    [2015-10-03 16:47:40,244] [Log ] [7 ] [INFO ] - Controller: StartTimeShifting NRJ12 65
    [2015-10-03 16:47:40,246] [Log ] [7 ] [INFO ] - Controller: epg stop
    [2015-10-03 16:47:40,247] [Log ] [7 ] [INFO ] - Controller: find free card for channel NRJ12
    [2015-10-03 16:47:40,249] [Log ] [7 ] [INFO ] - Controller: find card for channel NRJ12
    [2015-10-03 16:47:40,252] [Log ] [7 ] [INFO ] - Controller: got 1 tuning details for NRJ12
    [2015-10-03 16:47:40,254] [Log ] [7 ] [INFO ] - Controller: channel #1 DVBT:tv:confused:MR6 NRJ12 Freq:562000 ONID:8442 TSID:6 SID:1538 PMT:0xD2 FTA:True LCN:12 BandWidth:8
    [2015-10-03 16:47:40,255] [Log ] [7 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2015-10-03 16:47:40,256] [Log ] [7 ] [INFO ] - Controller: card:2 type:DvbIP is disabled
    [2015-10-03 16:47:40,258] [Log ] [7 ] [INFO ] - Controller: card:7 type:DvbT can tune to channel
    [2015-10-03 16:47:40,261] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT can tune to channel
    [2015-10-03 16:47:40,262] [Log ] [7 ] [INFO ] - Controller: card:5 type:DvbT is disabled
    [2015-10-03 16:47:40,264] [Log ] [7 ] [INFO ] - Controller: card:6 type:DvbT is disabled
    [2015-10-03 16:47:40,265] [Log ] [7 ] [INFO ] - Controller: found 2 card(s) for channel
    [2015-10-03 16:47:40,266] [Log ] [7 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 17 msec
    [2015-10-03 16:47:40,267] [Log ] [7 ] [INFO ] - Controller: found 2 free card(s)
    [2015-10-03 16:47:40,268] [Log ] [7 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 20 msec
    [2015-10-03 16:47:40,313] [Log ] [7 ] [INFO ] - Controller: card:7 type:DvbT users: 2
    [2015-10-03 16:47:40,314] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT users: 0
    [2015-10-03 16:47:40,316] [Log ] [7 ] [INFO ] - Controller: card:8 type:DvbT is available
    [2015-10-03 16:47:40,317] [Log ] [7 ] [INFO ] - Controller: try max 2 of 2 cards for timeshifting
    [2015-10-03 16:47:40,324] [Log ] [7 ] [INFO ] - card: CardTune 7 NRJ12 X54:7:-1
    [2015-10-03 16:47:40,326] [Log ] [7 ] [INFO ] - card: Tune on card 7 to subchannel NRJ12
    [2015-10-03 16:47:40,344] [Log ] [7 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 2 subch#-1
    [2015-10-03 16:47:40,346] [Log ] [7 ] [INFO ] - tvcard:FreeSubChannel :-1 - sub channel not found
    [2015-10-03 16:47:40,347] [Log ] [7 ] [INFO ] - tvcard:FreeSubChannel : subchannels STILL present 2, continuing graph
    [2015-10-03 16:47:40,348] [Log ] [7 ] [INFO ] - dvbt: Tune:DVBT:tv:confused:MR6 NRJ12 Freq:562000 ONID:8442 TSID:6 SID:1538 PMT:0xD2 FTA:True LCN:12 BandWidth:8
    [2015-10-03 16:47:40,350] [Log ] [7 ] [INFO ] - dvb:confused:ubmiting tunerequest Channel:NRJ12 subChannel:-1
    [2015-10-03 16:47:40,351] [Log ] [7 ] [INFO ] - dvb:Getting new subchannel
    [2015-10-03 16:47:40,352] [Log ] [7 ] [INFO ] - dvb:GetNewSubChannel:2 #2
    [2015-10-03 16:47:40,354] [Log ] [7 ] [INFO ] - TvDvbChannel ctor new subchIndex:2
    [2015-10-03 16:47:40,356] [Log ] [7 ] [INFO ] - card: AddTuneEvent card: 7 / subch: 2
    [2015-10-03 16:47:40,357] [Log ] [7 ] [INFO ] - dvb:confused:ubmit tunerequest size:3 new:2
    [2015-10-03 16:47:40,358] [Log ] [7 ] [INFO ] - subch:2 OnBeforeTune
    [2015-10-03 16:47:40,359] [Log ] [7 ] [INFO ] - subch:2 OnAfterTune
    [2015-10-03 16:47:40,360] [Log ] [7 ] [INFO ] - RunGraph
    [2015-10-03 16:47:40,375] [Log ] [7 ] [INFO ] - dvb: LockInOnSignal ok
    [2015-10-03 16:47:40,377] [Log ] [7 ] [INFO ] - subch:2 OnGraphStart
    [2015-10-03 16:47:40,378] [Log ] [7 ] [INFO ] - subch:2 Graph already running - WaitForPMT
    [2015-10-03 16:47:40,379] [Log ] [7 ] [INFO ] - subch:2 SetupPmtGrabber:pid D2 sid:602
    [2015-10-03 16:47:40,380] [Log ] [7 ] [INFO ] - subch:2 set pmt grabber pmt:D2 sid:602
    [2015-10-03 16:47:40,404] [Log ] [13 ] [INFO ] - subch:2 OnPMTReceived() pmt:D2 ran:True dynamic:False
    [2015-10-03 16:47:40,406] [Log ] [7 ] [INFO ] - subch:2 SendPmt:602 602 FFFFFFFF 1C
    [2015-10-03 16:47:40,408] [Log ] [7 ] [INFO ] - Decode pmt
    [2015-10-03 16:47:40,409] [Log ] [7 ] [INFO ] - Set descriptor data with length 6
    [2015-10-03 16:47:40,410] [Log ] [7 ] [INFO ] - Set descriptor data with length 6
    [2015-10-03 16:47:40,411] [Log ] [7 ] [INFO ] - Set descriptor data with length 6
    [2015-10-03 16:47:40,412] [Log ] [7 ] [INFO ] - Set descriptor data with length 10
    [2015-10-03 16:47:40,413] [Log ] [7 ] [INFO ] - Set descriptor data with length 10
    [2015-10-03 16:47:40,414] [Log ] [7 ] [INFO ] - Set descriptor data with length 3
    [2015-10-03 16:47:40,416] [Log ] [7 ] [INFO ] - subch:2 SendPMT: Channel is FTA, nothing to do.
    [2015-10-03 16:47:40,417] [Log ] [7 ] [INFO ] - subch:2 SetMpegPidMapping
    [2015-10-03 16:47:40,418] [Log ] [7 ] [INFO ] - subch:2 pid:DC pcr
    [2015-10-03 16:47:40,419] [Log ] [7 ] [INFO ] - subch:2 pid:D2 pmt
    [2015-10-03 16:47:40,421] [Log ] [7 ] [INFO ] - subch:2 pid:DC video type:MPEG-2
    [2015-10-03 16:47:40,422] [Log ] [7 ] [INFO ] - subch:2 map pid:DC video type:MPEG-2
    [2015-10-03 16:47:40,423] [Log ] [7 ] [INFO ] - subch:2 pid:E6 audio lang:fra type:MPEG-1
    [2015-10-03 16:47:40,424] [Log ] [7 ] [INFO ] - subch:2 map pid:E6 audio lang:fra type:MPEG-1
    [2015-10-03 16:47:40,425] [Log ] [7 ] [INFO ] - subch:2 pid:E8 audio lang:eng type:MPEG-1
    [2015-10-03 16:47:40,426] [Log ] [7 ] [INFO ] - subch:2 pid:E9 audio lang: type:MPEG-1
    [2015-10-03 16:47:40,427] [Log ] [7 ] [INFO ] - subch:2 pid:FA subtitle type:6
    [2015-10-03 16:47:40,428] [Log ] [7 ] [INFO ] - subch:2 map pid:FA subtitle type:6
    [2015-10-03 16:47:40,429] [Log ] [7 ] [INFO ] - subch:2 pid:FB subtitle type:6
    [2015-10-03 16:47:40,430] [Log ] [7 ] [INFO ] - subch:2 map pid:FB subtitle type:6
    [2015-10-03 16:47:40,431] [Log ] [7 ] [INFO ] - subch:2 pid:10E type:5
    [2015-10-03 16:47:40,432] [Log ] [7 ] [INFO ] - subch:2 pid:10F type:B
    [2015-10-03 16:47:40,433] [Log ] [7 ] [INFO ] - subch:2 stop tif
    [2015-10-03 16:47:40,435] [Log ] [7 ] [INFO ] - dvbt: tune: Graph running. Returning TvLibrary.Implementations.DVB.TvDvbChannel
    [2015-10-03 16:47:40,478] [Log ] [7 ] [INFO ] - **************************************************
    [2015-10-03 16:47:40,479] [Log ] [7 ] [INFO ] - ***** SIGNAL LEVEL: 71, SIGNAL QUALITY: 100 *****
    [2015-10-03 16:47:40,481] [Log ] [7 ] [INFO ] - **************************************************
    [2015-10-03 16:47:40,482] [Log ] [7 ] [INFO ] - user:X54 add
    [2015-10-03 16:47:40,483] [Log ] [7 ] [INFO ] - card2:X54 7 2
    [2015-10-03 16:47:40,485] [Log ] [7 ] [INFO ] - Controller: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live7-2.ts
    [2015-10-03 16:47:40,489] [Log ] [7 ] [INFO ] - Controller: epg stop
    [2015-10-03 16:47:40,509] [Log ] [7 ] [INFO ] - card: StartTimeShifting 7 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live7-2.ts
    [2015-10-03 16:47:40,512] [Log ] [7 ] [INFO ] - card: CAM enabled : False
    [2015-10-03 16:47:40,513] [Log ] [7 ] [INFO ] - subch:2 SetTimeShiftFileName:C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live7-2.ts
    [2015-10-03 16:47:40,514] [Log ] [7 ] [INFO ] - Set video / audio observer
    [2015-10-03 16:47:40,516] [Log ] [7 ] [INFO ] - subch:2 SetTimeShiftFileName fill in pids
    [2015-10-03 16:47:40,518] [Log ] [7 ] [INFO ] - subch:2-2 tswriter StartTimeshifting...
    [2015-10-03 16:47:40,537] [Log ] [13 ] [INFO ] - PID seen - type = Video
    [2015-10-03 16:47:40,539] [Log ] [13 ] [INFO ] - audioVideoEventHandler Video
    [2015-10-03 16:47:40,560] [Log ] [7 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2015-10-03 16:47:40,563] [Log ] [13 ] [INFO ] - PID seen - type = Audio
    [2015-10-03 16:47:40,567] [Log ] [13 ] [INFO ] - audioVideoEventHandler Audio
    [2015-10-03 16:47:40,568] [Log ] [7 ] [INFO ] - card: WaitForFile - video and audio are seen after 0.0080005 seconds[/collapse]

    This time-shifting was not stopped until 19:57 when the user ("X54") had to be kicked in order to start recording "Journal" from channel "France 2":
    [collapse]
    [2015-10-03 19:57:00,926] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record France 2 7:57 PM-8:40 PM Journal
    [2015-10-03 19:57:00,927] [Log ] [scheduler thread] [INFO ] - Controller: find free card for channel France 2
    [2015-10-03 19:57:00,929] [Log ] [scheduler thread] [INFO ] - Controller: find card for channel France 2
    [2015-10-03 19:57:00,960] [Log ] [scheduler thread] [INFO ] - Controller: got 1 tuning details for France 2
    [2015-10-03 19:57:00,962] [Log ] [scheduler thread] [INFO ] - Controller: channel #1 DVBT:tv:GR1 A France 2 Freq:586000 ONID:8442 TSID:1 SID:257 PMT:0x6E FTA:True LCN:2 BandWidth:8
    [2015-10-03 19:57:00,964] [Log ] [scheduler thread] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2015-10-03 19:57:00,966] [Log ] [scheduler thread] [INFO ] - Controller: card:2 type:DvbIP is disabled
    [2015-10-03 19:57:00,973] [Log ] [scheduler thread] [INFO ] - Controller: card:7 type:DvbT can tune to channel
    [2015-10-03 19:57:01,001] [Log ] [scheduler thread] [INFO ] - Controller: card:8 type:DvbT can tune to channel
    [2015-10-03 19:57:01,002] [Log ] [scheduler thread] [INFO ] - Controller: card:5 type:DvbT is disabled
    [2015-10-03 19:57:01,004] [Log ] [scheduler thread] [INFO ] - Controller: card:6 type:DvbT is disabled
    [2015-10-03 19:57:01,005] [Log ] [scheduler thread] [INFO ] - Controller: found 2 card(s) for channel
    [2015-10-03 19:57:01,007] [Log ] [scheduler thread] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 77 msec
    [2015-10-03 19:57:01,008] [Log ] [scheduler thread] [INFO ] - Controller: found 2 free card(s)
    [2015-10-03 19:57:01,009] [Log ] [scheduler thread] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 81 msec
    [2015-10-03 19:57:01,047] [Log ] [scheduler thread] [INFO ] - Controller: card:7 type:DvbT users: 1
    [2015-10-03 19:57:01,049] [Log ] [scheduler thread] [INFO ] - Controller: card:7 type:DvbT is available
    [2015-10-03 19:57:01,052] [Log ] [scheduler thread] [INFO ] - Controller: card:8 type:DvbT users: 1
    [2015-10-03 19:57:01,053] [Log ] [scheduler thread] [INFO ] - Controller: card:8 type:DvbT is not available, tuned to different transponder
    [2015-10-03 19:57:01,059] [Log ] [scheduler thread] [INFO ] - scheduler: try max 1 of 1 free cards for recording
    [2015-10-03 19:57:01,166] [Log ] [scheduler thread] [INFO ] - Scheduler : card is not tuned to the same transponder and not recording, kicking all users. record on card:7 priority:2
    [2015-10-03 19:57:01,169] [Log ] [scheduler thread] [INFO ] - Scheduler : kicking user:X54
    [2015-10-03 19:57:01,182] [Log ] [scheduler thread] [INFO ] - Controller: StopTimeShifting 7
    [2015-10-03 19:57:01,290] [Log ] [scheduler thread] [INFO ] - Stop cardid=7, ticket=58, tunestate=TunePending, stopstate=Stopping
    [2015-10-03 19:57:01,292] [Log ] [scheduler thread] [INFO ] - card EyeTV Diversity Digital Tuner (Dev1 Path0): StopTimeShifting user:X54 sub:2
    [2015-10-03 19:57:01,295] [Log ] [scheduler thread] [INFO ] - user:X54 remove
    [2015-10-03 19:57:01,329] [Log ] [scheduler thread] [INFO ] - subch:2-2 tswriter StopTimeshifting...
    [2015-10-03 19:57:02,280] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#2
    [2015-10-03 19:57:02,282] [Log ] [scheduler thread] [INFO ] - DVB subch:2 Decompose()
    [2015-10-03 19:57:02,295] [Log ] [scheduler thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 2
    [2015-10-03 19:57:02,296] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
    [2015-10-03 19:57:02,299] [Log ] [scheduler thread] [INFO ] - dvb:confused:topGraph called
    [2015-10-03 19:57:02,300] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
    [2015-10-03 19:57:02,302] [Log ] [scheduler thread] [INFO ] - dvb:confused:topGraph
    [2015-10-03 19:57:02,367] [Log ] [scheduler thread] [INFO ] - debug: IMediaControl stopped! hr = 0x0 :)
    [2015-10-03 19:57:02,372] [Log ] [scheduler thread] [INFO ] - dvb:confused:topGraph called
    [2015-10-03 19:57:02,375] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
    [2015-10-03 19:57:02,376] [Log ] [scheduler thread] [INFO ] - dvb:confused:topGraph filterstate already stopped, returning.
    [2015-10-03 19:57:02,377] [Log ] [scheduler thread] [INFO ] - user:X54 remove
    [2015-10-03 19:57:02,380] [Log ] [scheduler thread] [INFO ] - Controller:Timeshifting stopped on card:7
    [2015-10-03 19:57:02,381] [Log ] [scheduler thread] [INFO ] - RTSP: remove stream stream7.2[/collapse]


    I don't understand this. There was between 1 and 2 users during the sequence of recordings of "The Middle" episodes, due to a 10 minutes post-recording padding.
    But the last recording completed 1 hour before...
    As above: user "X54" was using the tuner for time-shifting.

    Why is it available if there is still 1 user?
    Because the scheduler user (which performs recordings) is configured with higher priority than "X54". Therefore "X54" can be kicked in order to start the recording. Refer to:
    http://wiki.team-mediaportal.com/1_...n/TV-Server_Configuration/10a_User_Priorities

    Does this mean live TV was on on card 7?
    Yes, as explained above. :)

    If card 7 was really free, I would have expected this tune request to be successful. "France 2" is one of the channels with the best reception.
    How do you know France 2 has good reception?
    From the readings that I see in the log, it seems like it has some of the worst reception:
    [2015-10-03 17:17:34,005] [Log ] [17 ] [INFO ] - dvbt: Tune:DVBT:tv:GR1 A France 2 Freq:586000 ONID:8442 TSID:1 SID:257 PMT:0x6E FTA:True LCN:2 BandWidth:8
    ...
    [2015-10-03 17:17:34,929] [Log ] [17 ] [INFO ] - ***** SIGNAL LEVEL: 51, SIGNAL QUALITY: 0 *****

    Is it possible that card 7 was not properly freed? This would explain why all the retries after this keep failing...
    No, it is not possible that card 7 was not properly freed. I am 100% certain about that.

    Regards,
    mm
     

    Users who are viewing this thread

    Top Bottom