Bug #5494
EITp/f fails if EPG is from a different network
0%
Description
I have two tuners connected to my Pi-based TVHeadend system, one DVB-T2 and one DVB-S2. EIT-based recordings fail (start at the wrong time or occasionally are missed) when both tuners are in use.
The attached files illustrate the problem.
Two events are allocated to different tuners (they don't have a common mux). The Channel 5 recording is correctly triggered by its Running Status. However the BBC Four recording starts shortly after its advertised start time of 19:00:00 despite the fact that the Running Status only changes at 19:00:03.881.
I have a utility dvbrs (https://github.com/dave-p/dvbrs) which monitors running status (log attached), and this confirms that the BBC Four r/s changed at 19:00:03:864.
Files
History
Updated by Jaroslav Kysela almost 6 years ago
If there are no running state updates in the warm-up window, the TVH uses the advertised start from EPG.
It seems that the EPG running updates around 18:59:06 are missed. I need more logs for tbl-eit system to see what's going on.
Updated by Dave Pickles almost 6 years ago
I'm using service 8951 for BBC Four, and there indeed wasn't a r/s update for that sid in the warm-up window. Also possibly this example is a special case, since BBC Four is a part-time channel which only comes on-air at 19:00. I'll do some more research with other channel pairs to try to replicate the issue.
Updated by Dave Pickles almost 6 years ago
- File tvh6a.log.gz tvh6a.log.gz added
- File tvh4a.log tvh4a.log added
File tvh6a.log shows a trace for a recording which started at the scheduled time instead of the r/s triggered time. There was another recording running on the DVB-T tuner so this one was on DVB-S. From my dvbrs utility the r/s change happened at 11:40:03.575.
A more serious failure is shown in tvh4a.log. The event scheduled at 21:00 is not recorded. Interestingly, all of the "dvr event running check" traces are for services on the DVB-T mux - maybe TVH isn't monitoring DVB-S? Unfortunately I didn't get a tbl-eit trace for this one.
My system is set to use these EPG grabbers: "EIT-DVB Grabber", "UK: Freesat", "UK: Freesat (EIT)" and "UK: Freeview", all at their default priorities.
Updated by Jaroslav Kysela almost 6 years ago
This is an example if tvh sees the running event:
2019-01-17 11:40:03.407 [ TRACE]:tbl-eit: svc='CBBC HD', ch='CBBC HD', eid= 1672, tbl=4e, running=4, start=2019-01-17;11:40:00(+0000), stop=2019-01-17;12:10:00(+0000), ebc=0x1238df0
The code 4 (running=4) means that the event is being broadcasted. 3=pause, 2=warm, 1=stop. And it really looks like that there are not correctly parsed or handled the DVB-S EITp/f events. Could you just do EIT log when only one DVB-S channel is being watched or recorded and EPG changes (small shows would be perfect to verify EITp/f parsing).
Updated by Dave Pickles almost 6 years ago
Here is the log from watching 'CBeebies' via DVB-S as r/s changes.
Updated by Jaroslav Kysela almost 6 years ago
I think that I can explain that - I assume that your 'CBeebies HD' channel has two services - DVB-T + DVB-S, right?
See:
2019-01-17 17:25:03.756 [ TRACE]:tbl-eit: svc='CBeebies HD', ch='CBeebies SAT', eid= 2621, tbl=4e, running=4, start=2019-01-17;17:25:00(+0000), stop=2019-01-17;17:35:00(+0000), ebc=0x6faa0c20 2019-01-17 17:25:03.756 [ TRACE]:tbl-eit: svc='CBeebies HD', ch='CBeebies HD', eid= 2621, tbl=4e, running=4, start=2019-01-17;17:25:00(+0000), stop=2019-01-17;17:35:00(+0000), ebc=(nil) 2019-01-17 17:25:03.756 [ TRACE]:tbl-eit: CBeebies HD: running state only ebc=(nil)
The channel 'CBeebies SAT' has probably only DVB-S service and the EPG event is found for it (ebc=0x6faa0c20).
The channel 'CBeebies HD' has probably EPG database from DVB-T, thus the DVB EPG Event ID (16-bit number) is different and TVH drops the EITp/f update.
This patch will print the EIDs for the check:
diff --git a/src/epg.c b/src/epg.c index 093cc1a63..483b5b70c 100644 --- a/src/epg.c +++ b/src/epg.c @@ -717,6 +717,7 @@ static int epg_match_event_fuzzy(epg_broadcast_t *a, epg_broadcast_t *b) return 0; /* Matching ID */ + tvhtrace(LS_TBL_EIT, "match_event_fuzzy: eid(a) = %d, eid(b) = %d", a->dvb_eid, b->dvb_eid); if (a->dvb_eid) { if (b->dvb_eid && a->dvb_eid == b->dvb_eid)
For a further test, you may also comment the if section bellow the added trace (deactivate the EID check).
Updated by Dave Pickles almost 6 years ago
Yes, "CBeebies HD" uses both tuners (DVB-T by default). I created "CBeebies SAT" to force TVH to use the DVB-S tuner.
Actually EIDs are the same across DVB-T and DVB-S, at least for this channel, though the SIDs are different.
DVB-T:
09:23:54.952 sid 18112 eid 1709, 'So Awkward' rs 4
09:23:55.952 sid 18112 eid 1710, 'So Awkward' rs 1
DVB-S:
09:24:27.716 sid 6972 eid 1709, 'So Awkward' rs 4
09:24:27.788 sid 6972 eid 1710, 'So Awkward' rs 1
However for channel "QUEST HD" the EIDs are different:
09:55:44:341 sid 45152 eid 38435, 'Chasing Classic Cars' rs 1
09:55:45:341 sid 45152 eid 37788, 'Salvage Hunters' rs 4
09:55:54:251 sid 52580 eid 522, 'Salvage Hunters' rs 4
09:55:54:363 sid 52580 eid 523, 'Chasing Classic Cars' rs 1
I'll try your extra trace shortly.
Updated by Dave Pickles almost 6 years ago
Two more log files, with your extra trace included. The first is from the same setup as comment 5, watching CBeebies HD via DVB-S. As mentioned, the EIDs are the same on DVB-T and DVB-S for this channel so the fuzzy-match works.
The second log is from recording QUEST HD via DVB-S (with the DVB-T tuner busy showing another mux via Kodi). For this channel the EIDs do not match and the recording never starts.
I'm wondering where the problem lies here. Is what I'm seeing expected behaviour? Or is there a problem with my setup - maybe the EPG grabbers?
Updated by Jaroslav Kysela almost 6 years ago
It seems that both different EPG encoders are used for DVB-T/S so we cannot rely on EID accross the networks. For a simple test, you may comment out or just replace the condition to 'if (0 && a->dvb_eid) {' in the trace code patch in my comment 6. It seems that the fuzzy match might be more configurable.
Updated by Dave Pickles almost 6 years ago
I've been using this patch for the last 2 days with no problems so far:
--- src/epg.c 2019-01-20 09:09:27.183110189 +0000 +++ src/epg.c 2019-01-20 10:26:13.551345393 +0000 @@ -720,7 +720,6 @@ if (a->dvb_eid) { if (b->dvb_eid && a->dvb_eid == b->dvb_eid) return 1; - return 0; } /* Wrong length (+/-20%) */ @@ -746,8 +745,10 @@ /* episode check */ epg_broadcast_get_epnum(a, &num1); epg_broadcast_get_epnum(b, &num2); - if (epg_episode_number_cmp(&num1, &num2) == 0) + if (epg_episode_number_cmp(&num1, &num2) == 0) { + tvhtrace(LS_TBL_EIT, "match_event_fuzzy: eid(a) = %d, eid(b) = %d - success!", a->dvb_eid, b->dvb_eid); return 1; + } return 0; }
I'm not sure this would work in all cases though. Suppose a channel was showing all the episodes in a series one after another, and with no episode numbers in the EPG. Could TVH mistake the 'now' event for 'next'?
I've also checked the EIDs on the UK DVB-T and DVB-S networks. The BBC channels and 'Channel 4' use the same EIDs for both, but all of the other channels I've checked are different.
I wonder if the title of this Issue should be changed now that the reason is understood? Perhaps "Accurate Recording fails if EPG is from a different network".
Updated by Jaroslav Kysela almost 6 years ago
- Subject changed from EIT-based recording fails if two events have the same start time to EITp/f fails if EPG is from a different network
Updated by Dave Pickles over 4 years ago
I believe I'm finally close to solving this issue. However most of the fault lies with the UK DVB/T (Freeview) and DVB/S (Freesat) networks.
The networks have a few quirks:
- Most channels use different Event IDs for programmes on the two networks (BBC and Channel4 are exceptions).
- On DVB/S Freesat, most channels use different Event IDs for the main Freesat EIT and for the 'now & next' EITp/f table (0x4e)
- A few events in the EIT of both networks (~1%) have a trailing space after the title. On Freeview the trailing space also appears in the p/f table, on Freesat it does not.
The patch below seems to deal with the quirks, hopefully without changing the behaviour for more standards-compliant networks. However I'm still occasionally missing recordings.
The final check in epg_match_event_fuzzy() is to deal with the case where a channel is showing episodes of a series one after another. If episode number information is not available the 'now' episode could be identified as 'next' or vice versa. The fix does mean that if the episode start time in p/f is delayed past the original stop time the recording will be missed, but this must be a fairly unusual event. Also config.epg_update_window is now redundant.
--- epg.c.orig 2020-01-16 14:47:00.091490628 +0000 +++ epg.c 2020-01-17 15:42:26.738083763 +0000 @@ -712,16 +712,14 @@ time_t t1, t2; const char *title1, *title2; epg_episode_num_t num1, num2; + int title1_len, title2_len; if (a == NULL || b == NULL) return 0; /* Matching ID */ - if (a->dvb_eid) { - if (b->dvb_eid && a->dvb_eid == b->dvb_eid) - return 1; - return 0; - } + if (a->dvb_eid && b->dvb_eid && a->dvb_eid == b->dvb_eid) + return 1; /* Wrong length (+/-20%) */ t1 = a->stop - a->start; @@ -730,36 +728,40 @@ return 0; /* No title */ - if (!(title1 = epg_broadcast_get_title(a, NULL))) - return 0; - if (!(title2 = epg_broadcast_get_title(b, NULL))) - return 0; - - /* Outside of window */ - if ((int64_t)llabs(b->start - a->start) > config.epg_update_window) + if (!(title1 = epg_broadcast_get_title(a, NULL)) || !(title2 = epg_broadcast_get_title(b, NULL))) return 0; - /* Title match (or contains?) */ - if (strcasecmp(title1, title2)) + /* Title match (ignoring trailing chars) */ + title1_len = strlen(title1); + title2_len = strlen(title2); + if (strncmp(title1, title2, MIN(title1_len, title2_len))) return 0; /* episode check */ epg_broadcast_get_epnum(a, &num1); epg_broadcast_get_epnum(b, &num2); - if (epg_episode_number_cmp(&num1, &num2) == 0) - return 1; + if (epg_episode_number_cmp(&num1, &num2) != 0) + return 0; + + /* Outside of original event window */ + if (labs((long)(b->start - a->start)) >= MAX(t1,t2)) + return 0; - return 0; + return 1; } epg_broadcast_t *epg_match_now_next ( channel_t *ch, epg_broadcast_t *ebc ) { epg_broadcast_t *ret; - if (epg_match_event_fuzzy(ch->ch_epg_now, ebc)) + if (epg_match_event_fuzzy(ch->ch_epg_now, ebc)) { + tvhdebug(LS_DVR, "epg_match_now_next: NOW '%s' '%s' %d/%d",epg_broadcast_get_title(ebc,NULL),channel_get_name(ch, channel_blank_name),ch->ch_epg_now->dvb_eid,ebc->dvb_eid); ret = ch->ch_epg_now; - else if (epg_match_event_fuzzy(ch->ch_epg_next, ebc)) + } + else if (epg_match_event_fuzzy(ch->ch_epg_next, ebc)) { + tvhdebug(LS_DVR, "epg_match_now_next: NEXT '%s' '%s' %d/%d",epg_broadcast_get_title(ebc,NULL),channel_get_name(ch, channel_blank_name),ch->ch_epg_next->dvb_eid,ebc->dvb_eid); ret = ch->ch_epg_next; + } else return NULL; /* update eid for further lookups */