T4 - Constant Spinner

[naigy]

Hi,

I have recently started to see regular spinners on my T4. It occurs often about once a minute for 5 to 10 seconds but has also occurred less frequently and also for longer durations and on at least one occasion resulted in the T4 rebooting after probably 3 minutes.

We have in recent weeks had several blackouts but the other thing I am thinking may have had an impact is I have set up a plex server on a raspberry pi 4 and linked it to my samba WizT4 share. I have tried switching the raspberry pi off and that doesn't seem to impact it at all so guessing while the timeline kind of co-insides that that is likely just a coincidence. Have also disabled FTP and MiniDLNA however neither of those seem to have had an impact.

I have logged into my T4 by Telnet and noticed that when I type dmesg I get the following 3 lines as part of the output being I am guessing perhaps very relevant (perhaps an issue brought on by the power blackouts. However as it isn't a full linux install unsure how to fix what I believe is HDD corruption.

Code: Select all

EXT4-fs (sda1): error count: 574
EXT4-fs (sda1): initial error at 1671789128: ext4_validate_block_bitmap:375
EXT4-fs (sda1): last error at 1672931805: ext4_ext_find_extent:876: inode 453145

Appreciate any ideas on the spinner and also this possible HDD issue (if unrelated).

[naigy]

Hi all,
Think I have managed to sort this out. Suspicion of it being HDD corruption appears correct and have now been watching for about 15 minutes and haven't seen any issues and utilising recordings and playback etc. hasn't caused spinner to appear (so far)

I had tried to get fsck to work without success (primarily due to being unable to unmount the drive with umount). Doing a reboot with the switch at rear instead of via Gui may have been what made the difference . Also found that I appear to have needed e2fsck instead of fsck.

Dmesg now doesn't reference any filesystem issue so hopefully all good.

[prl]

I had tried to get fsck to work without success (primarily due to being unable to unmount the drive with umount).

A volume can't be unmounted if it is currently active: any currently open files or any processes with their current directory on the volume.

This means that the timeshift recording needs to be stopped, that there be no current recordings, and that there is no logging to the HDD. If you're doing the fsck through the commandline interface (as you seem to be), you also need to make sure that the current directory of the shell that you're running is not on the HDD (do a cd without any arguments to go to your home directory, which is on the root volume in the firmware flash, before trying to unmount the HDD.

[naigy]

I had tried to do the check through the OSD menu but that failed. I did make sure I was in my home dir and had disabled timeshift in OSD menu and made sure no other recordings or devices linked via samba (including shutting down rpi which links to it via Plex. That is why I then went to try via the command line

I however appear to have thought the issue was solved a bit to hasty. The spinner has returned. Currently coming up for about 5 seconds and then reappearing between 10sec and 1min40. Any idea where I should start to try work out what is causing it.

To clarify also I am currently running firmware 19.3.20211010 if that is relevant

[prl]

disabled timeshift in OSD menu

That's a two-step process. You need to disable it in the setup screens, and then change to a different channel. Disabling it disables auto-start of the timeshift recording, but it doesn't stop one if there's already one waiting. Changing channels stops the current timeshift recording, and then doesn't start a new one if auto-start is disabled.

Do you have debug logging enabled and directed to /media/hdd/logs/? If so, you need to stop logging (or redirect it to /home/root/logs/), and do a GUI restart.

[naigy]

Ok that explains it. Pretty sure I didn't change channel after disabling timeshift. My Bad!

Currently didn't have debug logging enabled but have now enabled it (/home/root) and done a reset. Of course at the moment it now isn't doing it (not sure if perhaps the issue starts after it has beenn several hours after it has booted perhaps. Will watch it and if occurs again with download that log file then I guess

[naigy]

Have been tracking this and decided to reload the firmware which momentarily seemed to help and limit this occurring to it being more sporadic (at least when I have been watching). However this afternoon it has been back and more consistent again. It appears it may relate to autotimers or EPG cache from what I can make out in the logs (have included 2 small portions from the current log file for viewing but also attached the full log file.

Code: Select all

{600}< 46287.045> [AutoTimer] No changes in configuration, won't parse
{602}< 46289.897> [gRC] main thread is non-idle! display spinner!
{602}< 46304.498> [gRC] main thread is non-idle! display spinner!
{600}< 46374.012> [AutoTimer] No changes in configuration, won't parse
{602}< 46377.898> [gRC] main thread is non-idle! display spinner!
{602}< 46391.435> [gRC] main thread is non-idle! display spinner!
{600}< 46416.747> [eDVBLocalTimerHandler] no transponder tuned... or no TDT/TOT avail .. try to use RTC :)

600}<630518.028> [eDVBLocalTimerHandler] RTC to Receiver time difference is 0 seconds
{600}<630518.028> [eDVBLocalTimerHandler] no change needed
{625}<630518.028> [eventData] EPG Cache is corrupt (eventData::~eventData), you should restart Enigma!
{625}<630518.028> [eventData] EPG Cache is corrupt (eventData::~eventData), you should restart Enigma!
{600}<630519.512> [AutoTimer] No changes in configuration, won't parse
{602}<630522.036> [gRC] main thread is non-idle! display spinner!
{602}<630536.784> [gRC] main thread is non-idle! display spinner!
{600}<630629.320> [AutoTimer] No changes in configuration, won't parse
{602}<630633.037> [gRC] main thread is non-idle! display spinner!
{600}<630706.822> [AutoTimer] No changes in configuration, won't parse
{602}<630710.036> [gRC] main thread is non-idle! display spinner!

Any advice as to how to check for autotimer issues or way to prevent EPG Cache corruption.

Enigma2-2023-01-08_08-54-09.log.txt

(3.82 MiB) Downloaded 27 times

[prl]

Any advice as to how to ... prevent EPG Cache corruption.

It may be related to whatever is causing the AutoTimer processing to stall, or it could be the cause of the stall.

You can force a complete re-build of the EPG cache (assuming that you're not using IceTV), by clearing it by enabling IceTV, then disabling it. Then visit a channel from each broadcaster for about 30-60 sec each to reload the EPG cache.

[naigy]

Hi,

Have reloaded the EPG via EPGRefresh after clearing and the same is still constantly occurring.

Code: Select all

{580}<  1897.166> [AutoTimer] No changes in configuration, won't parse
{603}<  1900.749> [gRC] main thread is non-idle! display spinner!
root@beyonwizt4:~/logs# tail Enigma2-2023-01-16_12-59-24.log
{580}<  1877.329> [eConsoleAppContainer] Starting /bin/sh
{580}<  1889.487> [Console] finished: /usr/bin/ntpdate-sync
{580}<  1889.488> [NetworkTime] setting E2 time: 1673836218.47
{580}<  1897.166> [AutoTimer] No changes in configuration, won't parse
{603}<  1900.749> [gRC] main thread is non-idle! display spinner!
{580}<  1974.988> [AutoTimer] No changes in configuration, won't parse
{603}<  1978.250> [gRC] main thread is non-idle! display spinner!
{603}<  1991.249> [gRC] main thread is non-idle! display spinner!
{580}<  2053.120> [AutoTimer] No changes in configuration, won't parse
{603}<  2055.748> [gRC] main thread is non-idle! display spinner!

How do I go about checking for issues in autotimers as at least now it appears the EPG is not corrupt? or should I be looking elsewhere?

[Grumpy_Geoff]

However this afternoon it has been back and more consistent again. It appears it may relate to autotimers or EPG cache from what I can make out in the logs (have included 2 small portions from the current log file for viewing but also attached the full log file.

You've got more than 1,000 timers going back four months - are you keeping them for that long on purpose?

I think you should fix up your timezone -

Code: Select all

{600}<    49.678> [AutoTimer] Failed to load timezone notifier.
{600}<    49.686> [Timezones] setting timezone to Australia/Sydney

There should be an AutoTimer run initiated by the Timezone code, but it isn't being run for you.

The normal location for the EPG cache is "internal flash" (/etc/enigma2/).
Your location is set to /media/hdd/. I suggest you set it to internal flash memory.
Additionally, turn off setting "EPG cache reload" as you appear to have it on and it goes tits up -

Code: Select all

{28096}<172876.461> [EPGC] Refreshing EPGCache.
{28096}<172876.461> [EPGC] /media/hdd/epg.dat not found, try /epg.dat
{28096}<172876.461> [EPGC] /epg.dat not found, giving up

No AutoTimer definitions parsing is being logged. I suspect this is because of a corrupted EPG cache.
Additionally, it appears the AutoTimer plugin is being invoked multiple times - the below shows four initiations in five minutes. This may also be because of a corrupted EPG cache.
As to why the first AutoTimer scheduled run occurred ~44,000 seconds after enigma2 start, I've no idea.

Code: Select all

{600}< 44008.836> [AutoTimer] No changes in configuration, won't parse
{602}< 44012.798> [gRC] main thread is non-idle! display spinner!
{602}< 44026.798> [gRC] main thread is non-idle! display spinner!
{600}< 44108.193> [AutoTimer] No changes in configuration, won't parse
{602}< 44110.799> [gRC] main thread is non-idle! display spinner!
{602}< 44131.911> [gRC] main thread is non-idle! display spinner!
{600}< 44205.071> [AutoTimer] No changes in configuration, won't parse
{602}< 44208.798> [gRC] main thread is non-idle! display spinner!
{602}< 44223.028> [gRC] main thread is non-idle! display spinner!
{600}< 44313.286> [AutoTimer] No changes in configuration, won't parse
{602}< 44316.798> [gRC] main thread is non-idle! display spinner!
{602}< 44331.113> [gRC] main thread is non-idle! display spinner!

[naigy]

Thanks for your informative reply Geoff.

1. In regards to your timezone comment. I already have Timezone set per Openwebif to Australia - > Sydney & Internet (NTP). and haven't any knowledge of seeing it having the incorrect time at all in the info bar etc. Is that the setting you are referring to or is there a separate setting for timezone somewhere else.

2. Not keeping the old timers on purpose it just does it by default. I have done the Menu -> Timers -> Cleanup. Is there a way to change this to happen automatically

3. I had changed the EPG location earlier today to internal cache but have now also turned off EPG Cache Reload as suggested

I have in addition deleted all my autotimers earlier today and reloading them all manually (some through GUI and others via OpenWebif). Currently still in progress.

Hope the combination of Geoffs suggestion and redoing the autotimers helps to resolve the issue as the constant spinner and remote unresponsive has been driving me a little nuts.

Will post back in a few days and advise how its going. Thanks again all for your help.

[Grumpy_Geoff]

1. In regards to your timezone comment. I already have Timezone set per Openwebif to Australia - > Sydney & Internet (NTP). and haven't any knowledge of seeing it having the incorrect time at all in the info bar etc. Is that the setting you are referring to or is there a separate setting for timezone somewhere else.

Your serring isn't wotking. What's in Setup>>System>>Time settings?

2. Not keeping the old timers on purpose it just does it by default. I have done the Menu -> Timers -> Cleanup. Is there a way to change this to happen automatically

Setup>>TV>>Recording settings, 3rd page "Remoe completed timers after (days)"
I suggest 8 days.

I have in addition deleted all my autotimers earlier today and reloading them all manually (some through GUI and others via OpenWebif). Currently still in progress.

The definitions could still be an issue, see how you go. You may need to post the definitions if you still have issues. If I'd seen this earlier (I've been away on hols) then I'd have asked for it before you nuked it.

[naigy]

Thanks again Geoff

What's in Setup>>System>>Time settings?

Australia, Sydney, NTP(Internet), au.pool.ntp.org, 30 minutes, Dayname D Month Year, HH:mm:ss

Setup>>TV>>Recording settings, 3rd page "Remoe completed timers after (days)"
I suggest 8 days.

Setting changed. Was set at 120days as you had thought.

I do have a backup copy of the autotimers and timer files before changing anything (among all other files in /etc/enigma2) if you do want them I can supply. Just let me know.

Thanks again. Crossing my fingers its all sorted now

[Grumpy_Geoff]

What's in Setup>>System>>Time settings?

Australia, Sydney, NTP(Internet), au.pool.ntp.org, 30 minutes, Dayname D Month Year, HH:mm:ss

Yep that looks fine. Perhaps it was a knackered EPG cache that caused the bark.

I do have a backup copy of the autotimers and timer files before changing anything (among all other files in /etc/enigma2) if you do want them I can supply. Just let me know.

Yep, attach the backup of "/etc/enigma2/autotimer.xml" file and I'll take a peep to see if I can catch any obvious errors.

[naigy]

See attached autotimer file as requested. As stated this is before I have cleared them all and reloaded them all manually.

[Grumpy_Geoff]

See attached autotimer file as requested. As stated this is before I have cleared them all and reloaded them all manually.

Take your "MacGyver" definition below as an example -

Code: Select all

 <timer name="MacGyver" match="MacGyver" enabled="yes" id="2" location="/hdd/movie/Craig/" searchType="start">
  <bouquet>1:7:1:0:0:0:0:0:0:0:FROM BOUQUET "userbouquet.favourites.tv" ORDER BY bouquet</bouquet>
 </timer>

The broadcast program itself repeats within the week (EPG extract) -
"begin": "05:00",
"shortdesc": "When a satellite crashes from orbit and animals start dying from a strange organism attached to it, MacGyver must investigate.",
"date": "Mon 23.01.2023",

"begin": "12:00",
"shortdesc": "When a satellite crashes from orbit and animals start dying from a strange organism attached to it, MacGyver must investigate.",
"date": "Mon 23.01.2023",

"begin": "03:10",
"shortdesc": "When a satellite crashes from orbit and animals start dying from a strange organism attached to it, MacGyver must investigate.",
"date": "Tue 24.01.2023",

... so I'd use "Require description to be unique" as either "On same service" or "On any service".
Further, be aware that the setting for "Check for uniqueness in" with a value of "Title and all descriptions" is buggy.
Additionally, in the OWIF AutoTimer page, if you set a timer/recording uniqueness check (i.e. set option "Require description to be unique:" to anything other than "No"), then the AutoTimer plugin will default to using "Check for uniqueness in Title and all descriptions" (i.e. buggy).
So, to use "Title and all descriptions" you need to fix this by doing a code change - see viewtopic.php?f=47&t=15098&p=199505#p199497 for the required code change to implement the fix for using "Title and all descriptions", or stick with "Title and Short description"

Keeping timers for 8 days allows old timers to be checked for the uniqueness test.

Also enable setting "Check existing timer based on begin/end" (AutoTimer>>MENU>>6/Setup) to handle the same event when the broadcasters replace it with a different EIT (NINE used to do it a lot with slightly altered times).

You've only got two definitions using "description" searches, and I don't think they'd be a processing issue.

[naigy]

Hi,

Just to give an update on this. It is definitely better after everything I have done. When I have been watching I haven't seen the spinner at all. It appears though according to the log that it is still happening however like I said I haven't seen it whilst watching. I feel like Autotimers is running a lot more than its scheduled (currently set at every 60 minutes.

I have attached my recent log file but here in a small section to perhaps give an idea

{1676}< 13913.254> [AutoTimer] No changes in configuration, won't parse
{1676}< 13914.609> [eDVBTSTools] setSource loading streaminfo for /media/hdd/movie/20230117 2127 - 7mateHD Sydney - Aussie Salvage Squad.ts
{1676}< 13978.338> [AutoTimer] No changes in configuration, won't parse
{1676}< 13979.948> [eDVBTSTools] setSource loading streaminfo for /media/hdd/movie/20230117 2127 - 7mateHD Sydney - Aussie Salvage Squad.ts
{1678}< 13983.093> [gRC] main thread is non-idle! display spinner!
{1676}< 14043.689> [AutoTimer] No changes in configuration, won't parse
{1676}< 14045.072> [eDVBTSTools] setSource loading streaminfo for /media/hdd/movie/20230117 2127 - 7mateHD Sydney - Aussie Salvage Squad.ts
{1676}< 14108.788> [AutoTimer] No changes in configuration, won't parse
{1676}< 14110.137> [eDVBTSTools] setSource loading streaminfo for /media/hdd/movie/20230117 2127 - 7mateHD Sydney - Aussie Salvage Squad.ts
{1699}< 14153.779> [eDVBSectionReader] DMX_SET_FILTER pid=18
{1699}< 14153.780> [eDVBSectionReader] DMX_SET_FILTER pid=18
{1699}< 14153.780> [eDVBSectionReader] DMX_SET_FILTER pid=18
{1699}< 14160.781> [eEPGCache] abort non avail schedule other reading
{1699}< 14160.799> [eEPGCache] nownext finished(1673953230)
{1699}< 14168.915> [eEPGCache] schedule finished(1673953238)
{1699}< 14168.915> [eEPGCache] next update in 5 min
{1676}< 14173.815> [AutoTimer] No changes in configuration, won't parse
{1676}< 14175.163> [eDVBTSTools] setSource loading streaminfo for /media/hdd/movie/20230117 2127 - 7mateHD Sydney - Aussie Salvage Squad.ts
{1676}< 14279.277> [AutoTimer] No changes in configuration, won't parse
{1676}< 14281.975> [eDVBTSTools] setSource loading streaminfo for /media/hdd/movie/20230117 2127 - 7mateHD Sydney - Aussie Salvage Squad.ts
{1676}< 14349.689> [AutoTimer] No changes in configuration, won't parse
{1676}< 14351.191> [eDVBTSTools] setSource loading streaminfo for /media/hdd/movie/20230117 2127 - 7mateHD Sydney - Aussie Salvage Squad.ts
{1676}< 14415.078> [AutoTimer] No changes in configuration, won't parse
{1676}< 14417.151> [eDVBTSTools] setSource loading streaminfo for /media/hdd/movie/20230117 2127 - 7mateHD Sydney - Aussie Salvage Squad.ts
{1678}< 14420.356> [gRC] main thread is non-idle! display spinner!

[Grumpy_Geoff]

I feel like Autotimers is running a lot more than its scheduled (currently set at every 60 minutes.

Every time you press GREEN whilst the AutoTimer definitions list is showing, it kicks off an AutoTimer run.
So, if you're going to make lots of definition changes, then press it once at the end of all of the edits.

Additional runs may come from the EPG cache auto-save, so try turning that off.
Also turn off the invocation from EPGRefresh.

[stevebow]

Also enable setting "Check existing timer based on begin/end" (AutoTimer>>MENU>>6/Setup) to handle the same event when the broadcasters replace it with a different EIT (NINE used to do it a lot with slightly altered times).

I've noticed SBS do this for their news in Sydney on occasion. What happens with this setting - is the original (auto)timer event replaced with the later updated event?

[Grumpy_Geoff]

Also enable setting "Check existing timer based on begin/end" (AutoTimer>>MENU>>6/Setup) to handle the same event when the broadcasters replace it with a different EIT (NINE used to do it a lot with slightly altered times).

I've noticed SBS do this for their news in Sydney on occasion. What happens with this setting - is the original (auto)timer event replaced with the later updated event?

Yes, as long as there is greater than 80% overlap comparing the new event and the original unpadded timer's duration.