Bug #3935
Recordings failing with "Source deleted" error
0%
Description
In the last couple of days, I've noticed some recordings (both encrypted and FTA) are failing with the error in the UI being logged as "Source deleted". I've got debugging turned on by default on my box so I managed to capture the following logs;
root@TVHeadend:~/tvheadend_master# cat /tmp/tvheadend.log | grep "Premier League Highlights"
2016-08-14 03:37:23.100 [ INFO]:dvr: entry 6cf48fba9cc673e6df322bc910395de7 "Premier League Highlights" on "Sky Sports 1" starting at 2016-08-14 03:58:30, scheduled for recording by "WiFi"
2016-08-14 03:58:30.002 [ INFO]:dvr: "Premier League Highlights" on "Sky Sports 1" recorder starting
2016-08-14 03:58:30.539 [ INFO]:subscription: 03AF: "DVR: Premier League Highlights" subscribing on channel "Sky Sports 1", weight: 300, adapter: "TurboSight TBS 6984 DVBS/S2 frontend : DVB-S #0", network: "Sky UK", mux: "12109.5H", provider: "BSkyB", service: "Sky Sports 1", profile="pass"
2016-08-14 03:59:00.039 [ TRACE]:dvr: Creating directory "/mnt/recordedtv/Premier League Highlights" with octal permissions "777" gid -1 uid -1
2016-08-14 03:59:00.041 [ DEBUG]:dvr: File "/mnt/recordedtv/Premier League Highlights/Premier League Highlights_Sky Sports 1_2016-08-14_04-00.ts" -- No such file or directory -- Using for recording
2016-08-14 03:59:00.042 [ INFO]:dvr: /mnt/recordedtv/Premier League Highlights/Premier League Highlights_Sky Sports 1_2016-08-14_04-00.ts from adapter: "TurboSight TBS 6984 DVBS/S2 frontend : DVB-S #0", network: "Sky UK", mux: "12109.5H", provider: "BSkyB", service: "Sky Sports 1"
2016-08-14 04:00:02.088 [ ERROR]:dvr: Recording stopped: "/mnt/recordedtv/Premier League Highlights/Premier League Highlights_Sky Sports 1_2016-08-14_04-00.ts": Subscription overridden
2016-08-14 04:00:02.432 [ INFO]:subscription: 03AF: "DVR: Premier League Highlights" unsubscribing from "{name-not-set}"
2016-08-14 04:00:02.432 [ INFO]:dvr: "Premier League Highlights" on "{name-not-set}": End of program: Source deleted
The error in the log seems to be "Subscription overridden" but from what I can gather, this should only happen when you run out of tuners and a higher priority recording takes over.
I have eight tuners in my box (four of which were eligible to record this programe on satellite) so it's not an issue with running out of tuners.
What is interesting is the channel name changing from "*Sky Sports 1*" to "*{name-not-set}*" - I've seen this with channels whose services have been lost/deleted but I checked this morning and the channel in question is still there (and working) and I know for a fact that it didn't "disappear" as it still has its tag (which is removed by TVHeaded if the service disappears). There is a small fragment of the recording on disk, and this plays perfectly fine, so it doesn't appear to be a downstream decryption issue (the oscam logs show that the subscription was simply removed at the time TVHeadend decided to stop recording).
Any idea's?
Linux version: Ubuntu 16.04
Kernel version: 4.4.0-31
TVHeadend version: 4.1-2154~ge3e8a79
DVB Card: TBS-6984 (four DVB-S/S2 tuners)
History
Updated by Jaroslav Kysela over 8 years ago
Updated by Could log '--trace dvr,service,subscription,mpegts' ?
Updated by Jonathan Thomson over 8 years ago
Updated by Jaroslav Kysela wrote:
Could log '--trace dvr,service,subscription,mpegts' ?
The above trace includes dvr but I'll need to enable the others and keep my fingers crossed that I catch another instance of the error.
Updated by Jonathan Thomson over 8 years ago
FYI TVHeadend automatically rescheduled the failed recording for a later time (4 hours later, on the same channel) and that recording finished successfully.
Updated by Jonathan Thomson over 8 years ago
Managed to catch another one;
A recording was scheduled to start on Tue 08/16/2016 4:58:30 AM but stopped recording after writing only 400kb to disk.
The basic logs look pretty much as per my previous example above but I've also captured the full trace logs as requested - link at the bottom of this post.
2016-08-16 04:59:00.329 [ DEBUG]:dvr: File "/mnt/recordedtv/Paw Patrol/Paw Patrol_Nick Jr._2016-08-16_05-00.ts" -- No such file or directory -- Using for recording
2016-08-16 04:59:00.330 [ INFO]:dvr: /mnt/recordedtv/Paw Patrol/Paw Patrol_Nick Jr._2016-08-16_05-00.ts from adapter: "TurboSight TBS 6984 DVBS/S2 frontend : DVB-S #0", network: "Sky UK", mux: "12265.5H", provider: "BSkyB", service: "Nick Jr."
2016-08-16 04:59:02.174 [ ERROR]:dvr: Recording stopped: "/mnt/recordedtv/Paw Patrol/Paw Patrol_Nick Jr._2016-08-16_05-00.ts": Subscription overridden
2016-08-16 04:59:02.267 [ INFO]:subscription: 001C: "DVR: Paw Patrol" unsubscribing from "{name-not-set}"
2016-08-16 04:59:02.267 [ INFO]:dvr: "Paw Patrol" on "{name-not-set}": End of program: Source deleted
Updated by Jonathan Thomson over 8 years ago
And here I've isolated the trace down to only the DVB-S inputs (this was a DVB-S recording that failed, as was the one in the original bug report)
Updated by Jonathan Thomson over 8 years ago
Couple of things stand out to my untrained eye;
Firstly, right before the recording stops, TVHeadend seems to kill the transport stream;
2016-08-16 04:59:02.174 [ INFO]:mpegts: 12265.5H in Sky UK (0x55b4f9051460) - deleting
...and then 'stops' the mux (whatever that means)...
2016-08-16 04:59:02.174 [ DEBUG]:mpegts: 12265.5H in Sky UK - stopping mux (forced)
...then this happens...
2016-08-16 04:59:02.174 [ TRACE]:mpegts: TurboSight TBS 6984 DVBS/S2 frontend : DVB-S #0 - flush subscribers 2016-08-16 04:59:02.174 [ TRACE]:mpegts: table: mux 0x55b4f9051460 destroy pmt 02/FF (2) pid 0112 (274) 2016-08-16 04:59:02.174 [ TRACE]:mpegts: table: mux 0x55b4f9051460 free pmt 02/FF (2) pid 0112 (274)
...before the recording eventually fails with the error 'Subscription overridden'...
2016-08-16 04:59:02.174 [ ERROR]:dvr: Recording stopped: "/mnt/recordedtv/Paw Patrol/Paw Patrol_Nick Jr._2016-08-16_05-00.ts": Subscription overridden
But I'm still unclear what causes the whole thing to fall over 
Updated by Jaroslav Kysela over 8 years ago
This seems like a tvh restart... Is something in your system log why tvh was killed?
Updated by Jonathan Thomson over 8 years ago
I've found the culprit, there was a rogue crontab entry that was restarting TVHeadend at 4am without checking for active subscriptions - I'm now writing a bash script to handle that.
Please accept my apologies and close the bug.
Updated by Jonathan Thomson over 8 years ago
Mmm actually the crontab entry is an hour before the failed recordings occur - so in the original example, it was a perfect match, the recording ended abruptly when TVHeadend was restarted, but in the latest example, the failure is an hour after TVHeadend is restarted.
I've commented out the crontab entry but for now please don't close down the issue as crontab might be a red herring.
Updated by Jonathan Thomson over 8 years ago
So the same recording again failed this morning, exactly the same time, even after the crontab entry has been removed.