Transmitter Or Tuner Error Caused Later Recordings To Fail (1 Viewer)

[CyberSimian]

An interesting event occurred last night. I was recording several programmes whilst simultaneously watching live TV (actually, I think that I was... ). Then I realised that the TV screen had frozen. I tried changing the channel several times: most gave the "no signal found" diagnostic, but one channel displayed correctly. Also, the red recording dot continued to display on the EPG panel during this time. I ought to have tried one channel from each of the eight MUXes available at my location, but I did not think of that until this morning. Instead, I watched a DVD.

Much later I was just about to switch off when I noticed that there was no red recording dot when in fact two programmes should have been recording. Being a believer in the therapeutic effects of a reboot, I rebooted and the two programmes immediately started recording. I cancelled the recordings and deleted those files. I then looked at the recordings that had been in progress when the original "event" had occurred.

With one exception, all of the recordings had stopped prematurely, at the same time. By replaying one recording, I determined that this time was 2014-12-03 21:23 plus or minus one minute. However, there was one recording that had continued successfully through the "event", and was complete. From this evidence, I would conclude the following:

(1) One or several MUXes had stopped broadcasting temporarily, but some MUXes continued uninterrupted. OR:

(2) One tuner or tuner card had developed a fault, and the vagaries of TV Server's tuner-selection algorithm meant that when tuning to different channels it sometimes selected the faulty tuner or card, and sometimes selected a good tuner or card.

(3) Whatever the cause, one/several/all of the tuners were left in a non-working state that caused the later recordings to fail ("Dallas" scheduled for 00:00 today, and "The 13th Warrior" scheduled for 00.10 today).

You may recall that I had a similar problem with recordings failing to start a few weeks ago; this thread:

https://forum.team-mediaportal.com/threads/recording-failed-to-start.128150/

The problem described there was caused by a bad choice of EPG grabber options (which I have now corrected). The trigger this time seems to be different, but the underlying result might be the same, namely that the TBS tuner driver has ended up in a confused state. I would be very interested in your opinion. If you think that this is another example of the bug in the TBS tuner driver, I am minded to contact TBS to see if they would provide a fix. I have attached the logs.

-- from CyberSimian in the UK

 

[mm1352000]

Hello

I'm not able to explain this problem, but it definitely does not look the same as the previous TBS/EPG grabber issue.

What I'm seeing most are PMT errors. In other words, the tuner apparently tuned successfully but the channel video/audio information was not found in the broadcast stream. This can happen in a variety of situations including low signal strength/quality, channel moved to a different transmitter, channel temporarily off air, tuner not delivering stream etc. These errors start when trying to start the "Death Tunnel" recording:
[2014-12-03 22:49:05,489] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record movies4men 22:49-00:40 Death Tunnel

It is entirely possible that the problem started earlier as you indicated, however I'm not able to confirm an exact time. All I can see is that the previous tune request was successful:
[2014-12-03 21:30:07,669] [Log ] [32 ] [INFO ] - Controller: find free card for channel Al Jazeera Eng

There are some interesting network-related messages in the system event log a bit later:
[collapse]
03/12/2014 21:53:43";"BROWSER";"(0)";"Information";"The browser has forced an election on network \Device\NetBT_Tcpip_{81C0168F-9659-4E1E-AEA4-19BF9BA5CA6C} because a master browser was stopped.";"1073749857"
"03/12/2014 21:53:43";"W32Time";"(0)";"Warning";"NtpClient was unable to set a manual peer to use as a time source because of DNS resolution error on 'time.windows.com,0x1'. NtpClient will try again in 15 minutes and double the reattempt interval thereafter. The error was: No such host is known. (0x80072AF9)";"2186936454"
"03/12/2014 21:53:43";"e1express";"(0)";"Warning";"Intel(R) 82566DC-2 Gigabit Network Connection Link has been disconnected.";"2684616731"
"03/12/2014 21:53:44";"W32Time";"(0)";"Warning";"NtpClient was unable to set a manual peer to use as a time source because of DNS resolution error on 'time.windows.com,0x1'. NtpClient will try again in 15 minutes and double the reattempt interval thereafter. The error was: No such host is known. (0x80072AF9)";"2186936454"
"03/12/2014 21:53:48";"Microsoft-Windows-ResourcePublication";"(0)";"Information";"The description for Event ID '102' in Source 'Microsoft-Windows-ResourcePublication' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'PausePublication'";"102"
"03/12/2014 22:52:10";"e1express";"(0)";"Information";"Intel(R) 82566DC-2 Gigabit Network Connection Link has been established: 100Mbps half duplex.";"1610874914"
"03/12/2014 22:52:10";"e1express";"(0)";"Warning";"Intel(R) 82566DC-2 Gigabit Network Connection is set up for auto-negotiation but the link partner is not configured for auto-negotiation. A duplex mismatch may occur.";"2684616734"
"03/12/2014 22:52:10";"Tcpip";"(0)";"Information";"The system detected that network adapter Local Area Connection was connected to the network, and has initiated normal operation.";"1073746025"
"03/12/2014 22:52:10";"Tcpip";"(0)";"Information";"The system detected that network adapter Local Area Connection was connected to the network, and has initiated normal operation.";"1073746025"
"03/12/2014 22:52:12";"Microsoft-Windows-ResourcePublication";"(0)";"Information";"The description for Event ID '104' in Source 'Microsoft-Windows-ResourcePublication' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'BeginPublication'";"104"
"03/12/2014 22:52:23";"W32Time";"(0)";"Warning";"NtpClient was unable to set a manual peer to use as a time source because of DNS resolution error on 'time.windows.com,0x1'. NtpClient will try again in 15 minutes and double the reattempt interval thereafter. The error was: No such host is known. (0x80072AF9)";"2186936454"
"03/12/2014 22:52:27";"Service Control Manager";"(0)";"Information";"The description for Event ID '1073748860' in Source 'Service Control Manager' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'WinHTTP Web Proxy Auto-Discovery Service', 'running'";"1073748860"
"03/12/2014 22:52:35";"W32Time";"(0)";"Warning";"NtpClient was unable to set a manual peer to use as a time source because of DNS resolution error on 'time.windows.com,0x1'. NtpClient will try again in 15 minutes and double the reattempt interval thereafter. The error was: No such host is known. (0x80072AF9)";"2186936454"
"03/12/2014 23:08:56";"Service Control Manager";"(0)";"Information";"The description for Event ID '1073748860' in Source 'Service Control Manager' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'WinHTTP Web Proxy Auto-Discovery Service', 'stopped'";"1073748860"[/collapse]

Not sure if/how that would connect...

Regards,
mm

 

[Vasilich]

"03/12/2014 22:52:10";"e1express";"(0)";"Information";"Intel(R) 82566DC-2 Gigabit Network Connection Link has been established: 100Mbps half duplex.";"1610874914"

router reset? ethernet cable defect or has been bent to too sharp angle? haven't seen halfduplex ethernet connection for a very long time...

 

[CyberSimian]

It is entirely possible that the problem started earlier as you indicated, however I'm not able to confirm an exact time. All I can see is that the previous tune request was successful:
[2014-12-03 21:30:07,669] [Log ] [32 ] [INFO ] - Controller: find free card for channel Al Jazeera Eng

I think that this was when I had noticed that the screen had frozen, and was trying various other channels to see if any of them worked. One of them did. I cannot remember which it was, but it was probably that one ("Al Jazeera Eng").

"03/12/2014 22:52:10"; "e1express"; "(0)"; "Information"; "Intel(R) 82566DC-2 Gigabit Network Connection Link has been established: 100Mbps half duplex."; "1610874914"

router reset? ethernet cable defect or has been bent to too sharp angle? haven't seen halfduplex ethernet connection for a very long time...

I am quite ignorant with regard to networking, so most of the log lines that mm quoted are opaque to me. I have no idea what the "Windows Resource Publication" is, or what the "master browser" does. However, I can explain some of what is going on, but I don't think that it is related to the recording failures. If you want to see some details of my HTPC set-up, read this post:

http://www.thegreenbutton.tv/forums/viewtopic.php?p=71731#p71731

The "executive summary" is that I use a mains-powered Netgear fast ethernet hub to trigger my HTPC to wake from hibernation when the TV is switched on. The hub is connected to the HTPC and also to a powerline networking socket. I previously used this (via a Belkin ADSL router) to download the Microsoft online EPG for use with Windows Media Center, but these days I think that it is only used for synchronising the clock in the HTPC (and copying MP logs from my HTPC to my laptop, for attachment to threads like this!). My MP client and TV Server are both on the one-and-only HTPC, and nowhere else.

Looking at the log extract quoted, it seems that I switched the TV off shortly before 22:00 (probably having decided that the channel that I wanted to watch was not going to return anytime soon), but I don't actually recollect doing that. I did watch a DVD later, sometime after 22:52, which is when the network connection was re-established, i.e. when the TV was switched on again.

-- from CyberSimian in the UK

 

[CyberSimian]

It is entirely possible that the problem started earlier as you indicated, however I'm not able to confirm an exact time. All I can see is that the previous tune request was successful:
[2014-12-03 21:30:07,669] [Log ] [32 ] [INFO ] - Controller: find free card for channel Al Jazeera Eng

I have just been looking at "MediaPortal.3.log", searching for occurrences of the string "View Channel=" (without the quotes). Starting from line 12840, the log contains the following entries, which are in accord with what I remember I did at the time; lines below show: "time", "channel tuned to", and "(my comment)":

20:32:05.747  BBC RB 301  (this is when I started watching, note time is one hour earlier)
21:25:49.407  BBC RB 301  (after channel freeze; returned to EPG and tried 301 again)
21:26:20.027  BBC News HD  (I now tried various channels to find one that worked)
21:27:33.945  CBS Reality 
21:27:55.662  4Seven
21:29:27.265  BBC News
21:29:52.257  Sky News
21:30:07:635  Al Jazeera Eng  (This is the first one that worked)

After the screen freeze, I tried the channels shown above, but none worked until I tried "Al Jazeera Eng". I also looked in "tvserver_TVService.3.log" at similar times, and in "tvserver_TsWriter.bak". All of the tuning attempts seem to be present, but no error messages!

-- from CyberSimian in the UK

 

[mm1352000]

After the screen freeze, I tried the channels shown above, but none worked until I tried "Al Jazeera Eng". I also looked in "tvserver_TVService.3.log" at similar times, and in "tvserver_TsWriter.bak". All of the tuning attempts seem to be present, but no error messages!

I wouldn't say "no error messages". In each case except 4seven you'll see the following error:
[2014-12-03 21:25:52,490] [Log ] [7 ] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 3 seconds. Increase the PMT timeout value?

Looking back to the BBC RB viewing, TsReader shows the freeze occurred here:
[2014-12-03 21:13:49,030] [1faeb4b0] [13a4] - Demux : Audio to render 0.701 Sec
[2014-12-03 21:23:21,617] [1faeb4b0] [ 824] - CTsReaderFilter:uration - correction to predicted duration: 9806.612 s
[2014-12-03 21:23:25,859] [1faeb4b0] [ 824] - CTsReaderFilter:uration - correction to predicted duration: 9806.612 s

I might have guessed it coincides with this in the TsWriter log:
[2014-12-03 21:07:47,291] [d2bf1e8] [1144] - Recorderid c9 Continuity error... 7 ( prev a ) - bad signal?
[2014-12-03 21:07:47,291] [d2bf1e8] [1144] - Recorderid c9 Continuity error... b ( prev 7 ) - bad signal?

Takes awhile longer than I'd have expected for you to stop timeshifting though. Were you timeshifting (ie. not viewing TV at the live point)?

 

[CyberSimian]

Takes awhile longer than I'd have expected for you to stop timeshifting though. Were you timeshifting (ie. not viewing TV at the live point)?

These days, if I am not expecting something to go wrong, I don't pay attention to factors that may subsequently turn out to be important. Was I time-shifting? Umm, I don't think that I was time-shifting, but if the logs say otherwise...

The time of the first "error" at 21:07:47 is curious, as that is much earlier than the time that I deduced for the more-widespread failure (screen freeze, with all-but-one recordings ending prematurely). In the UK, not all MUXes are broadcast with the same power, so channels on the less-powerful MUXes are more prone to momentary pixelation if one's aerial system is not optimal. Usually I have no problem with any of the MUXes, but over the past week or so I have had momentary pixelation on some channels, possibly caused by the atmospheric conditions in the UK at the moment. Could the error at 21:07:47 be a momentary drop out rather than the start of the widespread failure?

I determined the time of the widespread failure by looking at the recordings that ended prematurely. As they were incomplete, and most were repeated later in the week, I deleted them. However, I did keep one recording (for the radio science documentary "Frontiers"); this had almost completed, and is not repeated later in the week. I have just examined it again. The broadcast time was 21:00-21:30, so with 1 minute pre-padding and 5 minutes post-padding, the recording should have been 20:59-21:35, and these are the start and end times shown on the "Recorded Radio" panel. But when I play the recording, it terminates at 24 mins 8 secs, so this is how I deduced the time of 21:23:00 plus/minus 1 min for the time of the widespread failure.

The aspect that I find more concerning is the fact that the later recordings failed to start ("The 13th Warrior" and "Dallas"). After rebooting, these started immediately, so there was no signal problem with them; either TV Server or the tuner driver had got into a state where it could not start the recordings (which seems similar to the EPG problem in the other thread). If I am going on holiday for two weeks, and there is an "event" similar to the one in this thread, I could return home two weeks later to find that none of the scheduled recordings had taken place. That is why I would like to try to identify the cause of this problem, and arrive at a fix (if possible).

-- from CyberSimian in the UK

 

[mm1352000]

Could the error at 21:07:47 be a momentary drop out rather than the start of the widespread failure?

Yes, absolutely.

I determined the time of the widespread failure by looking at the recordings that ended prematurely. As they were incomplete, and most were repeated later in the week, I deleted them. However, I did keep one recording (for the radio science documentary "Frontiers"); this had almost completed, and is not repeated later in the week. I have just examined it again. The broadcast time was 21:00-21:30, so with 1 minute pre-padding and 5 minutes post-padding, the recording should have been 20:59-21:35, and these are the start and end times shown on the "Recorded Radio" panel. But when I play the recording, it terminates at 24 mins 8 secs, so this is how I deduced the time of 21:23:00 plus/minus 1 min for the time of the widespread failure.

That time agrees with the TsReader log entries that I pointed out. Given that you said you weren't timeshifting, I think it is safe to conclude that is when the problem was triggered.

The aspect that I find more concerning is the fact that the later recordings failed to start ("The 13th Warrior" and "Dallas"). After rebooting, these started immediately, so there was no signal problem with them; either TV Server or the tuner driver had got into a state where it could not start the recordings (which seems similar to the EPG problem in the other thread). If I am going on holiday for two weeks, and there is an "event" similar to the one in this thread, I could return home two weeks later to find that none of the scheduled recordings had taken place. That is why I would like to try to identify the cause of this problem, and arrive at a fix (if possible).

I understand your concern, but personally I don't find the behaviour surprising. Further, I don't think there is anything more we can do to identify the cause, and therefore I don't have any expectation of identifying a solution.

From my perspective the logs suggest the problem was triggered by something external to MP/TV Server. The strongest evidence for this is the fact that the stream from the tuner just stopped (the original "freeze") when TV Server wasn't actively interacting with any tuners. That being said, I'm not able to positively identify the cause so I can't completely rule TV Server out of the equation. There's nothing in the application or system event log at the time of the freeze, so all I can say is that in my opinion it is highly unlikely that TV Server is directly to blame.

Whether the true cause is signal strength/quality, overheating, driver issues, BDA issues, DirectShow issues, TV Server... a combination... something else... I can't say. I just don't know. There isn't enough information in the logs to confirm this, and I can't think of any other information that we could acquire now that would help us narrow it down. My gut feeling is that the cause is something to do with the tuner hardware or driver, but I can't prove that. I'd like to reiterate that the logs show this problem is similar but not identical to the previously experienced problem with the continuous EPG grabbing.

About the subsequent failed recordings...
When problems like this occur, a tuner graph rebuild (TV service restart) or even a driver reset (devcon or Windows reboot) are usually required to recover tuner function. TV Server repeatedly tried to start the recordings until the scheduled end times... but this was probably in vain. It is hard to do more than this because from TV Server's perspective there is no difference between the symptoms of this problem and the symptoms seen when trying to tune an inactive channel...