PDA

View Full Version : [Mut@nt] HD51 Online Upgrade Crash (log attached)



Spoof
08-01-22, 11:08
OK, been having various problems lately, mainly a very slow boot (around 3 minutes). Tried various things, factory reset, upgrade from 5 > 6.
Now getting a lot of crashes, so tried to do an online flash (tried latest V6 and a downgrade to V5) but the box just crashes when I click "flash" (blue button).
Any help appreciated.

Log attached.

Regards,
Spoooo




< 3995.1333> 10:03:13.1299 [InfoBarGenerics] Key: 352 (Make) KeyID='KEY_OK' Binding='('OK',)'.
< 3995.1334> 10:03:13.1300 [ActionMap] Keymap 'OkCancelActions' -> Action = 'ok'.
< 3995.1355> 10:03:13.1321 Traceback (most recent call last):
< 3995.1355> 10:03:13.1322 File "/usr/lib/enigma2/python/Components/ActionMap.py", line 60, in action
< 3995.1361> 10:03:13.1327 res = self.actions[action]()
< 3995.1361> 10:03:13.1328 File "/usr/lib/enigma2/python/Plugins/SystemPlugins/ViX/ImageManager.py", line 403, in keyRestore
< 3995.1368> 10:03:13.1335 imagedict = GetImagelist()
< 3995.1369> 10:03:13.1335 File "/usr/lib/enigma2/python/Tools/Multiboot.py", line 135, in GetImagelist
< 3995.1376> 10:03:13.1343 Creator = BoxInfo.getItem("distro").title()
< 3995.1378> 10:03:13.1344 AttributeError: 'NoneType' object has no attribute 'title'
< 3995.1379> 10:03:13.1345 [ePyObject] (CallObject(<bound method ActionMap.action of <Components.ActionMap.ActionMap object at 0xb0a9c988>>,('OkCancelActions', 'ok')) failed)

twol
08-01-22, 12:59
OK, I need to look at that issue …… will be tomorrow probably

twol
08-01-22, 13:07
So copy the attachment into /usr/lib/enigma2/python/Tools and reboot.
Preferably in putty init 4 (space between)
Copy and then
init 6 (using putty)

Spoof
09-01-22, 11:06
Hi.
Thanks for your swift attention.
I tired the new file but unfortunately, the box still crashes when I click "flash".

Huevos
09-01-22, 12:23
That is the idea. Please post debug/crash log from the crash.

The file posted was not a fix. It was an attempt to get more debug data.

twol
09-01-22, 12:51
Hi.
Thanks for your swift attention.
I tired the new file but unfortunately, the box still crashes when I click "flash".
updated module to hopefully give me some info and allow you to flash. Instructions as before.....

After you have hopefully flashed, I need last 2 debug logs(current and last log from previous image)

Spoof
09-01-22, 15:28
OK, log attached.
The image flashed ok with the new multiboot.py, so no crash log!

Many thanks!

twol
09-01-22, 15:58
OK, log attached.
The image flashed ok with the new multiboot.py, so no crash log!

Many thanks!
Sorry, meant can I have the the current and last debug logs........!!

Also what/whose images did you have in the slots???? .... looks like you had a corrupted file in the flashed image

Spoof
09-01-22, 16:17
I had Vix 6.0.006 in slot 1 and flashed back to 5.4.016 (other slots empty).
I didn't have debug log enabled.

Spoof
10-01-22, 16:46
As a further update, downgrading back to 5.4 cured the slow boot (around 3 minutes in v6) and so far no random crashes either.
Not sure whether this is related to the multiboot.py file.

Huevos
10-01-22, 21:39
As a further update, downgrading back to 5.4 cured the slow boot (around 3 minutes in v6) and so far no random crashes either.
Not sure whether this is related to the multiboot.py file.Never heard of a 3 minute boot on a modern box. You must have something configured wrong.

Spoof
10-01-22, 22:45
Never heard of a 3 minute boot on a modern box. You must have something configured wrong.

It coincided with the upgrade form v5 > v6 (same setting). Now back on 5.4.016 and it boots fine (didn't time it but much less than a minute).
Will retry v6 when I get time and report back.

Joe_90
10-01-22, 23:17
My mutant hd51 boots from cold into displaying channel in 40-ish seconds on a Release 6 Vix image. It's about 5 seconds slower than Release 5. You must be doing something different with the version 6 image. Turn on debug log and reboot.

Spoof
11-01-22, 16:46
Some further testing and enclosed logs.
Log name with image version and boot time.

birdman
11-01-22, 18:35
The v5 one start up enigma2 ~14s after the system boots whereas the v6 one doesn't start it until 106s in.

So the problem is before enigma2 itself starts.

The v6 one also seems to be part of Multiboot, whereas the v5 one isn't.

Joe_90
11-01-22, 18:40
Some further testing and enclosed logs.
Log name with image version and boot time.

Version 6 doesn't seem to start enigma until 106 seconds have elapsed. Any chance of posting the /var/log/messages file to see what's happening earlier in the boot sequence?

Spoof
11-01-22, 19:38
Further info. on v6:

"starting" appears on TV with 5 rows of double dots on front display lasts for 1 minute 52 before the spinning VIX logo appers on the TV an the box completes boot.

Huevos
11-01-22, 21:12
V6 log is 29 seconds long, so whatever is causing the slowdown is before enigma starts writing to the log.

Spoof
13-01-22, 10:02
Version 6 doesn't seem to start enigma until 106 seconds have elapsed. Any chance of posting the /var/log/messages file to see what's happening earlier in the boot sequence?

Log attached.

Joe_90
13-01-22, 11:34
Log attached.

Can you post the corresponding debug log to this messages file? You seem to have an I/O error on your flash, but I've seen that on my mutant and ax61 on occasions and it doesn't seem to affect boot time. In the debug log settings turn on boot time and local time format. Attach debug.log and dmesg and messages.

EDIT
I was actually on 6.0.004 on my mutant HD51 (it doesn't get used very often). I updated to 6.0.006 just now and it boots even faster than .004. Something must be happening during the very initial boot process on your machine which I can't see on the messages file. Maybe dmesg will show the issue. As I posted above, turn on local time and boot time in the debug log format so we can relate messages and debug timestamps.

Spoof
14-01-22, 11:58
Logs attached (don't know why but the dmesg log is time-stamped 12 minutes earlier than the other two, if that helps).


If it's of any use, I did a test - loaded 6.006 and declined the option to restore my settings. I then set up one satellite and scanned one transponder and the boot time was 59.5 seconds.

Joe_90
14-01-22, 13:47
Logs attached (don't know why but the dmesg log is time-stamped 12 minutes earlier than the other two, if that helps).


If it's of any use, I did a test - loaded 6.006 and declined the option to restore my settings. I then set up one satellite and scanned one transponder and the boot time was 59.5 seconds.

Do these logs refer to your test without restoring your settings? They have the same 106 second delay before enigma starts.

If the logs are from a previous test after you have done your settings, then it's presumably something in your settings file that is causing the issue (although I'd expect anything in the settings to show up in the enigma log).

Maybe restore the settings and attach the contents of etc/enigma2/settings - block out any sensitive user/password details etc.

Is it possible that you are running some script prior to enigma start that is doing a backup or trying to access a network resource that is not responding or similar?

birdman
14-01-22, 15:09
Logs attached (don't know why but the dmesg log is time-stamped 12 minutes earlier than the other two, if that helps).The timestamps in the messages file are odd.


Jan 14 10:39:20 mutant51 kern.info kernel: [ 13.660545] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Jan 14 10:39:20 mutant51 cron.info crond[2105]: (CRON) STARTUP (1.5.7)
Jan 14 10:39:20 mutant51 cron.info crond[2105]: (CRON) INFO (Syslog will be used instead of sendmail.)
Jan 14 10:39:20 mutant51 cron.info crond[2105]: (CRON) INFO (RANDOM_DELAY will be scaled with factor 4% if used.)
Jan 14 10:39:20 mutant51 kern.err kernel: [ 105.285293] blk_update_request: I/O error, dev mmcblk0rpmb, sector 0
So the wall clock doesn't doesn't advance between the first and last entry, but the since-boot-time one has advanced by ~92s!?!
That I/O error looks suspicious.

Joe_90
14-01-22, 15:33
@birdman - see my post #20 regarding the I/O error. I get it on my mutant also - it's a 4GB mmc. I've got the error message to go away running fsck in the past, but it seems to return. Doesn't seem to cause any practical issues in my setup, though.
It's all very odd - time lost before enigma starts logging. I can only think something is waiting or delayed during linux boot - disk or network delay?

twol
14-01-22, 16:38
MMC I/O error ------ As far as I remember its the way the mmc is loaded up, think the image is bigger than the slot size (or the other way around - cannot remember too long ago) ... hence the notrunc when its built

https://github.com/oe-alliance/oe-alliance-core/blob/5.0/meta-brands/meta-gfutures/classes/hdemmc_image_multi.bbclass

birdman
14-01-22, 18:46
@birdman - see my post #20 regarding the I/O error. I get it on my mutant also - it's a 4GB mmc. I've got the error message to go away running fsck in the past, but it seems to return.OK. So just an unfortunate position in in the log.

So we just need to explain the 92s counted by the kernel clock (and which seem to be real as the user is reporting a pause) that do not show up on the wall clock, and the wall clock appears to be correct after those missing 92s as ntp runs at 10:39:33 (message log) with only a 0.0008s adjustment needed.

birdman
14-01-22, 18:57
So we just need to explain the 92s counted by the kernel clockOK. I can do that.
The message log isn't actually written at all until those blk_update_request entries arrive. At that point the entire (in memory) kernel log buffer gets dumped into the messages log with the current timestamp.
So the 92s delay does come between the network coming up and those I/O error reports. So what goes on then?

birdman
14-01-22, 19:19
Could you post your /etc/fstab file? (with any passwords removed...)

The S15mountnfs.sh actually seems to run mount -a (== mount everything) so this might contain a network mount that produces a pause(?).

Joe_90
14-01-22, 20:59
I think you're on the right lines as there is definitely something happening in the early start-up stages. As regards the "messages" file, I was always surprised as to the local time timestamps in it as they all seem to be the same. It would make sense if the (in memory) data all got written to the message file at one point with the current timestamp.

birdman
15-01-22, 02:32
It would make sense if the (in memory) data all got written to the message file at one point with the current timestamp.I think syslog does it at start-up.

Spoof
15-01-22, 11:25
Do these logs refer to your test without restoring your settings?




The logs are after I restore the settings.

Spoof
15-01-22, 11:30
Could you post your /etc/fstab file?


/dev/mmcblk0p1 /boot auto defaults 1 1
rootfs / auto defaults 1 1
proc /proc proc defaults 0 0
devpts /dev/pts devpts mode=0620,gid=5 0 0
usbdevfs /proc/bus/usb usbdevfs noauto 0 0
tmpfs /var/volatile tmpfs defaults 0 0
/dev/mmcblk0p10 none swap defaults 0 0

Joe_90
15-01-22, 12:23
The logs are after I restore the settings.

See post #28. Can you post your /etc/enigma2/settings file, please. Remove any user/password info if present.

Spoof
15-01-22, 23:37
Settings attached.

birdman
16-01-22, 00:49
See post #28. Can you post your /etc/enigma2/settings file, please. Remove any user/password info if present.Although we know the issue occurs before enigma2 starts up, so it's unlikely anything in its settings file is causing a problem.

Could you:

take a copy of your /etc/init.d/rc file (to reinstate later)
put the attached file (unzipped) in as /etc/init.d/rc
reboot the box
take a copy of the /tmp/debug-startup.log that is produced and post it here
reinstate the original /etc/init.d/rc file
reboot the box


The log file will give the times at which each start-up file stops running, so should indicate which one is taking up the time.

63217

Note that the rc file is an essential part of the system start-up so if the copy is in some way incorrect your system won't start, so you may wish to do a backup before you put it in place.
I have tested it on my own system.

Spoof
16-01-22, 11:17
take a copy of the /tmp/debug-startup.log that is produced and post it here


1st log is a warm boot log ("Standby & Restart > Reboot")

2nd log is a cold reboot.

I noticed the box seems to boot OK form a warm reboot and the 2nd log suggests (I think!) the wait at boot time is for networking to come up.
For your info., I have a mini router plugged in (powered) by the USB port of the receiver, and this takes abut 90 seconds to boot itself.

Spoof
16-01-22, 12:05
Some further testing (cold boot times):

Networking off - 30 seconds to clear channel.
dhcp enabled - 50 seconds before starting... changes to spinning Vix, 60 seconds to clear channel.
dhcp off (forced IP / my normal settings) 102 seconds before starting... changes to spinning Vix, 114 to clear channel

Huevos
16-01-22, 12:14
Which multiboot slot is the image loaded in? ... and which slot the 5.4 image?

Spoof
16-01-22, 12:20
I never set up multiboot, but when I flash from the image manager, I only ever use slot 1.

Huevos
16-01-22, 12:33
Can you completely disconnect it from the network. Remove the router so there is no WiFi. Then see if it boots.

birdman
16-01-22, 13:00
I noticed the box seems to boot OK form a warm reboot and the 2nd log suggests (I think!) the wait at boot time is for networking to come up.
Yes, it's starting the network that adds the delay.


For your info., I have a mini router plugged in (powered) by the USB port of the receiver, and this takes abut 90 seconds to boot itself.Which I would expect to be the cause of the problem.
Except that you say the problem only occurs with Vix v6, not v5.4

Spoof
16-01-22, 13:03
Except that you say the problem only occurs with Vix v6, not v5.4

That is correct, 5.4 boots fine / quickly.

Spoof
16-01-22, 13:06
Can you completely disconnect it from the network. Remove the router so there is no WiFi. Then see if it boots.

To clarify, this is a LAN (wired) connection, not WiFi.
I already tried with networking off and the box boots perfectly / quickly (post 37)

I will try later with WiFi instead of LAN and see what happens.

Joe_90
16-01-22, 13:31
Why do you have a USB powered mini-router attached? Your LAN cable would/should be connected to the RJ45 port on the mutant.

Spoof
16-01-22, 13:41
Why do you have a USB powered mini-router attached? Your LAN cable would/should be connected to the RJ45 port on the mutant.

Router is connected to the receiver by ethernet cable and provides mobile broadband.
The USB part is for power only and is much more convenient than finding another 240v socket for a power adapter.

Joe_90
16-01-22, 13:49
So, the router is connected to mobile broadband? Because it's active, the box is probably trying to establish an internet connection. Doesn't explain why it comes up quicker in V5. Must be some difference in the networking stack in V6. @huevos and @birdman will find it, no doubt;)

birdman
16-01-22, 17:40
So, the router is connected to mobile broadband? Because it's active, the box is probably trying to establish an internet connection. Doesn't explain why it comes up quicker in V5. Must be some difference in the networking stack in V6. @huevos and @birdman will find it, no doubt;)Enigma2 hasn't started at this point, so v5/v6 won't make any difference.
We're still starting the underlying Linux system, and that's unlikely to have changed (much?).

Joe_90
16-01-22, 18:18
Yes - it's a puzzle, but the OP says he has no boot issues in V5:confused: