LiveTV Recording: Error recording stream

[Erik 120]

@@Luke Here is a special one for you when you get a chance....I cannot figure it out...

 

I have recorded many shows using Emby Live TV (HDhomerun) and they work great (recorded 6 shows Thursday night and all correctly recorded). However, for about 4 weeks I have been trying to get "CBS News Sunday Morning" to record from 9am-10:30am on sundays and every time it never records the show and stays in the "scheduled" page. I can view the channel just fine and last week even watched it on one tuner while Emby should have recorded it with the other but still didn't record it.

 

Below is the error I get every time and the full log is attached.

2016-01-24 08:59:59.9685 Info App: Recording timer fired.
2016-01-24 09:00:00.0778 Error App: Error recording stream
	*** Error Report ***
	Version: 3.0.5818.0
	Command line: C:\Users\Administrator\AppData\Roaming\Emby-Server\System\MediaBrowser.ServerApplication.exe
	Operating system: Microsoft Windows NT 6.2.9200.0
	Processor count: 4
	64-Bit OS: True
	64-Bit Process: True
	Program data path: C:\Users\Administrator\AppData\Roaming\Emby-Server
	Application Path: C:\Users\Administrator\AppData\Roaming\Emby-Server\System\MediaBrowser.ServerApplication.exe
	Program with Id SH000191280000T635892408000000000C4.1 not found
	System.InvalidOperationException
	   at MediaBrowser.Server.Implementations.LiveTv.EmbyTV.EmbyTV.<RecordStream>d__81.MoveNext()
	--- End of stack trace from previous location where exception was thrown ---
	   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	   at MediaBrowser.Server.Implementations.LiveTv.EmbyTV.EmbyTV.<_timerProvider_TimerFired>d__76.MoveNext()

And this is an example of a scheduled recording that works perfectly.

2016-01-21 19:59:59.2755 Info App: Recording timer fired.
2016-01-21 19:59:59.3849 Info App: Streaming Channel hdhr_4.1
2016-01-21 19:59:59.4005 Info App: HttpClientManager GET: http://192.168.123.145/lineup.json
2016-01-21 19:59:59.4630 Debug App: Channels from http://192.168.123.145: [{"Name":"WGRZ-HD","Number":"2.1","Id":"hdhr_2.1","ChannelType":"TV","IsFavorite":true},{"Name":"WGRZ2-2","Number":"2.2","Id":"hdhr_2.2","ChannelType":"TV","IsFavorite":true},{"Name":"WGRZ2-3","Number":"2.3","Id":"hdhr_2.3","ChannelType":"TV","IsFavorite":true},{"Name":"WIVB-HD","Number":"4.1","Id":"hdhr_4.1","ChannelType":"TV","IsFavorite":true},{"Name":"CBLT-DT","Number":"5.1","Id":"hdhr_5.1","ChannelType":"TV","IsFavorite":true},{"Name":"WKBW-HD","Number":"7.1","Id":"hdhr_7.1","ChannelType":"TV","IsFavorite":true},{"Name":"LAFF","Number":"7.2","Id":"hdhr_7.2","ChannelType":"TV","IsFavorite":true},{"Name":"ESCAPE","Number":"7.3","Id":"hdhr_7.3","ChannelType":"TV","IsFavorite":true},{"Name":"CFTO","Number":"9.1","Id":"hdhr_9.1","ChannelType":"TV","IsFavorite":true},{"Name":"CHCH-DT","Number":"11.1","Id":"hdhr_11.1","ChannelType":"TV","IsFavorite":true},{"Name":"WNED-HD","Number":"17.1","Id":"hdhr_17.1","ChannelType":"TV","IsFavorite":true},{"Name":"Think","Number":"17.2","Id":"hdhr_17.2","ChannelType":"TV","IsFavorite":true},{"Name":"TVO","Number":"19.1","Id":"hdhr_19.1","ChannelType":"TV","IsFavorite":true},{"Name":"WNLO-HD","Number":"23.1","Id":"hdhr_23.1","ChannelType":"TV","IsFavorite":true},{"Name":"Bounce","Number":"23.2","Id":"hdhr_23.2","ChannelType":"TV","IsFavorite":true},{"Name":"WUTV-HD","Number":"29.1","Id":"hdhr_29.1","ChannelType":"TV","IsFavorite":true},{"Name":"TCN","Number":"29.2","Id":"hdhr_29.2","ChannelType":"TV","IsFavorite":true},{"Name":"Grit TV","Number":"29.3","Id":"hdhr_29.3","ChannelType":"TV","IsFavorite":true},{"Name":"CHCJ-DT","Number":"35.1","Id":"hdhr_35.1","ChannelType":"TV","IsFavorite":true},{"Name":"CITS-HD","Number":"36.1","Id":"hdhr_36.1","ChannelType":"TV","IsFavorite":true},{"Name":"CJMT","Number":"40.1","Id":"hdhr_40.1","ChannelType":"TV","IsFavorite":true},{"Name":"CIII-HD","Number":"41.1","Id":"hdhr_41.1","ChannelType":"TV","IsFavorite":true},{"Name":"CKVP-DT","Number":"42.1","Id":"hdhr_42.1","ChannelType":"TV","IsFavorite":true},{"Name":"WNYO-HD","Number":"49.1","Id":"hdhr_49.1","ChannelType":"TV","IsFavorite":true},{"Name":"CITYTV","Number":"57.1","Id":"hdhr_57.1","ChannelType":"TV","IsFavorite":true}]
2016-01-21 19:59:59.4786 Debug App: GetChannelStream - Waiting on tuner resource pool
2016-01-21 19:59:59.4786 Debug App: GetChannelStream - Unlocked resource pool
2016-01-21 19:59:59.4786 Info App: GetChannelStream: channel id: hdhr_4.1. stream id: 
2016-01-21 20:00:02.4988 Info App: Beginning recording.
2016-01-21 20:00:02.4988 Info App: Writing file to path: E:\Emby Server - TV Recordings\Series\The Big Bang Theory\The Big Bang Theory S09E03 The Bachelor Party Corrosion.ts
2016-01-21 20:00:02.4988 Info App: HttpClientManager GET: http://192.168.123.145:5004/auto/v4.1
 

Thanks,

Erik

Edited January 24, 2016 by Erik

[Luke 37007]

is it a series recording?

[Erik 120]

No, I did it as an individual recording.

[Erik 120]

@@Luke

 

I tried a recording again this morning with some additional info, all on the same channel. I had a test individual recording scheduled for 8-9am  (In Touch with Dr. Charles Stanley) and a series recording scheduled for 9-10:30am (CBS News Sunday Morning). Both recording were present in the "scheduled" tab and both show on the guide with the Red Circles indicating set for recording.

 

So...They both failed (1st@ 07:59:59.1043 and the 2nd@08:59:59.0566 to record the stream. So I went in and selected record on (CBS News Sunday Morning) at 09:54:16.0732 and it is recording successfully.

 

Log attached of course. If you can see something let me know.

 

The only thing I see is maybe a show naming issue between Emby and Schedules Direct? I see is that the scheduled recording is looking for the show ID (From log: Program with Id SH000191280000T635898456000000000C4.1 not found) but when I did the immediate recorded in the middle of the show (From Log: channel id: hdhr_4.1. stream id: BLANK).

 

Thanks Luke,

Erik

 

*Sorry for large log, had to cover the entire morning for all the events....

 

[Erik 120]

@@Luke

 

I think i have figured out what may be happening as i watched it try to record a show this evening and failed, yet at the same time a different recording was ok.

 

When i setup the scheduled recording the guide had the show scheduled for 20:01-20:31 (big bang theory on CBS, 4.1 antenna), at some point (im assuming during a guide refresh) the show was moved to 20:02-20:32.

 

However, the timer fired at a time of just before 20:00 and gave the error below, which makes sense as the show isn't scheduled to start until 20:02 so that Id wouldn't be in the guide at 20:00 and I noticed the show after it that I had scheduled to record also had moved a few minutes and had no red circles in the guide to indicate it would record. I removed the scheduled recording and re-scheduled it and now the red circle is there.

 

So it looks like a timing issue of some sort with emby firing the trigger at the incorrect time for the show.

 

Am I on the right track?

2016-02-04 19:59:58.5858 Info App: Recording timer fired.
2016-02-04 19:59:58.6170 Error App: Error recording stream
	*** Error Report ***
	Version: 3.0.5821.0
	Command line: C:\Users\Administrator\AppData\Roaming\Emby-Server\system\MediaBrowser.ServerApplication.exe
	Operating system: Microsoft Windows NT 6.2.9200.0
	Processor count: 4
	64-Bit OS: True
	64-Bit Process: True
	Program data path: C:\Users\Administrator\AppData\Roaming\Emby-Server
	Application Path: C:\Users\Administrator\AppData\Roaming\Emby-Server\system\MediaBrowser.ServerApplication.exe
	Program with Id EP009311820208T635902308000000000C4.1 not found
	System.InvalidOperationException
	   at MediaBrowser.Server.Implementations.LiveTv.EmbyTV.EmbyTV.<RecordStream>d__85.MoveNext()
	--- End of stack trace from previous location where exception was thrown ---
	   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	   at MediaBrowser.Server.Implementations.LiveTv.EmbyTV.EmbyTV.<_timerProvider_TimerFired>d__7a.MoveNext()

Edited February 5, 2016 by Erik

[mellomade 140]

I think I can provide some insight into why some of these scheduled recordings are being missed.  It likely has to with the detail of guide data provided by the network(s) and not Schedules Direct per se.  The detail in particular is the Program ID.  If a network provides generic show data - Schedules Direct will have data available for EmbyTV like this:

 

   "startTime": "2016-02-20T02:00Z",
   "endTime": "2016-02-20T03:00Z",
   "duration": 60,
   "qualifiers": ["CC", "DD 5.1", "HDTV", "New", "Stereo"],
   "ratings": [{
       "body": "USA Parental Rating",
       "code": "TVPG"
   }],
   "program": {
       "tmsId": "SH004468530000",
       "rootId": "188109",
       "seriesId": "188109",
       "subType": "Series",
       "title": "The Amazing Race",
       "releaseYear": 2001,
       "releaseDate": "2001-09-05",
       "origAirDate": "2001-09-05",
       "titleLang": "en",
       "descriptionLang": "en",
 

Note that the show title and the qualifiers mark it as new and with the correct title - but there is NO episode information (yet).  When the network updates their data and it is pulled into Schedules Direct - you get something like this:

"startTime": "2016-02-13T02:00Z",
   "endTime": "2016-02-13T03:00Z",
   "duration": 60,
   "qualifiers": ["CC", "DD 5.1", "HDTV", "New", "Season Premiere", "Stereo"],
   "ratings": [{
       "body": "USA Parental Rating",
       "code": "TVPG"
   }],
   "program": {
       "tmsId": "EP004468530188",
       "rootId": "12384201",
       "seriesId": "188109",
       "subType": "Series",
       "title": "The Amazing Race",
       "episodeTitle": "I Should've Been a Boy Scout",
 

Note that the tmsId (Program ID) has the prefix EP rather than SH for the episodes that record correctly.  I suspect that having the EP program ID information is a backend requirement for EmbyTV to make the recording.  Otherwise there is no episode information and therefore no way to identify and catalog the episode. 

 

This is all fine - however I think the main issue here with EmbyTV (and maybe @@Luke can confirm this) is that it does not force refresh the scheduled series data when the guide refreshes - so if there is any change to the data already downloaded for the date range you have entered - the scheduled recordings list does not see those updates and conflicts can arise.

 

For my example above - I have EmbyTV set to download 14 days of guide data.  On the 14th day - CBS has no episode information for 'The Amazing Race' yet.  So EmbyTV does not see that episode in the scheduled recordings list even though in the guide you can see the title and the fact that it is marked as new.  Now what will happen?  Let's say next week CBS updates the guide data and the update gets pulled into the Schedules Direct data and the EmbyTV guide sees this change.  Since that date has passed in the update window - will the scheduled recordings also update to reflect the change in the guide data? 

 

Guide data seems to be updated OK - but I don't know if the scheduled recordings JSON gets updated in the same manner.

[Luke 37007]

^ Thanks. Yea in dev what I've done is if we can't find a program based on the original program Id, then it's just going to find whatever program is in that time slot.

 

In addition to that, yes I will also have it clear out invalid series timers that occur as the guide data changes from day to day.

[mellomade 140]

^ Thanks. Yea in dev what I've done is if we can't find a program based on the original program Id, then it's just going to find whatever program is in that time slot.

 

But with the same title, right?  So if for some reason a show moves to a different day and time - then the timer would adapt based on the title and not just the time slot?