Bug #3904
dvr recording unexpectedly stops short with accurate recording enabled
0%
Description
Using TVH connected to DVB-T2 USB adapter tuned into UK Freeview and OTA EPG grabbers.
Recorded two consecutive programmes on BBC One HD - BBC News at Ten and This Is BBC One HD.
Under DVR recording profiles I have 'Extra warming up time' set to 60 seconds and 'Use EPG running state' enabled. There is no pre/post-padding set.
BBC News at Ten was scheduled to start at 10.00pm with a duration of 30 mins. This is BBC One HD was scheduled to start at 10.30pm with a duration of 15 mins.
I would expect the first recording to end and the second to start immediately. Watching both files, what happens is both started at the correct EPG AR time but the recording of the first programme on disk was cut short to c. 30 mins even though the programme lasted over 32 mins.
tvheadend extract from syslog below
Jul 19 21:59:00 haribo tvheadend[1281]: dvr: "BBC News at Ten" on "BBC ONE HD" recorder starting Jul 19 21:59:00 haribo tvheadend[1281]: service: 2: BBC ONE HD si 0x7f6ac4009650 Silicon Labs Si2168 : DVB-T #0 weight 0 prio 10 error 0 Jul 19 21:59:00 haribo tvheadend[1281]: mpegts: 618.167MHz in Hannington - tuning on Silicon Labs Si2168 : DVB-T #0 Jul 19 21:59:00 haribo tvheadend[1281]: linuxdvb: Silicon Labs Si2168 : DVB-T #0 - starting 618.167MHz in Hannington Jul 19 21:59:00 haribo tvheadend[1281]: mpegts: 618.167MHz in Hannington - started ... Jul 19 21:59:55 haribo tvheadend[1281]: dvr: dvr entry e5fec9969b15b80b52b48b2c14dcf676 event BBC News at Ten on BBC ONE HD - EPG marking start Jul 19 21:59:55 haribo tvheadend[1281]: dvr: File "/home/shared/openshare/kodi_test_files/.inprogress/BBC-ONE-HD/2016-07-19/2016-07-19-22-00-BBC-News-at-Ten-.mkv" -- No such file or directory -- Using for recording Jul 19 21:59:55 haribo tvheadend[1281]: dvr: /home/shared/openshare/kodi_test_files/.inprogress/BBC-ONE-HD/2016-07-19/2016-07-19-22-00-BBC-News-at-Ten-.mkv from adapter: "Silicon Labs Si2168 : DVB-T #0", network: "Hannington", mux: "618.167MHz", provider: "<N/A>", service: "BBC ONE HD" Jul 19 21:59:55 haribo tvheadend[1281]: dvr: # type lang resolution aspect ratio sample rate channels Jul 19 21:59:55 haribo tvheadend[1281]: dvr: 1 H264 1920x1080 16:9 Jul 19 21:59:55 haribo tvheadend[1281]: dvr: 2 AAC eng 48000 2 Jul 19 21:59:55 haribo tvheadend[1281]: dvr: 3 AAC eng ? ? <disabled, no valid input> Jul 19 21:59:55 haribo tvheadend[1281]: dvr: 4 DVBSUB eng ... Jul 19 22:29:00 haribo tvheadend[1281]: dvr: "This Is BBC One HD" on "BBC ONE HD" recorder starting Jul 19 22:29:00 haribo tvheadend[1281]: service: 2: BBC ONE HD si 0x7f6ac400a960 Silicon Labs Si2168 : DVB-T #0 weight -1 prio 9 error 0 Jul 19 22:29:00 haribo tvheadend[1281]: subscription: 005E: "DVR: This Is BBC One HD" subscribing on channel "BBC ONE HD", weight: 300, adapter: "Silicon Labs Si2168 : DVB-T #0", network: "Hannington", mux: "618.167MHz", service: "BBC ONE HD", profile="matroska" Jul 19 22:30:00 haribo tvheadend[1281]: subscription: 005D: "DVR: BBC News at Ten" unsubscribing from "BBC ONE HD" Jul 19 22:30:00 haribo tvheadend[1281]: dvr: "BBC News at Ten" on "BBC ONE HD": End of program: Completed OK ... Jul 19 22:32:37 haribo tvheadend[1281]: dvr: dvr entry 35bce60baab3c83ac38a991b792b19bd event This Is BBC One HD on BBC ONE HD - EPG marking start Jul 19 22:32:37 haribo tvheadend[1281]: dvr: File "/home/shared/openshare/kodi_test_files/.inprogress/BBC-ONE-HD/2016-07-19/2016-07-19-22-30-This-Is-BBC-One-HD-.mkv" -- No such file or directory -- Using for recording Jul 19 22:32:37 haribo tvheadend[1281]: dvr: /home/shared/openshare/kodi_test_files/.inprogress/BBC-ONE-HD/2016-07-19/2016-07-19-22-30-This-Is-BBC-One-HD-.mkv from adapter: "Silicon Labs Si2168 : DVB-T #0", network: "Hannington", mux: "618.167MHz", provider: "<N/A>", service: "BBC ONE HD" Jul 19 22:32:37 haribo tvheadend[1281]: dvr: # type lang resolution aspect ratio sample rate channels Jul 19 22:32:37 haribo tvheadend[1281]: dvr: 1 H264 1920x1080 16:9 Jul 19 22:32:37 haribo tvheadend[1281]: dvr: 2 AAC eng 48000 2 Jul 19 22:32:37 haribo tvheadend[1281]: dvr: 3 AAC eng ? ? <disabled, no valid input> Jul 19 22:32:37 haribo tvheadend[1281]: dvr: 4 DVBSUB eng Jul 19 22:32:38 haribo tvheadend[1281]: epg: expire event 321853 (BBC News at Ten) from BBC ONE HD
Notice the epg expire event comes at 22:32:38 but the recording stopped at 22:30:00.
Using ffmpeg confirmed file duration of BBC News at Ten is only 00:30:05.80.
Files
History
Updated by Mark Clarkstone over 8 years ago
Updated by dj bloc wrote:
.. snip ...
This looks like the BBC screwed the EITp/f, I've seen this myself. Unfortunately there isn't a lot you can do. You should also be seeing additional debug messages like "Waiting for EPG running flag" etc.
Updated by dj bloc over 8 years ago
Updated by Mark Clarkstone wrote:
This looks like the BBC screwed the EITp/f, I've seen this myself. Unfortunately there isn't a lot you can do. You should also be seeing additional debug messages like "Waiting for EPG running flag" etc.
I don't think that's is the case in this instance. If you look at the last log TVH registers the expire event at 22:32:38 yet the recording stop at 22:30:00.
Updated by Jaroslav Kysela over 8 years ago
Updated by dj bloc wrote:
Mark Clarkstone wrote:
This looks like the BBC screwed the EITp/f, I've seen this myself. Unfortunately there isn't a lot you can do. You should also be seeing additional debug messages like "Waiting for EPG running flag" etc.
I don't think that's is the case in this instance. If you look at the last log TVH registers the expire event at 22:32:38 yet the recording stop at 22:30:00.
The event expiration (removal from the TVH EPG database) has nothing to do with EITp/f. The broadcaster signaled the event stop sooner.
Updated by dj bloc over 8 years ago
Jaroslav Kysela wrote:
<snip> The broadcaster signaled the event stop sooner.
Isn't the receiving of the EIT start flag for the subsequent event effectively the stop signal for the current event? Based on the above example this would have happened at 22:32:37.
Updated by dj bloc over 8 years ago
For comparison I ran a similar setup again on the 29th July. This time I also scheduled using Humax PVR for comparison. Same TV aerial input.
Playback of the two sets of video files confirms:
BBC News at Ten - Both TVH and HUMAX start at the same point (EIT transition). HUMAX stops recording at the EIT transition to 'This is BBC One HD' event. TVH incorrectly stops recording at scheduled/EPG stop time
This is BBC One HD - Both TVH and HUMAX start at the same point. Both HUMAX and TVH stop recording at the EIT transition.
Updated by Mark Clarkstone over 8 years ago
dj bloc wrote:
Jaroslav Kysela wrote:
<snip> The broadcaster signaled the event stop sooner.
Isn't the receiving of the EIT start flag for the subsequent event effectively the stop signal for the current event? Based on the above example this would have happened at 22:32:37.
In the UK yes, but not necessarily everywhere else. I suppose the "Use EPG running state" should be changed to multiple choice with two options, "Standard" and "Stop when next event starts".
Updated by Jaroslav Kysela over 8 years ago
Could you upgrade to v4.1-2163-geb90c21 and provide '--trace dvr' ? I improved logs, so we can check better what's going on.
Updated by dj bloc over 8 years ago
Jaroslav Kysela wrote:
Could you upgrade to v4.1-2163-geb90c21 and provide '--trace dvr' ? I improved logs, so we can check better what's going on.
Upgraded to 4.1-2166~ge7f90e7~trusty this evening. Switched dvr trace on. Used web interface to schedule consecutive recordings through EPG - 'BBC News at Ten' and 'This is BBC One HD' at 21:07:03 and 21:07:13.
'BBC News at Ten' EPG scheduled time was 22:00 to 22:20.
'This is BBC One HD' EPG scheduled time was 22:20 to 22:30.
trace file attached.
Updated by Jaroslav Kysela over 8 years ago
And where's an issue?
2016-08-17 22:00:06.228 [ DEBUG]:dvr: dvr entry 35fb80866f45e7faf3d062a40b4dea3b event BBC News at Ten on BBC ONE HD - EPG marking start 2016-08-17 22:00:06.584 [ INFO]:dvr: /home/shared/openshare/kodi_test_files/.inprogress/BBC-ONE-HD/2016-08-17/2016-08-17-22-00-BBC-News-at-Ten-.mkv from adapter: "Silicon Labs Si2168 : DVB-T #0", network: "Hannington", mux: "618.167MHz", provider: "<N/A>", service: "BBC ONE HD" 2016-08-17 22:21:07.193 [ DEBUG]:dvr: dvr entry 35fb80866f45e7faf3d062a40b4dea3b event BBC News at Ten on BBC ONE HD - EPG marking stop 2016-08-17 22:21:07.202 [ INFO]:dvr: "BBC News at Ten" on "BBC ONE HD": End of program: Completed OK 2016-08-17 22:21:07.202 [ DEBUG]:dvr: dvr entry ecca24c000421debeec981e2339c9b12 event This Is BBC One HD on BBC ONE HD - EPG marking start 2016-08-17 22:21:07.217 [ INFO]:dvr: /home/shared/openshare/kodi_test_files/.inprogress/BBC-ONE-HD/2016-08-17/2016-08-17-22-20-This-Is-BBC-One-HD-.mkv from adapter: "Silicon Labs Si2168 : DVB-T #0", network: "Hannington", mux: "618.167MHz", provider: "<N/A>", service: "BBC ONE HD" 2016-08-17 22:30:48.227 [ DEBUG]:dvr: dvr entry ecca24c000421debeec981e2339c9b12 event This Is BBC One HD on BBC ONE HD - EPG marking stop 2016-08-17 22:30:48.242 [ INFO]:dvr: "This Is BBC One HD" on "BBC ONE HD": End of program: Completed OK