Actions
Bug #5210
open
DVR: major issue: sky.de recordings end prematurely when OTA EPG grabber runs [stable git]
Added by da h4xX0rz1sT over 6 years ago. Updated over 6 years ago.
Start date:
2018-09-16
Due date:
% Done:
0%
Estimated time:
Found in version:
4.2.6-47~g73404e4
Affected Versions:
Description
If you record a sky.de channel, when the EPG grabber runs, it will at some point stop the recording.
That behaviour is- not reproducible on "Das Erste HD" (open)
- not reproducible on "RTL HD" (encrypted HD+)
- 100% reproducible on "Sky Cinema" (encrypted Sky.de)
- record Sky.de channel
- trigger OTA EPG grabber
- No problem whatsoever
- Recording is stopped prematurely, and log/GUI show "completed OK" though percentage completed is <100, which of cause cannot be correct
Files
| premature.stop_Abgang.mit.Stil.png (44 KB) premature.stop_Abgang.mit.Stil.png | da h4xX0rz1sT, 2018-09-16 18:25 | ||
| premature.stop_atomic.blonde.png (96 KB) premature.stop_atomic.blonde.png | da h4xX0rz1sT, 2018-09-16 18:25 | ||
| Happy.Deathday.recording.taken.down.by.OTA-EPG-grabber.log (2.14 MB) Happy.Deathday.recording.taken.down.by.OTA-EPG-grabber.log | da h4xX0rz1sT, 2018-09-18 17:41 | ||
| Kingsman.The.Golden.Circle.recording.taken.down.by.OTA-EPG-grabber.extended_trace_patch.log (653 KB) Kingsman.The.Golden.Circle.recording.taken.down.by.OTA-EPG-grabber.extended_trace_patch.log | da h4xX0rz1sT, 2018-09-19 13:45 |
Updated by Jaroslav Kysela over 6 years ago
Do you use EITp/f (EPG running state)? Try to turn this off.
Updated by da h4xX0rz1sT over 6 years ago
Hi Jaroslav,
thanks for your reply.
EITp/f is on, yes. I'm currently running a test if the issue persists in "off" state.
Will update on this as soon as EPG grabber has finished.
/HXZ
Updated by da h4xX0rz1sT over 6 years ago
If EIT p/f is off, OTA EPG grabber no longer takes down active recordings.
/HXZ
Updated by Jaroslav Kysela over 6 years ago
You may turn off EITp/f start/stop detection only for selected channels. It depends on your usage. The broadcaster signaled that the broadcasting is interrupted or so.. For further analysis, a log data should be gathered (--trace dvr).
Updated by da h4xX0rz1sT over 6 years ago
OK, I've scheduled a test recording with --trace dvr for tomorrow afternoon:
Sep 17 19:11:37 tvhserver tvheadend[16346]: dvr: entry ec865935654fbb0ea4ed600100f9a92f "Hampstead Park - Aussicht auf Liebe" on "Sky Cinema +1" starting at 2018-09-18 13:49:30, scheduled for recording by "admin"
I'm sure it will be knocked out by OTA EPG grabber ... will post the log ASAP.
Updated by da h4xX0rz1sT over 6 years ago
- File Happy.Deathday.recording.taken.down.by.OTA-EPG-grabber.log Happy.Deathday.recording.taken.down.by.OTA-EPG-grabber.log added
OK, here is the log with '--trace dvr'. Recorded 'Happy Deathday' from 'Sky Cinema' on network 'DVB-S Astra1x'.
The test recording shown in my previous post failed because #5211. 3 of 4 recording failed today with no file written. For me, even more an issue than this one. Will push things forward to see if #5211 is also present on master ASAP.
The interesting stuff is right at the beginning and starting @ line 16862.
HTH,
/HXZ
Updated by Jaroslav Kysela over 6 years ago
Sep 18 16:42:58 tvhserver tvheadend[16300]: dvr: dvr event running check for Happy Deathday on Sky Cinema running 2 Sep 18 16:42:58 tvhserver tvheadend[16300]: dvr: dvr entry bf6af05b602cdc8e54e704709b6964b4 event Happy Deathday on Sky Cinema - EPG marking start .... Sep 18 17:05:26 tvhserver tvheadend[16300]: dvr: dvr event running check for Happy Deathday on Sky Cinema running 2 Sep 18 17:05:26 tvhserver tvheadend[16300]: dvr: dvr entry bf6af05b602cdc8e54e704709b6964b4 other running event Happy Deathday on Sky Cinema - EPG marking stop Sep 18 17:05:26 tvhserver tvheadend[16300]: subscription: 00DC: "DVR: Happy Deathday" unsubscribing from "Sky Cinema"
It looks like that the DVB event ID was changed or there are two events.
Try the patch bellow and report back the log (just lines for the recording):
iff --git a/src/dvr/dvr_db.c b/src/dvr/dvr_db.c
index 2cdea043a..e6668e866 100644
--- a/src/dvr/dvr_db.c
+++ b/src/dvr/dvr_db.c
@@ -2110,10 +2110,10 @@ void dvr_event_running(epg_broadcast_t *e, epg_source_t esrc, epg_running_t runn
if (esrc != EPG_SOURCE_EIT || e->dvb_eid == 0 || e->channel == NULL)
return;
- tvhtrace(LS_DVR, "dvr event running check for %s on %s running %d",
+ tvhtrace(LS_DVR, "dvr event running check for %s on %s running %d eid %d",
epg_broadcast_get_title(e, NULL),
channel_get_name(e->channel),
- running);
+ running, e->dvb_eid);
LIST_FOREACH(de, &e->channel->ch_dvrs, de_channel_link) {
if (running == EPG_RUNNING_NOW && de->de_dvb_eid == e->dvb_eid) {
if (de->de_running_pause) {
@@ -2170,9 +2170,9 @@ void dvr_event_running(epg_broadcast_t *e, epg_source_t esrc, epg_running_t runn
if (!de->de_running_stop ||
de->de_running_start > de->de_running_stop) {
atomic_add(&de->de_running_change, 1);
- tvhdebug(LS_DVR, "dvr entry %s %s %s on %s - EPG marking stop",
+ tvhdebug(LS_DVR, "dvr entry %s %s %s (eid %d) on %s - EPG marking stop",
idnode_uuid_as_str(&de->de_id, ubuf), srcname,
- epg_broadcast_get_title(e, NULL),
+ epg_broadcast_get_title(e, NULL), de->de_dvb_eid,
channel_get_name(de->de_channel));
}
atomic_set_time_t(&de->de_running_stop, gclk());
Updated by da h4xX0rz1sT over 6 years ago
Thank you Jaroslav.
I'll apply the patch, recompile, retest and send the log tomorrow at noon, if I manage to do it - many tasks on my agenda tomorrow. If not, pls allow some hours of delay, will send it, promised :)
/HXZ
Updated by da h4xX0rz1sT over 6 years ago
- File Kingsman.The.Golden.Circle.recording.taken.down.by.OTA-EPG-grabber.extended_trace_patch.log Kingsman.The.Golden.Circle.recording.taken.down.by.OTA-EPG-grabber.extended_trace_patch.log added
OK, here's the log. Seems it does not change eventID - eventID is also unique in the whole log.
At the end it shows "Kingsman: The Golden Circle" as not running and "Flatliners" (the next upcoming event) as running, which was not the case. EIT p/f works perfectly on that channel, except OTA EPG is running.
Sep 19 12:11:58 tvhserver tvheadend[7176]: dvr: entry 51fa491ad03bbeb881aa305e21da0974 "Kingsman: The Golden Circle" on "Sky Cinema" starting at 2018-09-19 11:04:30, scheduled for recording by "admin" Sep 19 12:11:58 tvhserver tvheadend[7176]: dvr: "Kingsman: The Golden Circle" on "Sky Cinema" recorder starting Sep 19 12:11:58 tvhserver tvheadend[7176]: dvr: About to set stop timer for "Kingsman: The Golden Circle" on "Sky Cinema" at start 1537347900 and original stop 1537356900 and overall stop at 1537356900 Sep 19 12:12:00 tvhserver tvheadend[7176]: dvr: /media/recordings/Kingsman_-The-Golden-Circle/Kingsman_-The-Golden-Circle.Sky-Cinema.2018-09-19.11-05.mkv from adapter: "SAT>IP OctopusNet S2/4 DVB-S #1", network: "DVB-S Astra1x", mux: "11914.5H", provider: "SKY", service: "Sky Cinema HD" Sep 19 12:12:00 tvhserver tvheadend[7176]: dvr: # type lang resolution aspect ratio sample rate channels Sep 19 12:12:00 tvhserver tvheadend[7176]: dvr: 1 H264 1920x1080 16:9 Sep 19 12:12:00 tvhserver tvheadend[7176]: dvr: 2 AC3 ger 48000 5.1 Sep 19 12:12:00 tvhserver tvheadend[7176]: dvr: 3 AC3 eng 48000 2 [...] Sep 19 12:19:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:19:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:20:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:20:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:21:26 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:21:26 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:21:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:21:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:22:17 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:22:17 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:22:27 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:22:27 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:23:16 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:23:16 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:23:46 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:23:46 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:23:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:23:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:25:31 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:25:31 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:29:36 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:29:36 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:30:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:30:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:30:12 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:30:12 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:30:42 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:30:42 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:31:31 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:31:31 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:31:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:31:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:32:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:32:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:32:26 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:32:26 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:32:47 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:32:47 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:32:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:32:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:33:52 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:33:52 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:35:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:35:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:42:11 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:42:11 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:42:42 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:42:42 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:45:52 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:45:52 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:46:22 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:46:22 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:46:41 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:46:41 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:47:11 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:47:11 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:48:31 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:48:31 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:48:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:48:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:49:21 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:49:21 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:49:26 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:49:26 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:49:57 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:49:57 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:50:27 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:50:27 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:50:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:50:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:51:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:51:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:51:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:51:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:54:25 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:54:25 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:54:37 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:54:37 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:54:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:54:56 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:55:07 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:55:07 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:56:46 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:56:46 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:57:17 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:57:17 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:57:41 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 12:57:41 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:00:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:00:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:04:36 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:04:36 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:05:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:05:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:05:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:05:06 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:05:31 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:05:31 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:05:50 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:05:50 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:06:20 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:06:20 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:07:46 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:07:46 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:10:46 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:10:46 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:12:21 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:12:21 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:12:27 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:12:27 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:12:50 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:12:50 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:15:45 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:15:45 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:16:21 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:16:21 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:16:51 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:16:51 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:18:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:18:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:19:11 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:19:11 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:19:42 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:19:42 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:20:41 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:20:41 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:21:01 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:21:02 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:21:32 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:21:32 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:22:19 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:22:19 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:22:45 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 2 eid 8567 Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 0 eid 8567 Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: dvr event running check for Kingsman: The Golden Circle on Sky Cinema running 0 eid 8567 Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: dvr entry 51fa491ad03bbeb881aa305e21da0974 event Kingsman: The Golden Circle (eid 8567) on Sky Cinema - EPG marking stop Sep 19 13:23:16 tvhserver tvheadend[7176]: subscription: 000E: "DVR: Kingsman: The Golden Circle" unsubscribing from "Sky Cinema" Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: entry 51fa491ad03bbeb881aa305e21da0974 - set state - state COMPLETED rec_state FINISHED error 'OK' Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: adding inotify watch to /srv/dev-disk-by-label-FireCuda/recordings/Kingsman_-The-Golden-Circle (fd=221) Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: entry 51fa491ad03bbeb881aa305e21da0974 when 1970-01-01;01:00:00(+0100) - retention arm Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: "Kingsman: The Golden Circle" on "Sky Cinema": End of program: Completed OK Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: entry 51fa491ad03bbeb881aa305e21da0974 when 1970-01-01;01:00:00(+0100) - retention arm Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: dvr entry 51fa491ad03bbeb881aa305e21da0974 event Kingsman: The Golden Circle on Sky Cinema - EPG stop Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: dvr event running check for Flatliners on Sky Cinema running 2 eid 8568 Sep 19 13:23:16 tvhserver tvheadend[7176]: dvr: entry 51fa491ad03bbeb881aa305e21da0974 - retention timer - disarm
I've attached the full log for your reference just in case you need it.
HTH,
/HXZ
Updated by da h4xX0rz1sT over 6 years ago
Pls forget my previous post. I'm sorry - this time it worked, the recording was complete until the end.
When you want those errors to come up, they don't - first time this happened. I'll have to retry ;)
/HXZ
Updated by da h4xX0rz1sT over 6 years ago
OK, here is a proper log.
Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 - assign broadcast 1305727 Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 start 2018-09-20;16:59:30(+0200) stop 2018-09-20;19:45:00(+0200) - set timer Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 start 2018-09-20;16:59:30(+0200) - set timer - schedule Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 "Blade Runner 2049" on "Sky Cinema +1" starting at 2018-09-20 16:59:30, scheduled for recording by "admin" Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 start 2018-09-20;16:59:30(+0200) stop 2018-09-20;19:45:00(+0200) - set timer Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 start 2018-09-20;16:59:30(+0200) - set timer - schedule Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 start 2018-09-20;16:59:30(+0200) stop 2018-09-20;19:45:00(+0200) - set timer Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 start 2018-09-20;16:59:30(+0200) - set timer - schedule Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 - set state - state RECORDING rec_state PENDING error 'OK' Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: "Blade Runner 2049" on "Sky Cinema +1" recorder starting Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: About to set stop timer for "Blade Runner 2049" on "Sky Cinema +1" at start 1537455600 and original stop 1537465500 and overall stop at 1537465500 Sep 20 17:45:13 tvhserver tvheadend[22306]: mpegts: 12070.5H in DVB-S Astra1x - tuning on SAT>IP OctopusNet S2/4 DVB-S #1 Sep 20 17:45:13 tvhserver tvheadend[22306]: subscription: 000F: "DVR: Blade Runner 2049" subscribing on channel "Sky Cinema +1", weight: 300, adapter: "SAT>IP OctopusNet S2/4 DVB-S #1", network: "DVB-S Astra1x", mux: "12070.5H", provider: "SKY", service: "Sky Cinema +1 HD", profile="matroska" Sep 20 17:45:13 tvhserver tvheadend[22306]: dvr: a7af7cebf116ce7667ddaaae01d92132 - recoding thread started for "Blade Runner 2049" Sep 20 17:45:14 tvhserver tvheadend[22306]: TS: DVB-S Astra1x/12070.5H/Sky Cinema +1 HD Transport error indicator (total 1) Sep 20 17:45:14 tvhserver tvheadend[22306]: dvr: dvr event running check for Blade Runner 2049 on Sky Cinema +1 running 2 eid 10535 Sep 20 17:45:14 tvhserver tvheadend[22306]: dvr: dvr entry a7af7cebf116ce7667ddaaae01d92132 event Blade Runner 2049 on Sky Cinema +1 - EPG marking start [...] Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: a7af7cebf116ce7667ddaaae01d92132 - running flag changed from 0 to 1 Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 - set state - state RECORDING rec_state RUNNING error 'OK' Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 - set state - state RECORDING rec_state WAIT error 'OK' Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: File "/media/recordings/Blade-Runner-2049/Blade-Runner-2049.Sky-Cinema-+1.2018-09-20.17-00.mkv" -- No such file or directory -- Using for recording Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: /media/recordings/Blade-Runner-2049/Blade-Runner-2049.Sky-Cinema-+1.2018-09-20.17-00.mkv from adapter: "SAT>IP OctopusNet S2/4 DVB-S #1", network: "DVB-S Astra1x", mux: "12070.5H", provider: "SKY", service: "Sky Cinema +1 HD" Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: # type lang resolution aspect ratio sample rate channels Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: 1 H264 1920x1080 16:9 Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: 2 AC3 ger 48000 5.1 Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: 3 AC3 eng 48000 2 Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: a7af7cebf116ce7667ddaaae01d92132 - muxing activated Sep 20 17:45:15 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 - set state - state RECORDING rec_state RUNNING error 'OK' Sep 20 17:45:16 tvhserver tvheadend[22306]: dvr: dvr event running check for Blade Runner 2049 on Sky Cinema +1 running 2 eid 10535 [... message above repeated some times every minute or so ...] Sep 20 18:00:07 tvhserver tvheadend[22306]: dvr: dvr event running check for Blade Runner 2049 on Sky Cinema +1 running 2 eid 10535 Sep 20 18:00:07 tvhserver tvheadend[22306]: dvr: dvr event running check for Blade Runner 2049 on Sky Cinema +1 running 2 eid 10535 Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: dvr event running check for Blade Runner 2049 on Sky Cinema +1 running 2 eid 10548 Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: dvr entry a7af7cebf116ce7667ddaaae01d92132 other running event Blade Runner 2049 (eid 10535) on Sky Cinema +1 - EPG marking stop Sep 20 18:00:34 tvhserver tvheadend[22306]: subscription: 000F: "DVR: Blade Runner 2049" unsubscribing from "Sky Cinema +1" Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 - set state - state COMPLETED rec_state FINISHED error 'OK' Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: adding inotify watch to /srv/dev-disk-by-label-FireCuda/recordings/Blade-Runner-2049 (fd=94) Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 when 1970-01-01;01:00:00(+0100) - retention arm Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: "Blade Runner 2049" on "Sky Cinema +1": End of program: Completed OK Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 when 1970-01-01;01:00:00(+0100) - retention arm Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: dvr entry a7af7cebf116ce7667ddaaae01d92132 other running event Blade Runner 2049 on Sky Cinema +1 - EPG stop Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: dvr entry 8460c1f81253816a14f3e3300ae48a3e event Blade Runner 2049 on Sky Cinema +1 - EPG marking start Sep 20 18:00:34 tvhserver tvheadend[22306]: dvr: entry a7af7cebf116ce7667ddaaae01d92132 - retention timer - disarm
Seems you were right and it really changes eventID...
HTH,
/HXZ
Updated by Jaroslav Kysela over 6 years ago
No, we rely on the event id at the moment. Perhaps, there's a commercial or so and the broadcaster changed the event id for this. In this case, we should determine other unique EPG event identification (CRID?).
Updated by da h4xX0rz1sT over 6 years ago
No, there is no commercial in that moment. Sky Cinema has commercials only before or after the movies. If it just had cut a commercial, I wouldn't mind ;)
In fact, it is right during the movie.
I don't know why they change the eventID, possibly their mistake, or willingly to trap non-Sky devices or so, that's the only thing I could imagine. eventID should be unique and fixed IMHO, but obviously it isn't.
I don't know if eventID could be replaced by CRID, if it's always present, unique and fixed. Just using the title of the broadcast of cause could be non-unique.
Maybe there is a simpler workaround to not update/always update current recordings' eventIDs.
HTH,
/HXZ
Updated by da h4xX0rz1sT over 6 years ago
Seems like this issue still persists with master git 4.3-1469~g5c14193ed.
However, the behaviour is a little different. 4.2 stable just stopped, as if I had pressed stop button for the recording. Master just hangs at that point, the recording is no longer growing in size, and status shows the well-known 0kbps output size.
HTH,
/HXZ
Actions