IceTV plugin - Failed update

[Grumpy_Geoff]

I thought I would check on my swapped-in T4 post its tuner regulator repair. I noticed this in the IceTV log, the first update attempt appeared to do nowt -

Ice_failedUpdate.png (69.98 KiB) Viewed 4675 times

I then checked the debug log and saw an error -

Code: Select all

{556}<   124.535> [VideoHardware] setting aspect: 16:9
{556}<   124.536> [VideoHardware] setting wss: auto
{556}<   124.537> [VideoHardware] setting policy: panscan
{556}<   124.540> [VideoHardware] setting policy2: letterbox
{556}<   124.667> [eDVBServicePMTHandler] AITready
{556}<   124.667> [eDVBServicePMTHandler] AIT: 7HbbTV
{556}<   124.667> [eDVBServicePMTHandler] AIT: Freeview
{814}<   127.876> Unhandled Error
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    
  File "/usr/lib/python2.7/threading.py", line 754, in run
    
  File "/usr/lib/python2.7/site-packages/twisted/_threads/_threadworker.py", line 46, in work
    
  File "/usr/lib/python2.7/site-packages/twisted/_threads/_team.py", line 190, in doWork
    
--- <exception caught here> ---
  File "/usr/lib/python2.7/site-packages/twisted/python/threadpool.py", line 246, in inContext
    
  File "/usr/lib/python2.7/site-packages/twisted/python/threadpool.py", line 262, in <lambda>
    
  File "/usr/lib/python2.7/site-packages/twisted/python/context.py", line 118, in callWithContext
    
  File "/usr/lib/python2.7/site-packages/twisted/python/context.py", line 81, in callWithContext
    
  File "/usr/lib/enigma2/python/Plugins/SystemPlugins/IceTV/plugin.py", line 349, in doWork
    
  File "/usr/lib/enigma2/python/Plugins/SystemPlugins/IceTV/plugin.py", line 423, in makeChanShowMap
    
exceptions.ImportError: Failed to import _strptime because the import lockis held by another thread.

{558}<   128.535> [gRC] main thread is non-idle! display spinner!
{556}<   128.770> [HBBTV] __application {'control': 1, 'profile': 0, 'name': '7HbbTV', 'url': 'http://swmhbbtv.freeviewplus.net.au/index.html', 'orgid': 324, 'appid': 16385}
{556}<   128.773> [HBBTV] __application {'control': 2, 'profile': 0, 'name': 'Freeview', 'url': 'http://hbbtv.freeviewplus.net.au/index.html', 'orgid': 321, 'appid': 16384}
{814}<   128.830> [IPKG] executing opkg  --add-dest /:/ update
{814}<   128.830> [eConsoleAppContainer] Starting /bin/sh
{556}<   128.836> [Task] job Components.Task.Job name=OnlineVersionCheck #tasks=1 completed with [] in None
{556}<   132.193> [eDVBServicePlay] [Timeshift] stopTimeshift
{556}<   132.209> [eDVBServicePlay] Start timeshift!
{556}<   132.231> [eDVBServicePlay] timeshift recording to /media/hdd/timeshift/timeshift.VeDZ8m
{831}<   132.233> [setIoPrio] realtime level 7 ok
{831}<   132.233> [eFilePushThreadRecorder] THREAD START
{556}<   132.241> [eEPGCache] saveEventToFile epg event id 7723
{556}<   132.243> [eDVBServicePlay] unpause
{556}<   135.045> [eDVBLocalTimerHandler] diff is -4
{556}<   135.045> [eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
{556}<   135.045> [eDVBLocalTimerHandler] set RTC Time
{556}<   135.045> [eDVBLocalTimerHandler] update RTC
{556}<   135.045> [eDVBLocalTimerHandler] time update to 06:17:18
{556}<   135.045> [eDVBLocalTimerHandler] m_time_difference is -4
{556}<   135.045> [eDVBLocalTimerHandler] set Linux Time
{556}<   135.046> [eDVBChannel] getDemux cap=00

Bad timing?

[prl]

I have seen that once, too. It looks like some sort of locking conflict between imports in different threads when there's a "lazy" import of the _strptime module from inside the time module. I'm not sure how often it happens: it looks like it's some sort of race condition.

It may be possible to avoid by putting something like strptime(strftime("%a %b %d %H:%M:%S %Y")) just after the imports in the startup code for the IceTV/plugin.py module. That should ensure that the _strptime module is imported by main thread code.

Its relative rarity makes it difficult to replicate and to ensure that it's been fixed.

[Grumpy_Geoff]

I see now I had it once in Feb and once in March too. Since it recovers, don't worry about it.
Was it something that came with plugin version 20180601 as I haven't seen it on 20171208?

[peteru]

Its relative rarity makes it difficult to replicate and to ensure that it's been fixed.

Given that it is a non-crashing issue and the most likely impact is one missed IceTV poll once in a blue moon, I'd say it is not worth spending any time on it. Various networking issues are likely to result in missed polls more often.

[prl]

OK. Do you want it documented in the issue tracker, anyway?

[peteru]

I don't see a reason, unless this becomes a more persistent occurrence that does require attention.

[Brainz]

IceTV is not updating this morning. I have posted on their forum in support of spacecadet's post.


Re: Updates Failing 15 August 2019
« Reply #1 on: August 16, 2019, 09:25:51 AM »

Quote from: spacecadet on August 15, 2019, 11:36:20 PM

Beyonwiz U4

IceTV updates started failing this evening with "Error trying to fetch: Invalid control charcter at: line 1 column 1167762 (char 1167761)

Rebooted. Relogged in. Not fixed.
----------------------------------------------------

I am also having the same problem. Logged out, logged in, rebooted. No info in EPG at all now.
My Beyonwiz T2 had been playing up since last night and I thought it was the box. After factory resetting it and restoring backups I now believe it was IceTV causing the issues.

[Grumpy_Geoff]

IceTV is not updating this morning. I have posted on their forum in support of spacecadet's post.

Yep, indeed. Crap data in the IceTV EPG content.

Code: Select all

    
  File "/usr/lib/enigma2/python/Plugins/SystemPlugins/IceTV/plugin.py", line 348, in doWork
    
  File "/usr/lib/enigma2/python/Plugins/SystemPlugins/IceTV/plugin.py", line 644, in getShows
    
  File "/usr/lib/python2.7/site-packages/requests/models.py", line 896, in json
    
  File "/usr/lib/python2.7/json/__init__.py", line 339, in loads
    
  File "/usr/lib/python2.7/json/decoder.py", line 364, in decode
    
  File "/usr/lib/python2.7/json/decoder.py", line 380, in raw_decode
    
exceptions.ValueError: Invalid control character at: line 1 column 283214 (char 283213)

[prl]

In the corresponding IceTV forum topic, Daniel Hall @ IceTV said that the problem has now been resolved.

I understand that IceTV is working on fixing the encoding of non-ASCII characters in the EPG data. If this has been a glitch in that process, it may be worth it in the long run. When it's fixed, it means that characters with multi-byte UTF-8 representations will be displayed correctly, so names like Sofie Gråbøl (The Killing, Fortitude) will display correctly, and not have the non-Latin characters mangled.

[Grumpy_Geoff]

Is anyone else having an IceTV fetch issue where the update does not complete?
The normal process is for the EPG to be fetched first, then the timers. In this case, the EPG fetch doesn't complete, there's just a 'Start update' IceTV log entry.

I posted the below on the IceTV forum, no response so far.


EPG data feed issue?
The IceTV fetch Beyonwiz T2 and T4 models doesn't complete -

Code: Select all

{938}<  2825.712> [IceTV] 2019-09-20 09:31:14: Start update
{938}<  2827.265> /usr/lib/enigma2/python/Plugins/SystemPlugins/IceTV/plugin.py:352: RuntimeWarning: tp_compare didn't return -1 or -2 for exception
{938}<  2827.272> Unhandled Error
...
  File "/usr/lib/enigma2/python/Plugins/SystemPlugins/IceTV/plugin.py", line 352, in doWork
exceptions.OverflowError: Python int too large to convert to C long

The fetch at 09:16 AWT succeeded on the T4 (the T2 wasn't running then).

[grampus]

Both my T3 and U4 have been fetching OK for a full log's worth

[Grumpy_Geoff]

Both my T3 and U4 have been fetching OK for a full log's worth

Thanks.
Perhaps it's a location specific guide data issue then.

What version is your IceTV plugin?

[prl]

I'm seeing it in the Canberra data. I don't want to go into too much detail until Daniel Hall@IceTV has verified that I'm correct about what the problem is.

It shouldn't be a model-specific problem, or depend on the IceTV version.

[prl]

I posted the below on the IceTV forum, no response so far.

I have since commented there, too.

[Grumpy_Geoff]

I posted the below on the IceTV forum, no response so far.

I have since commented there, too.

Ta.

[Grumpy_Geoff]

It completed the fetch just then, but had an error of some sort -

Code: Select all

{600}<  2383.836> [IceTV] 2019-09-20 15:22:10: Start update
{603}<  2387.404> [gRC] main thread is non-idle! display spinner!
{600}<  2391.047> [EPGFetcher] ERROR: lookup of 0x01 "Violence" returned "Cult"
{600}<  2402.731> [EPGFetcher] ERROR: lookup of 0x01 "Violence" returned "Cult"
{600}<  2404.484> [IceTV] 2019-09-20 15:22:31: EPG download OK
{600}<  2404.719> [IceTV] 2019-09-20 15:22:31: Timers updated OK
{600}<  2404.720> [IceTV] 2019-09-20 15:22:31: End update

Any idea what that error is related to?

[prl]

My IceTV EPG now loads successfully. The problem should be fixed.

[prl]

A minor fix related to (but not the cause of) the IceTV plugin crashes yesterday has been merged into the firmware repository.

If you look at the genres for Movie: Social Media Murders (In Canberra, PRIME 7 & PRIME7 HD, 12:00 Thu 26 Sep) in the current firmware, you'll see "Drama, Movie". When the firmware update arrives, it will become "Drama, Movie, Violence".

The cause of yesterday's IceTV crashes was that there was a problem with how the Violence genre tag was represented in the IceTV feed. That was fixed yesterday, but the plugin needs to be updated to be able to display the new genre tag.

[Grumpy_Geoff]

The cause of yesterday's IceTV crashes was that there was a problem with how the Violence genre tag was represented in the IceTV feed. That was fixed yesterday, but the plugin needs to be updated to be able to display the new genre tag.

I had assumed there was a data mismatch given the subsequent errors I received as shown above.

[prl]

The cause of yesterday's IceTV crashes was that there was a problem with how the Violence genre tag was represented in the IceTV feed. That was fixed yesterday, but the plugin needs to be updated to be able to display the new genre tag.

I had assumed there was a data mismatch given the subsequent errors I received as shown above.

Yes, that error, lookup of 0x01 "Violence" returned "Cult", is due to there not being an entry for Violence in the IceTV genre tables. Handling genres in IceTV is messy.

If you have debug logs for a fetch at the right time yesterday, you'll see anoher fatal error that happened, this time because the plugin made some incorrect assumptions about what fields must be present in a JSON category entry. That was also fixed in the feed, but I will make the plugin more robust.

[prl]

The overnight online beta update 20190921 adds the Violence genre tag.

It's a big update: 300+ packages.

[Gully]

The overnight online beta update 20190921 adds the Violence genre tag.

It's a big update: 300+ packages.

Has anyone done it online?

[Grumpy_Geoff]

The overnight online beta update 20190921 adds the Violence genre tag.

It's a big update: 300+ packages.

Has anyone done it online?

Yep - U4.

[Gully]

The overnight online beta update 20190921 adds the Violence genre tag.

It's a big update: 300+ packages.

Has anyone done it online?

Yep - U4.

Thanks

[prl]

The overnight online beta update 20190921 adds the Violence genre tag.

It's a big update: 300+ packages.

Has anyone done it online?

Yep - U4.

Likewise, also, coincidentally, on a U4.

[MrQuade]

U4, V2, and T4 all successful. No wuckers.

[MrQuade]

U4, V2, and T4 all successful. No wuckers.

[prl]

I've done the online update to 20190921 on all of T2, T3, T4, U4 & V2. No problems.