Weird EPG errors. EPG Refresh. Recent versions of OpenViX e.g. 5.4.008.

[LraiZer]

To save me searching can anyone point me to the location of the code that limits the size and number of debug logs?

Use PuTTY and save log on your PC!

Telnet to box with PuTTY

stop enigma2

init 4

start enigma2 with debug level 4 logging

ENIGMA_DEBUG_LVL=4 enigma2

end debug logging

CTRL+C

start enigma2 in normal mode again

init 3

[LraiZer]

I saw lots of doubles this morning on tomorrow's (Friday 12th) EPG slots just before midday, containing entries from Wednesday 10 just before midnight. All have the same 36 hour 24 minute (2184 minutes) offset from the original broadcast time. I know I keep banging on about this value being 0x888 or binary 100010001000 which I think is being caused by a bug in the Julian date handling for events starting before midnight and straddling the midnight hour, but I think the answer lies there.

I think all agree that this should be the first place for Brian to look to debug and fix this issue

[bbbuk]

...TODO: fix source type issue, update epg.dat from V7 to V8.

I think you may also be seeing an issue in epgcache code that prevents many of the epg readers inc. OpenTV from updating/removing previously cached events, which would result in you seeing overlapping events from events that were not removed/updated as no longer needed. Fixing this issue would also require updating the epg.dat save/load functions and the file structure of the epg.dat file so the epg Version would also need incrementing from V7 to V8. We need to adjust the eventData type(0xFF) size of the epg source from uint8_t to eventData type(0xFFFF) uint16_t. OpenTV source type(0x4000) and other many of the other readers with a greater source type ID than 255 are currently wrongly being set/saved/loaded as PRIVATE(0X00) source type. Some of the epgcache code checks for PRIVATE or 0 source type and these checks are blocking the wrongly set OpenTV source type (0x00) from ever updating or removing events, it is only allowing new events to be added.

When i next get some free time, i can make patch to fix this issue to test.

Would this explain why these phantom entries arent noticable (that I have observed) when using CrossEPG as i've noticed its code does something with epgcache (creates new instance I think)?

[Joe_90]

Would this explain why these phantom entries arent noticable (that I have observed) when using CrossEPG as i've noticed its code does something with epgcache (creates new instance I think)?

As far as I am aware, CrossEPG reads the Sky EPG transponder data and stores it in its own database and then populates the EPG cache afterwards. I don't know whether it shares or uses the same code used by the OpenTV reader that EPGRefresh or OpenTVzapper calls. So, it may not encounter the same corruption issue.

[LraiZer]

If you install RadiotimesXmltvEmulator from the feed, as it is based on CrossEPG, you should also see these bogus events in the xmltv file that it generated in /tmp

[Huevos]

I never noticed before... No event_id in that format.

 <programme start="20210316110000 +0100" stop="20210316120000 +0100" channel="282_2_6155">
  <title lang="en">Lorraine</title>
  <sub-title lang="en">Entertainment - Magazine</sub-title>
  <desc lang="en">Lorraine Kelly presents a topical mix of entertainment, discussion and showbiz glamour as well as the latest fashion, food and celebrity gossip.</desc>
 </programme>

[Joe_90]

Any sign of the ghost events in that format?

[ccs]

"tvheadend" has some interesting (and very old) comments about event_id's. eg...

https://github.com/tvheadend/tvheadend/commit/be1a42d9092550ffa892e39ef91026e1405192d2

Try to detect duplicate EPG entries from the DVB feed and adjust
EPG accordingly. The EPG code will search for events with the same
DVB event ID +- 2 events from the current one. If the event id is
equal, the prvious (old) entry will be removed in favor of the new one.
Reason for not blindingly trusting the event id is that some networks
seem to (incorrectly) reuse IDs.

[BrokenUnusableAccount]

Sorry - I couldn't work on this last night - I had to get up early this morning for something.
Tonight however I have:

This is the section of opentv.cpp I changed to log stuff, the lines I have added/changed are marked with //BB

OpenTvTitle::OpenTvTitle(const uint8_t * const buffer, uint16_t startMjd)
{
	uint8_t descriptor_tag = buffer[0];

	if (descriptor_tag == OPENTV_EVENT_TITLE_DESCRIPTOR)
	{
		uint8_t descriptor_length = buffer[1];
		uint8_t titleLength = descriptor_length > 7 ? descriptor_length-7 : 0;

		uint32_t startSecond = (UINT16(&buffer[2]) << 1); //BB

		startTimeBcd = ((startMjd - 40587) * 86400) + startSecond; //BB
		duration = UINT16(&buffer[4]) << 1;

		//genre content
		//uint8_t flag1 = buffer[6];
		//uint8_t flag2 = buffer[7];
		//uint8_t flag3 = buffer[8];

		char tmp[OPENTV_EVENT_TITLE_LENGTH];
		memset(tmp, '\0', OPENTV_EVENT_TITLE_LENGTH);

		if (!huffman_decode (buffer + 9, titleLength, tmp, OPENTV_EVENT_TITLE_LENGTH * 2, false))
			tmp[0] = '\0';

		title = convertDVBUTF8(tmp, sizeof(tmp), 5);

		eDebug("[OpenTV] +titl:\"%s\" SMJD:%i Ss:%i SBD:%i len:%i", tmp, startMjd, startSecond, startTimeBcd, duration); //BB

		/* storing all the crc unique titles in the title reader phase,
		   would give us a titles reduction of 155,000 down to 13,000!
		   we currently add/delete as we go with reduction size ~5000 */
		uint8_t *otvt = new uint8_t[titleLength];
		memcpy(otvt, buffer + 9, titleLength);
		crc32 = opentv_crc(otvt, titleLength);
		delete [] otvt;
	}
}

Just after midnight I see the "ghost events" showing with startMjd corresponding to today (the day that started just some minutes ago) and startSecond corresponding to start times of over 24:00.
The start times seem to be the old original start time plus 2^17 seconds which is 131072 (or 0x20000) seconds which is 2184 (or 0x888) minutes and 32 seconds.

but thinking hard.

https://www.brian-gregory.me.uk/GDL/Putty%20zgemmah7.lan%2020210312-124826.log
https://www.brian-gregory.me.uk/GDL/Putty%20zgemmah7.lan%2020210312-233623.log
https://www.brian-gregory.me.uk/GDL/Putty%20zgemmah7.lan%2020210313-000145.log

[birdman]

Just after midnight I see the "ghost events" showing with startMjd corresponding to today (the day that started just some minutes ago) and startSecond corresponding to start times of over 24:00.
The start times seem to be the old original start time plus 2^17 seconds which is 131072 (or 0x20000) seconds which is 2184 (or 0x888) minutes and 32 seconds.

but thinking hard.

Given that there are only 86400 seconds in a day (0x15180) that looks as though 0x20000 is a flag (meaning unknown) that needs to be masked off.
Or it's a bit that's been shifted down that shouldn't be there....(signed vs unsigned right-shift)?

[BrokenUnusableAccount]

Given that there are only 86400 seconds in a day (0x15180) that looks as though 0x20000 is a flag (meaning unknown) that needs to be masked off.
Or it's a bit that's been shifted down that shouldn't be there....(signed vs unsigned right-shift)?

I think it is as if it's a signed number but where as a normal x bit signed number when incremented the meaning goes from +(2^x)-1 to -(2^x) here the meaning changes from +ve to -ve at a different point, probably when it's over 86400 seconds.
The 0x20000 error is because the program currently just always interprets it as a positive unsigned value.

[birdman]

...and startSecond corresponding to start times of over 24:00.
The start times seem to be the old original start time plus 2^17 seconds which is 131072 (or 0x20000) seconds which is 2184 (or 0x888) minutes and 32 seconds.

Wait!! That should not happen!!!

The max value for UINT16 is 0xffff. Shifted left by 1 that becomes 0x1fffe. There is no way that the 0x20000 bit should ever be set.

Is there a bug in the UINT16 definition???

[BrokenUnusableAccount]

Wait!! That should not happen!!!

The max value for UINT16 is 0xffff. Shifted left by 1 that becomes 0x1fffe. There is no way that the 0x20000 bit should ever be set.

Is there a bug in the UINT16 definition???

I think I must have explained it badly. Did my second message make it clearer?

They are in a funny format.
Say something yesterday really started at 23:50 on 12th March.
I think they're trying to send it as 13th March starting at minus 00:10 but the software doesn't currently realise sky think negative start times are a thing.

Or maybe something earlier in the software is messing it up, but I don't think that's likely.

[birdman]

I think I must have explained it badly. Did my second message make it clearer?

No.
The relevant thing is that (assuming UINT16 returns a 16-bit unsigned int)

 (UINT16(&buffer[2]) << 1);

should never be able to set the 0x20000 bit. Regardless of who intends what.

The problem is that I cannot find a definition of UINT16 anywhere.

EDIT: Found it. It's in the dvbsi++ bytestream.h header file.

// deprecated 
#define UINT16(p)       r16(p)

#if __BYTE_ORDER == __BIG_ENDIAN 
#define r16(p)          (*(const uint16_t * const)(p))
...
#else 
#define r16(p)          bswap_16(*(const uint16_t * const)p)

[BrokenUnusableAccount]

No.
The relevant thing is that (assuming UINT16 returns a 16-bit unsigned int)

 (UINT16(&buffer[2]) << 1);

should never be able to set the 0x20000 bit. Regardless of who intends what.

It isn't.

It's like the error if a signed byte -17 is interpreted as unsigned giving incorrect value 249.
That's an error due to interpreting it wrongly of 256 or 0x100, even though the byte has no 0x100 bit in it.