Online Upgrade Crash (log attached)

[Joe_90]

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]

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]

V6 log is 29 seconds long, so whatever is causing the slowdown is before enigma starts writing to the log.

[Spoof]

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]

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]

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]

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]

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]

@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]

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-al..._multi.bbclass

[birdman]

@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]

So we just need to explain the 92s counted by the kernel clock

OK. 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]

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]

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]

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.