missing epg data - opentv

[satteliter]

i have a duo 4k se with unicable(8 tuners) and aerial(2 tuners). latest openvix 6.3.002.
The box is a few days old. I had been having issues with epg not loading information on startup from the hard drive so I switched the epg to use a usb (hoping the flash drive would rule out any issues with hard drive spin up time etc.)

However, I'm still seeing the same situation with the usb. I have confirmed the epg.dat is only being written to usb and not hdd.

This time, the aerial channels in the epg are showing 7 day guide but all the satellite channels are not showing any epg data.
This has been a reoccuring problem for the last few days.

It does not seem to matter if the box is coming out of standby or deep standby.
I had debug logs enabled which I've attached.

The later debug logs have the local time in the logs as well.


Is there any way to better troubleshoot this? Would switching to CrossEPG or some other plugin solve this?

Enigma2_debug_2023-02-25_13-22-16.logEnigma2_debug_2023-02-25_14-13-56.logepg settings.jpgepg terrestrial showing 7 days out.jpgepg terrestrial showing today.jpgopentv download setup.jpg


epg.dat is ~8mb and i can see some satellite channel epg info in there.

[satteliter]

here are logs from after a reboot when the epg data was still missing from satellite channelsEnigma2_debug_2023-02-25_16-40-32.log

[satteliter]

doing a 'force opentv download' populates the epg.

after monitoring the tuners in use(thus knowing when opentv finishes), i can see that the epg when epg is fully populated is 2364kb(roughly quarter of size of epg.dat when it was not populating on screen(8157kb))

this is headwrecking!

[abu baniaz]

During acquisition, the epg is held in RAM. It is only saved on graceful shutdown/restart. Acquiring and checking i snot a good test. You have to acquire and then restart.

EDIT:
There is nothing in your log to show why EPG is being dropped.

[satteliter]

there are now some later logs all of which say

Continued from /home/root/logs/Enigma2_debug_2023-02-25_17-45-07.log
< 438.7103> 17:45:54.2754 [huffman] Error. Cannot decode Huffman data
< 438.7103> 17:45:54.2754 [huffman] Error. Cannot decode Huffman data
< 438.7104> 17:45:54.2755 [convertDVBUTF8] reserved 0
< 438.7106> 17:45:54.2756 [convertDVBUTF8] reserved 0
< 438.7107> 17:45:54.2757 [convertDVBUTF8] reserved 0
< 438.7108> 17:45:54.2758 [convertDVBUTF8] reserved 0
< 438.7109> 17:45:54.2759 [convertDVBUTF8] reserved 0
< 438.7110> 17:45:54.2761 [convertDVBUTF8] reserved 0
< 438.7128> 17:45:54.2778 [huffman] Error. Cannot decode Huffman data
< 438.7128> 17:45:54.2778 [huffman] Error. Cannot decode Huffman data
< 438.7128> 17:45:54.2779 [huffman] Error. Cannot decode Huffman data
< 438.7129> 17:45:54.2779 [huffman] Error. Cannot decode Huffman data
< 438.7129> 17:45:54.2779 [huffman] Error. Cannot decode Huffman data
< 438.7129> 17:45:54.2780 [huffman] Error. Cannot decode Huffman data
< 438.7130> 17:45:54.2780 [huffman] Error. Cannot decode Huffman data

after turning box on from standby and checking epg, the sat epg data is missing again and the epg.dat size has gone up to 7995kb.


logs attached(zipped as filesize of 10mb too big)after force download and reboot.zip

[satteliter]

the entries preceeding the huffman errors(take from Enigma2_debug_2023-02-25_17-38-56.log):

< 330.4837> 17:44:06.0487 [eDVBSectionReader] DMX_SET_FILTER pid=1903
< 330.5509> 17:44:06.1159 [eDVBFrontend2] setVoltage 1
< 330.5509> 17:44:06.1159 [eDVBFrontend0] setVoltage FE_ENABLE_HIGH_LNB_VOLTAGE 0 FE_SET_VOLTAGE 0
< 330.5601> 17:44:06.1252 [eDVBFrontend2] update current switch params
< 330.5602> 17:44:06.1253 [eDVBFrontend2] startTuneTimeout 5000
< 330.5603> 17:44:06.1253 [eDVBFrontend2] setFrontend 1
< 330.5603> 17:44:06.1253 [eDVBFrontend2] setting frontend
< 330.5728> 17:44:06.1378 [eDVBFrontend2] fe event: status 0, inversion off, m_tuning 1
< 330.5728> 17:44:06.1378 [eDVBFrontend2] sleep 500ms
< 330.5803> 17:44:06.1453 [eDVBDemux] open demux /dev/dvb/adapter0/demux1
< 330.5803> 17:44:06.1454 [eDVBSectionReader] DMX_SET_FILTER pid=1904
< 330.6414> 17:44:06.2065 [eDVBFrontend2] fe event: status 7, inversion off, m_tuning 2
< 330.6415> 17:44:06.2066 [eDVBFrontend0] fe event: status 1f, inversion off, m_tuning 2
< 330.6621> 17:44:06.2272 [eDVBDemux] open demux /dev/dvb/adapter0/demux1
< 330.6622> 17:44:06.2272 [eDVBSectionReader] DMX_SET_FILTER pid=1905
< 330.7264> 17:44:06.2915 [eDVBFrontend2] fe event: status 1f, inversion off, m_tuning 3
< 330.7265> 17:44:06.2915 [eDVBChannel] OURSTATE: ok
< 330.7265> 17:44:06.2915 [eDVBLocalTimerHandler] channel 0xfb6c70 running
< 330.7266> 17:44:06.2916 [eDVBChannel] getDemux cap=00
< 330.7266> 17:44:06.2916 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7267> 17:44:06.2917 [eDVBSectionReader] DMX_SET_FILTER pid=20
< 330.7283> 17:44:06.2933 [eEPGTransponderDataReader] channel 0xfb6c70 running
< 330.7283> 17:44:06.2934 [eDVBChannel] getDemux cap=00
< 330.7283> 17:44:06.2934 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7284> 17:44:06.2934 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7284> 17:44:06.2935 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7285> 17:44:06.2935 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7285> 17:44:06.2935 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7285> 17:44:06.2936 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7286> 17:44:06.2936 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7286> 17:44:06.2937 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7287> 17:44:06.2937 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7287> 17:44:06.2937 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7287> 17:44:06.2938 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7288> 17:44:06.2938 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7288> 17:44:06.2938 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7289> 17:44:06.2939 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7289> 17:44:06.2939 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7289> 17:44:06.2940 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7290> 17:44:06.2940 [eDVBResourceManager] stop release channel timer
< 330.7290> 17:44:06.2940 [eDVBChannel] getDemux cap=01
< 330.7290> 17:44:06.2941 [eEPGChannelData] next update in 2 sec
< 330.7290> 17:44:06.2941 [eDVBResourceManager] allocate demux cap=01
< 330.7291> 17:44:06.2941 [eDVBResourceManager] allocating shared demux adapter=0, demux=2, source=2
< 330.7291> 17:44:06.2941 [eDVBServicePMTHandler] ok ... now we start!!
< 330.7291> 17:44:06.2941 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7291> 17:44:06.2942 [eDVBSectionReader] DMX_SET_FILTER pid=0
< 330.7297> 17:44:06.2948 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7298> 17:44:06.2948 [eDVBSectionReader] DMX_SET_FILTER pid=18
< 330.7302> 17:44:06.2952 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.7303> 17:44:06.2953 [eDVBSectionReader] DMX_SET_FILTER pid=0
< 330.7602> 17:44:06.3252 [eDVBDemux] open demux /dev/dvb/adapter0/demux1
< 330.7602> 17:44:06.3253 [eDVBSectionReader] DMX_SET_FILTER pid=1906
< 330.7733> 17:44:06.3384 [eDVBDemux] open demux /dev/dvb/adapter0/demux1
< 330.7734> 17:44:06.3384 [eDVBSectionReader] DMX_SET_FILTER pid=1907
< 330.8113> 17:44:06.3763 [eDVBServicePMTHandler] PATready
< 330.8113> 17:44:06.3764 [eDVBServicePMTHandler] use pmtpid 0100 for service_id 18a4
< 330.8114> 17:44:06.3764 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.8114> 17:44:06.3764 [eDVBSectionReader] DMX_SET_FILTER pid=256
< 330.8117> 17:44:06.3767 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.8117> 17:44:06.3768 [eDVBSectionReader] DMX_SET_FILTER pid=0
< 330.8127> 17:44:06.3778 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.8128> 17:44:06.3778 [eDVBSectionReader] DMX_SET_FILTER pid=256
< 330.8134> 17:44:06.3785 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 330.8135> 17:44:06.3785 [eDVBSectionReader] DMX_SET_FILTER pid=17
< 330.8681> 17:44:06.4331 [eDVBDemux] open demux /dev/dvb/adapter0/demux1
< 330.8682> 17:44:06.4332 [eDVBSectionReader] DMX_SET_FILTER pid=1908
< 330.9088> 17:44:06.4739 [eDVBLocalTimerHandler] diff is 0
< 330.9088> 17:44:06.4739 [eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
< 330.9089> 17:44:06.4739 [eDVBLocalTimerHandler] not changed
< 330.9091> 17:44:06.4741 [eDVBChannel] getDemux cap=00
< 331.0055> 17:44:06.5706 [eDVBServicePMTHandler] sdt update done!
< 331.0523> 17:44:06.6173 [eDVBServicePMTHandler] sdt update done!
< 331.0729> 17:44:06.6380 [eDVBFrontend2] set dynamic current limiting
< 331.2807> 17:44:06.8457 [eDVBServiceFCCPlay] eventNewProgramInfo 0 0 0
< 331.2808> 17:44:06.8458 [eDVBServiceFCCPlay] updateFCCDecoder [1:0:19:18A4:7FD:2:11A0000:0:0:0:]
have 1 video stream(s) (1518), and 1 audio stream(s) (1519), and the pcr pid is 1518, and the text pid is 151b< 331.2812> 17:44:06.8463
< 331.2812> 17:44:06.8463 [eDVBChannel] getDemux cap=01
< 331.2813> 17:44:06.8463 [decoder][eDVBText] initCache
< 331.2814> 17:44:06.8464 [eFCCDecoder] Alloc /dev/fcc1
< 331.2819> 17:44:06.8469 [eTSMPEGDecoder] FCC_START OK!
< 331.2820> 17:44:06.8470 [eDVBCAService] new service 1:0:19:18A4:7FD:2:11A0000:0:0:0:
< 331.2820> 17:44:06.8470 [eDVBCAService] add demux 2 to slot 0 service 1:0:19:18A4:7FD:2:11A0000:0:0:0:
< 331.2822> 17:44:06.8472 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 331.2823> 17:44:06.8473 [eDVBSectionReader] DMX_SET_FILTER pid=256
< 331.7280> 17:44:07.2931 [eEPGChannelData] start reading events(1677347047)
< 331.7281> 17:44:07.2932 [eDVBSectionReader] DMX_SET_FILTER pid=18
< 331.7289> 17:44:07.2939 [eDVBSectionReader] DMX_SET_FILTER pid=18
< 331.7297> 17:44:07.2948 [eDVBSectionReader] DMX_SET_FILTER pid=18
< 331.7308> 17:44:07.2959 [huffman] read.. '/usr/share/enigma2/otv_011a0000_0002_07d4.dict'
< 331.7330> 17:44:07.2980 [huffman] read.. dictionary completed, read 512 values
< 331.7330> 17:44:07.2981 [eDVBSectionReader] DMX_SET_FILTER pid=17
< 332.0326> 17:44:07.5976 [eDVBDemux] open demux /dev/dvb/adapter0/demux2
< 332.0327> 17:44:07.5977 [eDVBSectionReader] DMX_SET_FILTER pid=18
< 332.7290> 17:44:08.2941 [eEPGChannelData] start reading events(1677347048)
< 332.7294> 17:44:08.2944 [eDVBSectionReader] DMX_SET_FILTER pid=18
< 332.7315> 17:44:08.2965 [eDVBSectionReader] DMX_SET_FILTER pid=18
< 332.7325> 17:44:08.2976 [eDVBSectionReader] DMX_SET_FILTER pid=18
< 332.7338> 17:44:08.2989 [huffman] read.. '/usr/share/enigma2/otv_011a0000_0002_07fd.dict'
< 332.7341> 17:44:08.2992 [eEPGChannelData] abort non avail OpenTV EIT reading
< 335.4826> 17:44:11.0477 [eDVBLocalTimerHandler] diff is -10
< 335.4827> 17:44:11.0477 [eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
< 335.5934> 17:44:11.1584 [eDVBLocalTimerHandler] update RTC
< 335.5934> 17:44:11.1585 [eDVBLocalTimerHandler] time update to 17:44:01
< 335.5935> 17:44:11.1585 [eDVBLocalTimerHandler] m_time_difference is -10
< 335.5935> 17:44:11.1585 [eDVBLocalTimerHandler] slewing Linux Time by -10 seconds
< 335.5938> 17:44:11.1588 [eDVBChannel] getDemux cap=00
< 339.7344> 17:44:15.2994 [eEPGChannelData] abort non avail schedule reading
< 339.7356> 17:44:15.3007 [eEPGChannelData] abort non avail schedule other reading
< 339.8138> 17:44:15.3788 [eEPGChannelData] nownext finished(1677347055)
< 339.8143> 17:44:15.3793 [eEPGChannelData] stop caching events(1677347055)
< 339.8143> 17:44:15.3793 [eEPGChannelData] next update in 60 min
< 341.7857> 17:44:17.3507 [eEPGChannelData] OpenTV channels, found=833
< 341.7860> 17:44:17.3510 [eDVBSectionReader] DMX_SET_FILTER pid=48
< 341.7928> 17:44:17.3578 [huffman] Error. Cannot decode Huffman data

this is then followed by thousands of entries of "[huffman] Error. Cannot decode Huffman data"

[Joe_90]

The OpenTV zapper will (should) automatically start 5 minutes after a boot. The EPG data is then populated in RAM and is only written back to epg.dat on a controlled shutdown. The log seems to show a successful run of OpenTV zapper, but unless the box is shut down gracefully, the epg.dat file won't be be written.

I too am getting occasional issues when running the zapper and I'm tuned to RTE1 on terrestrial (as in your example at 17:44:07). The logfile will contain thousands of huffman error messages and the logs will grow to 4MB and then start a new log. I'm not sure what is triggering the huffman error messages, though. Your and my usage cases (Saorview terrestrial and 28.2 sat) may be a factor.

[satteliter]

but unless the box is shut down gracefully.

So far, has always been standby or reboot through ui. no power cuts/button pushing or direct linux commands executed.
i have 2 gigablue trio 4k boxes, each of which has 1 sat/1 aerial and haven't seen any epg issues. all running latest openvix etc..

are you using a vu+ duo 4k se by any chance?

i'm guessing switching to some internet source/crossepg for epg would not have these issues but i'm unsure what issues they might introduce.

[Joe_90]

No - I'm using a GB Quad Plus with 2xDVB-T and 2xDVB-S tuners. I think this is happening for me if I tune another channel while the OpenTV zapper is running. I'll see if I can get log review by a developer.


EDIT - have attached an extract of a debug log from today. When the Huffman Error messages start, they fill five logfiles, each of over 4MB, in the space of about three minutes while the zapper is running. Once the zapper finishes (with only partial EPG), the messages stop.

[satteliter]

interesting. thanks for sharing.

out of curiosity, does you box/setup have FCC (fast channel change) or equivalent?

[Joe_90]

interesting. thanks for sharing.

out of curiosity, does you box/setup have FCC (fast channel change) or equivalent?

Nope - it's an old box (2014 ish).

[satteliter]

just to add some more things. since the last post on 25/02, I disabled the 2nd satellite root tuner and also disabled fast channel changing.
no issues with epg since then.

earlier today, I re-enabled FCC (but left the 2nd satellite root tuner disabled), epg issue re-appeared. Box had not been powered off(i.e. has been used or standby or deep standby every day since).

so, with FCC, if any of the terrestrial muxes were watched before watching satellite, the box had the tuner 'active' (due to FCC being enabled).

I think this ties in with your observed behaviour ("getting occasional issues when running the zapper and I'm tuned to RTE1 on terrestrial ")

i've since disabled FCC.

unfortunately, some logs were overwritten as max total log size was reached before i got a chance to copy them over to see the log entries preceding the huffman error.

on a related note, later today , i switched to a terrestrial channel (tried both muxes) and manually ran 'opentv epg forced download'. i was unable to recreate the huffman error issue.
the log entries when i ran it read:

< 12724.4137> 22:41:57.2126 [opentv_zapper]currentlyPlayingNIM 8
< 12724.4139> 22:41:57.2127 [opentv_zapper]available tuners [0, 2, 3, 4, 5, 6, 7]

(available tuner 1 being the disabled sat root tuner)

'currentlyPlayingNIM 8' when either terrestrial mux was being viewed.

have you any steps to manually invoke the issue?

[Joe_90]

I've reported it as a possible bug, but had no feedback since. I'll chase it up again.

[abu baniaz]

Have you tried zapping with EPG refresh instead of openTV EPG zapper? If so, are results the same?

[satteliter]

Just added plugin and set it up. Will monitor and report back if issue re-appears.