Tvheadend

Could log '--trace dvr,service,subscription,mpegts' ?

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.

FYI TVHeadend automatically rescheduled the failed recording for a later time (4 hours later, on the same channel) and that recording finished successfully.

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

Full trace

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)

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 :(

This seems like a tvh restart... Is something in your system log why tvh was killed?

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.

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.

So the same recording again failed this morning, exactly the same time, even after the crontab entry has been removed.