[ET10x00] Software locking up when scrolling through EPG

[ccs]

I'm not losing the debug file when I power off normally. It's just I cannot power off normally on the lock-up as NONE of the remote buttons work, including the power button. If I kill the box by switching off the mains as a result of a lockup I get no debug logs and no crash logs.

That's what I was saying in my post.

 

[ccs]

When I was messing about with nas mounts last week, I have the faintest recollection of debug logs being switched off when I was sure they were on.

Have you noticed anything similar?

 

[adm]

When I was messing about with nas mounts last week, I have the faintest recollection of debug logs being switched off when I was sure they were on.

Have you noticed anything similar?

I was also messing around with the same and wondered if this was the cause of the missing debug messages (perhaps a timing issue when accessing external equipment)
During the time I was messing around with different settings I deleted my external disk mount and rebooted the box - it made no difference.
When deleting the mount the box crashed (finger trouble) and generated 3 off crash messages so the box is still capable of generating these messages when necessary.
I also deleted/removed a MP3 browswer plugin that I installed last week and rebooted - no difference.

 

[birdman]

I get a debug log if I put my box into deep standby
I do not get a debug log (or crash log) if the system hangs and I have to kill via the mains switch.
I do not get a debug log on the box starting up as a result of coming out of deep standby or as a result of being switch back on from the mains

That's the bit which makes no sense.
The log is opened by the script which starts enigma2. So if it's being opened it will be there when the system hangs.

I get no crash logs.

It's not crashing,so that's to be expected.

Reverting back to 5.1.021 which was also a software update
I only get a debug log for a normal shutdown. There is no startup debug log

As I said, it is opened (if at all) at enigma2 start-up. It doesn't (and can't) "just appear" at shutdown.

 

[adm]

That's the bit which makes no sense.
The log is opened by the script which starts enigma2. So if it's being opened it will be there when the system hangs.

It's not crashing,so that's to be expected.

As I said, it is opened (if at all) at enigma2 start-up. It doesn't (and can't) "just appear" at shutdown.

Perhaps I'm misunderstanding.

As I read you post...

On box start-up a log is started which presumably remains in RAM. So when does this log first get written to the log folder.
1) As and when required on a continuous basis while the box is on?
2) When the amount of data in the RAM reaches a threshold value?
3) Only as part of the shutdown process?

If 3 then this is what I’m seeing - one debug log file per on to off operation EXCEPT no file is written when I have to kill the box by an abrupt mains diconnection.

It doesn't "just appear" at shutdown
The file is in the log folder the next time the box is switched on with a time stamp matching the time when the box was last switched off.

So, all debug files are correcrtly generated if the box closes down normally.
When the box hangs debug info cannot be written because the box cannot be shut down in a normal way

 

[birdman]

Perhaps I'm misunderstanding.

Hence the questioning....to avoid any misunderstanding both ways.

On box start-up a log is started which presumably remains in RAM.

No. It gets written to the file-system as each entry arrives. That's why you can read the latest entries in the log when the process is running.

...one debug log file per on to off operation EXCEPT no file is written when I have to kill the box by an abrupt mains diconnection.

No. See above. You can, if you wish, tail -f the log to see the entries as they arrive whilst the process is running.

The file is in the log folder the next time the box is switched on with a time stamp matching the time when the box was last switched off.

That's correct. If you've powered off at the mains the log should still be there, but its timestamp might not be correct. It should, however, be the last-but-one log (another one will have been started by the time you get to look for it).

So, all debug files are correctly generated if the box closes down normally.

They are written to disk as the entries arrive. There will be memory buffering, but that would just mean you might not get the last few lines: the file should still be there - it was created when enigma2 started.

 

[adm]

Hence the questioning....to avoid any misunderstanding both ways.

[snip]

Thanks for the explanation.

What has been confusing me is the timestamp applied to the debug file.

I telnet into the box and at 1:55am issue a init 4 command and then go to the logs folder and delete all the logs. At 2:06am I issue a init 3 command I get a new debug log file with a time stamp of 2:06. The time stamp starting this way is the current correct time. This confirms to me that a file is created on start-up.

BUT….

I now put my box into deep standby at 2:09am and then switch it back on at 2:15am. On immediately checking I now see another debug log with a time stamp of 2:09 and NOT 2:15 as expected. The time stamp applied to this file is last time the box was switched off and NOT the time that the box was switched back on again. The file and name may have been created as the box switched on but the time stamp hasn’t come from the current time – it has come from a historic record which may be minutes or hours in the past depend on how long the box has been switched off.

I’ve been assuming that the time stamp on the file reflected reality hence when switching the box off normally the file was created on switch off, as per the time stamp applied to the file.

 

[ccs]

Where are you getting the time from, a time server or the current mux/transponder?

 

[adm]

The file and name may have been created as the box switched on but the time stamp hasn’t come from the current time – it has come from a historic record

Just to confirm. I switched the box into deepstandby at 3:00am and next switched the box on at 9:27am. The timestamp on the most recent entry in the log folder is 3:00:44.

Edit: and first time into the graphocal EPG and a lock up. The lock up occured immediately on the bouquet/epg appearing

Telnet to box, init 4 then init 6 and here is the debug file
The file with the timestamp of 3-00-44 was the one active when the lock-up occured
The file with the timestamp of 9-42-19 is the file start after the init4, init 6 reboot

View attachment logs_3.zip



Edit 2
Could this be an extreme symptom of something I have seen on a very odd occasion in many builds? I tend to change channels by going to the graphical EPG and scrolling up/down to find something else to watch. Sometimes when pressing, say, the down button multiple times the box doesn’t respond to the key presses immediately. It waits for maybe one or two seconds and then responds to all previous key presses and the program 5 down from the start position is highlighted.
In the case of the lock-up this delay is extended to forever (or at least > 5 minutes)

 

[ccs]

I reckon the last shutdown time is used very early in the boot process.

Very long thread here which may confirm.....

http://www.world-of-satellite.com/showthread.php?58598-Vix-5-1-006-Time-wrong&highlight=timer+server

 

[birdman]

BUT….

I now put my box into deep standby at 2:09am and then switch it back on at 2:15am. On immediately checking I now see another debug log with a time stamp of 2:09 and NOT 2:15 as expected. The time stamp applied to this file is last time the box was switched off and NOT the time that the box was switched back on again.

That's because your box hasn't yet got the correct time. fake-hwclock will have set it to the shutdown time and enigma2 has started up before your box has managed to get the correct current time via NTP.
Don't read too much into the log names or time-stamps. Just take their names in order.

 

[birdman]

Very long thread here which may confirm.....

http://www.world-of-satellite.com/showthread.php?58598-Vix-5-1-006-Time-wrong&highlight=timer+server

Yes. I must get back to SpaceRat about my "improved" ntpdate-sync.

 

[adm]

For now I've reverted back to 5.1.021 which appears to be working without problems. This is using the same settings, bouquets and EPG that locked-up 5.1.022 on my machine.

On a lock-up I can still telnet into the box to reset it with an init 6 command. On lock-up the box doesn't respond to any key on the remote. The last debug report I posted as a result of a lock-up seems to (correctly) show that more than one scroll down (the graphical EPG) command was seen by the box and recorded in the log (as the last few entries) but it didn't cause anything to happen on screen.

I tried installing 5.1.022 by both the software update and the couch flash method.
I've tried deleting the epg.dat file twice using telnet and the init 4 command before deleting the file
I only get my EPG for Freesat and Freeview over the air.

 

[birdman]

FYI: reported here to:
http://www.world-of-satellite.com/s...-I-scroll-through-the-EPG&p=468627#post468627

 

[daverave]

I had a similar problem with the GraphicalEPG freezing after installing 5.1.022 and reloading my backup settings. I was able to cure the problem as follows

Firstly go to Setup/EPG/Load-save-delete/Delete EPG and delete etc/enigma2/epg.dat

Secondly go to Setup/EPG/CrossEPG/Download now.

This seems to have cured the problem for me so hopefully does for others suffering the same problem.

 

[adm]

I had a similar problem with the GraphicalEPG freezing after installing 5.1.022 and reloading my backup settings. I was able to cure the problem as follows

Firstly go to Setup/EPG/Load-save-delete/Delete EPG and delete etc/enigma2/epg.dat

Secondly go to Setup/EPG/CrossEPG/Download now.

This seems to have cured the problem for me so hopefully does for others suffering the same problem.

i) I have deleted the EPG file multiple times by telenet, init4, remove file AND by the menu option
ii) I don't use CrossEPG and it is disabled. EPG importer is also been disabled. I get all my 7 day EPG over the air (Enable EIT EPG = yes, Enable Freesat EPG = yes)

Lock-up still occurs although more random in nature since I first reported it.

 

[abu baniaz]

What display settings have you got for Graphical EPG?
Does crash happen more often if you select a bouquet with a missing picon?

 

[ccs]

Maybe a debug during the period when it works might help?

Which skin are you using - the last skin reference in the debug log is to GraphicalEPGPIG

My guess is that you're using picture in graphics and channel preview mode.

 

[abu baniaz]

Does the bouquet have services that are on a dead frequency owing to Freeview changes?

 

[adm]

Background answering a few other questions
Skin = Vix-Night-HD (1280 x720)

My EPG location is /media/hdd
My EPG filename is epg (.dat)
I get my EPG over the air and don' t import any EPG from the Internet
For the graphical epg, channel preview mode = yes, show bouquets on launch = yes, picture in graphics = yes




Couch re-installed 5.1.022 with settings and plug-in restore from 021

Installed and ran the enigma2-plugin-extensions-removeepg-2016_06_17_all.pk
http://www.world-of-satellite.com/showthread.php?52890-Remove-EPG
EPG confirmed as being mainly blank and being re-populated

A few minutes later the box locks-up when first accessing graphical epg

Telnet session
init 4 - no visible response seen on TV screen – Mini video picture and audio still working.
killall enigma2 – no change, mini video picture and audio still working.
killall -9 enigma2 – EPG still on TV screen, no mini TV picture (black picture) and audio dead.
init 3 - EPG still on screen, mini TV picture shows one of the VIX start-up splash screens and no audio
The box is still locked up.

Result of telnet, including an intermediate ps -ef

Welcome to OpenViX for et10000
openvix 5.1 et10000

et10000 login: root
Last login: Thu Mar 29 15:47:58 BST 2018 on pts/0
root@et10000:~#
root@et10000:~# init 4
root@et10000:~# ps -ef
UID PID PPID C STIME TTY TIME CMD
root 1 0 0 15:05 ? 00:00:00 init [4]
root 2 0 0 15:05 ? 00:00:00 [kthreadd]
root 4 2 0 15:05 ? 00:00:00 [kworker/0:0H]
root 6 2 0 15:05 ? 00:00:00 [ksoftirqd/0]
root 7 2 0 15:05 ? 00:00:00 [rcu_sched]
root 8 2 0 15:05 ? 00:00:00 [rcu_bh]
root 9 2 0 15:05 ? 00:00:00 [migration/0]
root 10 2 0 15:05 ? 00:00:00 [lru-add-drain]
root 11 2 0 15:05 ? 00:00:00 [cpuhp/0]
root 12 2 0 15:05 ? 00:00:00 [cpuhp/1]
root 13 2 0 15:05 ? 00:00:00 [migration/1]
root 14 2 0 15:05 ? 00:00:00 [ksoftirqd/1]
root 16 2 0 15:05 ? 00:00:00 [kworker/1:0H]
root 17 2 0 15:05 ? 00:00:00 [kdevtmpfs]
root 18 2 0 15:05 ? 00:00:00 [oom_reaper]
root 19 2 0 15:05 ? 00:00:00 [writeback]
root 20 2 0 15:05 ? 00:00:00 [crypto]
root 22 2 0 15:05 ? 00:00:00 [bioset]
root 23 2 0 15:05 ? 00:00:00 [kblockd]
root 24 2 0 15:05 ? 00:00:00 [ata_sff]
root 25 2 0 15:05 ? 00:00:00 [cfg80211]
root 26 2 0 15:05 ? 00:00:00 [rpciod]
root 27 2 0 15:05 ? 00:00:00 [xprtiod]
root 28 2 0 15:05 ? 00:00:00 [kswapd0]
root 29 2 0 15:05 ? 00:00:00 [vmstat]
root 30 2 0 15:05 ? 00:00:00 [bioset]
root 31 2 0 15:05 ? 00:00:00 [nfsiod]
root 32 2 0 15:05 ? 00:00:00 [cifsiod]
root 61 2 0 15:05 ? 00:00:00 [bioset]
root 62 2 0 15:05 ? 00:00:00 [bioset]
root 63 2 0 15:05 ? 00:00:00 [bioset]
root 64 2 0 15:05 ? 00:00:00 [bioset]
root 65 2 0 15:05 ? 00:00:00 [bioset]
root 66 2 0 15:05 ? 00:00:00 [bioset]
root 67 2 0 15:05 ? 00:00:00 [bioset]
root 68 2 0 15:05 ? 00:00:00 [bioset]
root 69 2 0 15:05 ? 00:00:00 [scsi_eh_0]
root 70 2 0 15:05 ? 00:00:00 [scsi_tmf_0]
root 71 2 0 15:05 ? 00:00:00 [scsi_eh_1]
root 72 2 0 15:05 ? 00:00:00 [scsi_tmf_1]
root 80 2 0 15:05 ? 00:00:00 [bioset]
root 81 2 0 15:05 ? 00:00:00 [bioset]
root 82 2 0 15:05 ? 00:00:00 [bioset]
root 83 2 0 15:05 ? 00:00:00 [bioset]
root 84 2 0 15:05 ? 00:00:03 [kworker/0:2]
root 85 2 0 15:05 ? 00:00:00 [ubi_bgt0d]
root 86 2 0 15:05 ? 00:00:00 [ubifs_bgt0_0]
root 87 2 0 15:05 ? 00:00:00 [scsi_eh_2]
root 88 2 0 15:05 ? 00:00:00 [scsi_tmf_2]
root 89 2 0 15:05 ? 00:00:00 [usb-storage]
root 93 2 0 15:05 ? 00:00:00 [kworker/1:1H]
root 120 2 0 15:05 ? 00:00:00 [kworker/0:1H]
root 121 2 0 15:05 ? 00:00:00 [jbd2/sda1-8]
root 122 2 0 15:05 ? 00:00:00 [ext4-rsv-conver]
root 126 2 0 15:05 ? 00:00:00 [bioset]
root 183 2 0 15:05 ? 00:00:00 [jbd2/sdb1-8]
root 184 2 0 15:05 ? 00:00:00 [ext4-rsv-conver]
root 235 2 0 15:05 ? 00:00:00 [dpcr_integrator]
root 236 2 0 15:05 ? 00:00:00 [graphics3d_work]
root 237 2 0 15:05 ? 00:00:00 [nxsched]
root 238 2 0 15:05 ? 00:00:00 [nxsched]
root 239 2 0 15:05 ? 00:00:00 [nxsched]
root 240 2 0 15:05 ? 00:00:00 [nxsched]
root 241 2 0 15:05 ? 00:00:00 [nxsched]
root 242 2 0 15:05 ? 00:00:00 [nxsched]
root 243 2 0 15:05 ? 00:00:00 [nxsched]
root 244 2 12 15:05 ? 00:08:55 [nxsched]
root 261 2 0 15:05 ? 00:00:00 [pp_work]
root 262 2 0 15:05 ? 00:00:00 [rp_work]
root 332 2 0 15:05 ? 00:00:00 [reboot_work]
root 335 2 0 15:05 ? 00:00:00 [ci_work]
root 339 2 0 15:05 ? 00:00:00 [sci0]
root 341 2 0 15:05 ? 00:00:00 [sci1]
root 343 2 0 15:05 ? 00:00:00 [cec-hdmi_cec]
root 372 2 0 15:05 ? 00:00:00 [bioset]
root 374 2 0 15:05 ? 00:00:00 [xfsalloc]
root 375 2 0 15:05 ? 00:00:00 [xfs_mru_cache]
message+ 552 1 0 15:05 ? 00:00:00 /usr/bin/dbus-daemon --system
root 559 2 0 15:05 ? 00:00:00 [ipv6_addrconf]
root 560 1 0 15:05 ? 00:00:00 /usr/sbin/dropbear -r /etc/dropbear/dropbear_rsa_host_key -p 22 -B
root 598 1 0 15:05 ? 00:00:00 udhcpc -R -b -x hostname et10000 -p /var/run/udhcpc.eth0.pid -i eth0
root 608 1 0 15:05 ? 00:00:00 odhcp6c -Nnone -d -p /var/run/odhcp6c.eth0.pid eth0
root 640 1 0 15:05 ? 00:00:02 automount
root 650 1 0 15:05 ? 00:00:00 /usr/sbin/inetd
root 656 1 0 15:05 ? 00:00:00 /usr/bin/llmnrd -6 -d
root 669 1 0 15:05 ? 00:00:00 /usr/sbin/nmbd
root 676 1 0 15:05 ? 00:00:00 /usr/sbin/wsdd
root 680 1 0 15:05 ? 00:00:00 /sbin/syslogd -n -O /var/log/messages
root 683 1 0 15:05 ? 00:00:00 /sbin/klogd -n
root 686 1 0 15:05 ? 00:00:00 /usr/sbin/telnetd
avahi 693 1 0 15:05 ? 00:00:00 avahi-daemon: running [et10000.local]
avahi 694 693 0 15:05 ? 00:00:00 avahi-daemon: chroot helper
root 698 1 0 15:05 ? 00:00:00 /usr/sbin/vsftpd
root 1432 2 0 15:12 ? 00:00:04 [kworker/u4:1]
root 3204 2 0 15:27 ? 00:00:02 [kworker/1:2]
root 7264 2 0 16:02 ? 00:00:00 [kworker/u4:2]
root 7443 1 6 16:03 ? 00:00:54 /usr/bin/enigma2
root 7454 2 0 16:03 ? 00:00:00 [kdvb-ad-0-fe-0]
root 7492 2 0 16:04 ? 00:00:00 [kdvb-ad-0-fe-2]
root 7558 2 0 16:04 ? 00:00:00 [kworker/0:1]
root 8022 2 0 16:08 ? 00:00:00 [kworker/1:0]
root 9233 686 0 16:15 pts/0 00:00:00 /bin/login
root 9245 9233 0 16:15 pts/0 00:00:00 -sh
root 9679 9245 0 16:18 pts/0 00:00:00 ps -ef
root@et10000:~# killall enigma2
root@et10000:~# killall -9 enigma2
root@et10000:~# init 3
root@et10000:~#

On issuing an init 6 command the box reboots after approx 5 seconds


Attached are 4 debug files
The first two (with the earlier time stamps were when I was experimenting with the location of the epg which was named new_epg.dat and stored on my usb stick - but still with random lock-ups.

The ones with the later time stamps are the ones associated with this post. The one I believe to have been active at the time of the crash appears to be very short and perhaps of not much use. The one with the latest time stamp was after the init 6 reboot.
The very short debug log is the second to last in the list
There are no crash logs.


View attachment log4.zip