Project

General

Profile

Bug #5210

DVR: major issue: sky.de recordings end prematurely when OTA EPG grabber runs [stable git]

Added by da h4xX0rz1sT over 6 years ago. Updated about 6 years ago.

Status:
New
Priority:
Normal
Assignee:
Adam Sutton
Category:
PVR / DVR
Target version:
-
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)
Steps to reproduce:
  • record Sky.de channel
  • trigger OTA EPG grabber
Expected result:
  • No problem whatsoever
Actual result:
  • 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

History

#1

Updated by Jaroslav Kysela over 6 years ago

Do you use EITp/f (EPG running state)? Try to turn this off.

#2

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

#3

Updated by da h4xX0rz1sT over 6 years ago

If EIT p/f is off, OTA EPG grabber no longer takes down active recordings.

/HXZ

#4

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).

#5

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.

#6

Updated by da h4xX0rz1sT over 6 years ago

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

#7

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());
#8

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

#9

Updated by da h4xX0rz1sT over 6 years ago

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

#10

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

#11

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

#12

Updated by da h4xX0rz1sT about 6 years ago

Any news on that issue?

Thx
/HXZ

#13

Updated by Jaroslav Kysela about 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?).

#14

Updated by da h4xX0rz1sT about 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

#15

Updated by da h4xX0rz1sT about 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

Also available in: Atom PDF