Bug #4085
[EPG] OTA EPG Grabber won't scan more than 1 satellite/network
Start date:
2016-11-17
Due date:
% Done:
0%
Estimated time:
Found in version:
4.1-2325
Affected Versions:
Description
Setup:¶
- TVHeadend 4.1-2325~g242bee1~xenial
- Single DVB-S tuner
- DiSEqC rotor configured for 4 satellites (Astra 19.2E, Astra 23.5E, Astra 28.2E and Hotbird 13.0E)
Issue description:¶
When triggering the OTA EPG grabber (timed or forced), the grabber only completes one satellite/network. The remaining networks aren't processed.
In the log I notice the epggrab TRACE mentions the subscribed networks differently after the first network is completed.
During first network grab
2016-11-17 17:34:52.464 [ TRACE]:epggrab: mux 12713V in Hotbird 13.0E (0x7f0130980130), started 2016-11-17 17:34:52.464 [ TRACE]:epggrab: subscription failed for 10714.25H in Astra 28.2E (result 200) 2016-11-17 17:34:52.464 [ TRACE]:epggrab: subscription failed for 10743.75H in Astra 19.2E (result 200) 2016-11-17 17:34:52.464 [ TRACE]:epggrab: subscription failed for 11797.5H in Astra 23.5E (result 200)
At the start of the second network grab
2016-11-17 17:36:04.724 [ TRACE]:epggrab: mux 10714.25H in Astra 28.2E (0x7f01140181b0), started 2016-11-17 17:36:04.724 [ TRACE]:epggrab: no free adapter for 10773H in Astra 28.2E (subscribe) 2016-11-17 17:36:04.724 [ TRACE]:epggrab: no free adapter for 10743.75H in Astra 19.2E (subscribe) 2016-11-17 17:36:04.724 [ TRACE]:epggrab: no free adapter for 11797.5H in Astra 23.5E (subscribe)
How to reproduce:¶
- Configure more than 1 DVB-S network
- Trigger the OTA EPG grabber
- Grabber will process all muxes of one network and then won't process the other networks
Log snippet¶
This log snippet shows the end of an EPG grab of one satellite (Hotbird 13.0E) and the attempt to start the second satellite (Astra 28.2E). The number of pending muxes suddenly drops to zero after the first mux of Astra 28.2E is handled. After that, the EPG grabber just stops. So rest of Astra 28.2E and the remaining satellites Astra 19.2E and Astra 23.5E are never handled.
2016-11-17 17:33:10.175 [ TRACE]:epggrab: data timeout check succeed 2016-11-17 17:33:40.175 [ DEBUG]:epggrab: grab done for 12635V in Hotbird 13.0E (timeout) 2016-11-17 17:33:40.175 [WARNING]:epggrab: EIT: DVB Grabber - data completion timeout for 12635V in Hotbird 13.0E 2016-11-17 17:33:40.175 [WARNING]:epggrab: UK: Freesat - data completion timeout for 12635V in Hotbird 13.0E 2016-11-17 17:33:40.175 [WARNING]:epggrab: VIASAT: Baltic - data completion timeout for 12635V in Hotbird 13.0E 2016-11-17 17:33:40.175 [WARNING]:epggrab: Bulsatcom: Bula 39E - data completion timeout for 12635V in Hotbird 13.0E 2016-11-17 17:33:40.175 [WARNING]:epggrab: PSIP: ATSC Grabber - data completion timeout for 12635V in Hotbird 13.0E 2016-11-17 17:33:40.175 [ INFO]:subscription: 056B: "epggrab" unsubscribing 2016-11-17 17:33:40.176 [ TRACE]:epggrab: mux 12635V in Hotbird 13.0E (0x7f013090e910) stop 2016-11-17 17:33:41.175 [ TRACE]:epggrab: ota - kick callback 2016-11-17 17:33:41.175 [ INFO]:mpegts: 12673.28V in Hotbird 13.0E - tuning on Conexant CX24116/CX24118 : DVB-S #0 2016-11-17 17:33:41.175 [ TRACE]:diseqc: initial tone off 2016-11-17 17:33:41.235 [ DEBUG]:diseqc: rotor already positioned to 13.0E 2016-11-17 17:33:41.236 [ TRACE]:diseqc: set diseqc tone on 2016-11-17 17:33:41.300 [ INFO]:subscription: 0570: "epggrab" subscribing to mux "12673.28V", weight: 4, adapter: "Conexant CX24116/CX24118 : DVB-S #0", network: "Hotbird 13.0E", service: "Raw PID Subscription" 2016-11-17 17:33:41.300 [ TRACE]:epggrab: mux 12673.28V in Hotbird 13.0E (0x7f0130976b00), started 2016-11-17 17:33:41.300 [ TRACE]:epggrab: subscription failed for 12713V in Hotbird 13.0E (result 200) 2016-11-17 17:33:41.300 [ TRACE]:epggrab: subscription failed for 10714.25H in Astra 28.2E (result 200) 2016-11-17 17:33:41.300 [ TRACE]:epggrab: subscription failed for 10743.75H in Astra 19.2E (result 200) 2016-11-17 17:33:41.301 [ TRACE]:epggrab: subscription failed for 11797.5H in Astra 23.5E (result 200) 2016-11-17 17:33:41.301 [ TRACE]:epggrab: mux stats - all 475 pending 202 2016-11-17 17:33:42.480 [ NOTICE]:mpegts: mux 11765V in Hotbird 13.0E old params DVB-S freq 11765000 V sym 27500000 fec 2/3 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:33:42.480 [ NOTICE]:mpegts: mux 11765V in Hotbird 13.0E new params DVB-S 13.0E freq 11765000 V sym 27500000 fec 2/3 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:33:42.480 [ NOTICE]:mpegts: mux 11804V in Hotbird 13.0E old params DVB-S freq 11804000 V sym 27500000 fec 2/3 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) ######################################## LOTS OF mpegts NOTICES ###################################################################################### 2016-11-17 17:33:46.699 [ NOTICE]:mpegts: mux 11880V in Hotbird 13.0E old params DVB-S freq 11880000 V sym 27500000 fec 3/4 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:33:46.699 [ NOTICE]:mpegts: mux 11880V in Hotbird 13.0E new params DVB-S 13.0E freq 11880000 V sym 27500000 fec 3/4 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:34:21.253 [ TRACE]:epggrab: data timeout check succeed 2016-11-17 17:34:51.253 [ DEBUG]:epggrab: grab done for 12673.28V in Hotbird 13.0E (timeout) 2016-11-17 17:34:51.253 [WARNING]:epggrab: EIT: DVB Grabber - data completion timeout for 12673.28V in Hotbird 13.0E 2016-11-17 17:34:51.253 [WARNING]:epggrab: UK: Freesat - data completion timeout for 12673.28V in Hotbird 13.0E 2016-11-17 17:34:51.253 [WARNING]:epggrab: VIASAT: Baltic - data completion timeout for 12673.28V in Hotbird 13.0E 2016-11-17 17:34:51.253 [WARNING]:epggrab: Bulsatcom: Bula 39E - data completion timeout for 12673.28V in Hotbird 13.0E 2016-11-17 17:34:51.253 [WARNING]:epggrab: PSIP: ATSC Grabber - data completion timeout for 12673.28V in Hotbird 13.0E 2016-11-17 17:34:51.253 [ INFO]:subscription: 0570: "epggrab" unsubscribing 2016-11-17 17:34:51.256 [ TRACE]:epggrab: mux 12673.28V in Hotbird 13.0E (0x7f0130976b00) stop 2016-11-17 17:34:52.253 [ TRACE]:epggrab: ota - kick callback 2016-11-17 17:34:52.253 [ INFO]:mpegts: 12713V in Hotbird 13.0E - tuning on Conexant CX24116/CX24118 : DVB-S #0 2016-11-17 17:34:52.255 [ TRACE]:diseqc: initial tone off 2016-11-17 17:34:52.399 [ DEBUG]:diseqc: rotor already positioned to 13.0E 2016-11-17 17:34:52.399 [ TRACE]:diseqc: set diseqc tone on 2016-11-17 17:34:52.463 [ INFO]:subscription: 0575: "epggrab" subscribing to mux "12713V", weight: 4, adapter: "Conexant CX24116/CX24118 : DVB-S #0", network: "Hotbird 13.0E", service: "Raw PID Subscription" 2016-11-17 17:34:52.464 [ TRACE]:epggrab: mux 12713V in Hotbird 13.0E (0x7f0130980130), started 2016-11-17 17:34:52.464 [ TRACE]:epggrab: subscription failed for 10714.25H in Astra 28.2E (result 200) 2016-11-17 17:34:52.464 [ TRACE]:epggrab: subscription failed for 10743.75H in Astra 19.2E (result 200) 2016-11-17 17:34:52.464 [ TRACE]:epggrab: subscription failed for 11797.5H in Astra 23.5E (result 200) 2016-11-17 17:34:52.464 [ TRACE]:epggrab: mux stats - all 475 pending 201 2016-11-17 17:34:53.558 [ TRACE]:epggrab: ota 12713V in Hotbird 13.0E add new service Hotbird 13.0E/12713V/TG24Elezioni 2016-11-17 17:34:53.885 [ NOTICE]:mpegts: mux 11727V in Hotbird 13.0E old params DVB-S freq 11727000 V sym 27500000 fec 3/4 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:34:53.885 [ NOTICE]:mpegts: mux 11727V in Hotbird 13.0E new params DVB-S 13.0E freq 11727000 V sym 27500000 fec 3/4 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:34:53.885 [ NOTICE]:mpegts: mux 11565H in Hotbird 13.0E old params DVB-S freq 11565000 H sym 27500000 fec 3/4 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) ######################################## LOTS OF mpegts NOTICES ###################################################################################### 2016-11-17 17:34:58.081 [ NOTICE]:mpegts: mux 10971H in Hotbird 13.0E old params DVB-S freq 10971000 H sym 27500000 fec 3/4 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:34:58.081 [ NOTICE]:mpegts: mux 10971H in Hotbird 13.0E new params DVB-S 13.0E freq 10971000 H sym 27500000 fec 3/4 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:35:32.430 [ TRACE]:epggrab: data timeout check succeed 2016-11-17 17:36:02.430 [ DEBUG]:epggrab: grab done for 12713V in Hotbird 13.0E (timeout) 2016-11-17 17:36:02.430 [WARNING]:epggrab: EIT: DVB Grabber - data completion timeout for 12713V in Hotbird 13.0E 2016-11-17 17:36:02.430 [WARNING]:epggrab: UK: Freesat - data completion timeout for 12713V in Hotbird 13.0E 2016-11-17 17:36:02.430 [WARNING]:epggrab: VIASAT: Baltic - data completion timeout for 12713V in Hotbird 13.0E 2016-11-17 17:36:02.430 [WARNING]:epggrab: Bulsatcom: Bula 39E - data completion timeout for 12713V in Hotbird 13.0E 2016-11-17 17:36:02.431 [WARNING]:epggrab: PSIP: ATSC Grabber - data completion timeout for 12713V in Hotbird 13.0E 2016-11-17 17:36:02.431 [ INFO]:subscription: 0575: "epggrab" unsubscribing 2016-11-17 17:36:02.431 [ TRACE]:epggrab: mux 12713V in Hotbird 13.0E (0x7f0130980130) stop 2016-11-17 17:36:03.430 [ TRACE]:epggrab: ota - kick callback 2016-11-17 17:36:03.430 [ INFO]:mpegts: 10714.25H in Astra 28.2E - tuning on Conexant CX24116/CX24118 : DVB-S #0 2016-11-17 17:36:03.431 [ TRACE]:diseqc: set voltage 18V 2016-11-17 17:36:04.316 [ TRACE]:diseqc: initial tone off 2016-11-17 17:36:04.359 [ TRACE]:diseqc: initial sleep 100ms 2016-11-17 17:36:04.444 [ TRACE]:diseqc: sending diseqc (len 4) E0 31 6B 04 2016-11-17 17:36:04.724 [ DEBUG]:diseqc: rotor GOTOX pos 4 sent 2016-11-17 17:36:04.724 [ TRACE]:diseqc: waiting 8 seconds to finish setup for GOTOX 2016-11-17 17:36:04.724 [ INFO]:subscription: 0579: "epggrab" subscribing to mux "10714.25H", weight: 4, adapter: "Conexant CX24116/CX24118 : DVB-S #0", network: "Astra 28.2E", service: "Raw PID Subscription" 2016-11-17 17:36:04.724 [ TRACE]:epggrab: mux 10714.25H in Astra 28.2E (0x7f01140181b0), started 2016-11-17 17:36:04.724 [ TRACE]:epggrab: no free adapter for 10773H in Astra 28.2E (subscribe) 2016-11-17 17:36:04.724 [ TRACE]:epggrab: no free adapter for 10743.75H in Astra 19.2E (subscribe) 2016-11-17 17:36:04.724 [ TRACE]:epggrab: no free adapter for 11797.5H in Astra 23.5E (subscribe) 2016-11-17 17:36:04.725 [ TRACE]:epggrab: mux stats - all 475 pending 0 2016-11-17 17:36:12.702 [ TRACE]:diseqc: initial tone off 2016-11-17 17:36:22.733 [ NOTICE]:mpegts: mux 11464.25H in Astra 28.2E old params DVB-S freq 11464250 H sym 22000000 fec 5/6 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:36:22.733 [ NOTICE]:mpegts: mux 11464.25H in Astra 28.2E new params DVB-S 28.2E freq 11464250 H sym 22000000 fec 5/6 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:36:22.733 [ NOTICE]:mpegts: mux 11954H in Astra 28.2E old params DVB-S freq 11954000 H sym 27500000 fec 2/3 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) ######################################## LOTS OF mpegts NOTICES ###################################################################################### 2016-11-17 17:36:30.749 [ NOTICE]:mpegts: mux 11508.5V in Astra 28.2E old params DVB-S freq 11508500 V sym 22000000 fec 5/6 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:36:30.749 [ NOTICE]:mpegts: mux 11508.5V in Astra 28.2E new params DVB-S 28.2E freq 11508500 V sym 22000000 fec 5/6 mod QPSK roff 35 is_id -1 pls_mode ROOT pls_code 1 (00000001) 2016-11-17 17:36:52.702 [ TRACE]:epggrab: data timeout check succeed 2016-11-17 17:37:22.702 [ DEBUG]:epggrab: grab done for 10714.25H in Astra 28.2E (timeout) 2016-11-17 17:37:22.702 [WARNING]:epggrab: EIT: DVB Grabber - data completion timeout for 10714.25H in Astra 28.2E 2016-11-17 17:37:22.702 [WARNING]:epggrab: UK: Freesat - data completion timeout for 10714.25H in Astra 28.2E 2016-11-17 17:37:22.702 [WARNING]:epggrab: VIASAT: Baltic - data completion timeout for 10714.25H in Astra 28.2E 2016-11-17 17:37:22.702 [WARNING]:epggrab: Bulsatcom: Bula 39E - data completion timeout for 10714.25H in Astra 28.2E 2016-11-17 17:37:22.702 [WARNING]:epggrab: PSIP: ATSC Grabber - data completion timeout for 10714.25H in Astra 28.2E 2016-11-17 17:37:22.702 [ INFO]:subscription: 0579: "epggrab" unsubscribing 2016-11-17 17:37:22.705 [ TRACE]:epggrab: mux 10714.25H in Astra 28.2E (0x7f01140181b0) stop
Files
History
Updated by Jaroslav Kysela almost 8 years ago
Updated by Could you provide similar log, but enable also '--trace mpegts,service,subscription' ?
The lines between 'epggrab: ota - kick callback' and 'epggrab: mux stats - all # pending #' are important to check what's wrong.
Updated by ZZD M almost 8 years ago
Updated by - File endofscan_extra_traces.log endofscan_extra_traces.log added
- File full_extra_traces.log full_extra_traces.log added
Sorry I wasn't able to provide the info sooner, I didn't have access to my TVH server over the weekend. You can find the logs in attachment here. One is the complete grabbing of Hotbird 13.0E and the start of the next satellite. The other is just the last part, transitioning from one satellite to the other (pending muxes from xxx -> 0).
Updated by ZZD M almost 8 years ago
Any progress so far on this? Or should I test it again with a more recent build?
Updated by ZZD M almost 8 years ago
I've updated my setup to v4.1-2355~g1dd2652 today as yesterday the repo seemed to be down or unreachable. Unfortunately I don't have any test results yet due to a lack of time. Tomorrow I'll boot it up and let it run during the day, collecting the relevant logs.
Updated by ZZD M almost 8 years ago
- File epg_scan_ok.log epg_scan_ok.log added
So today I booted up my server before leaving for work, with v4.1-2355~g1dd2652 installed and scheduled to start an epggrab at around 11h30. And when I came back I noticed that all satellites were indeed checked for EPG data (did take a long time though, till +-16h30)! So this issue seems to be fixed. I've attached the log as a reference.
Updated by Jaroslav Kysela almost 8 years ago
- Status changed from New to Fixed
Nice. Marking as fixed.