Web page - Is this something to worry about?

Today I just got up and when I tried to load the page I see this:

Error: EIO: i/o error, stat '/usr/lib/node_modules/node-red/node_modules/@node-red/editor-client/public/ui/index.html'

There is more to come - an error log - but it is huge from what I see.

The log:

First entry is pointing to the vcgen node. undefined....

===================
When 2021-01-06 02:48:28
Who ERROR_REPORT/BedPi/Main Telemetry/undefined
Where e615a8e.9bc6358
What Error: spawn EIO
===================

The where points to the vcgen node.

The next error pointed to the exec node.

The third pointed to the ping node. (the node-red one)

Then it goes back to the vcgen, and other ping nodes.

Oh, and ALL of the errors were: spawn EIO.
Has Old McDonald been around?
(Sorry)
:wink:

If that really just started happening without you doing anything then it could be a corrupt SD card.
Have you run out of space on the card?
Have you tried a reboot?
Is it just node-red that is showing errors? Look in /var/log/syslog.

Thanks.

AFAIK, all is good. Yes, it did just start happening, but after rebooting all is happy.

This is similar to another recent problem with the advanced ping node where one day it all just went south.

This is the log around the time it happened:

Jan  6 02:41:51 BedPi systemd[600]: Starting Virtual filesystem service - digital camera monitor...
Jan  6 02:41:51 BedPi dbus-daemon[661]: Successfully activated service 'org.gtk.vfs.GPhoto2VolumeMonitor'
Jan  6 02:41:51 BedPi systemd[600]: Started Virtual filesystem service - digital camera monitor.
Jan  6 02:41:51 BedPi dbus-daemon[661]: Activating via systemd: service name='org.gtk.vfs.AfcVolumeMonitor' unit='gvfs-afc-volume-monitor.service'
Jan  6 02:41:51 BedPi systemd[600]: Starting Virtual filesystem service - Apple File Conduit monitor...
Jan  6 02:41:51 BedPi gvfs-afc-volume-monitor[820]: Volume monitor alive
Jan  6 02:41:51 BedPi dbus-daemon[661]: Successfully activated service 'org.gtk.vfs.AfcVolumeMonitor'
Jan  6 02:41:51 BedPi systemd[600]: Started Virtual filesystem service - Apple File Conduit monitor.
Jan  6 02:41:51 BedPi Node-RED[315]: 6 Jan 02:41:51 - [info]
Jan  6 02:41:51 BedPi Node-RED[315]: Welcome to Node-RED
Jan  6 02:41:51 BedPi Node-RED[315]: ===================
Jan  6 02:41:51 BedPi Node-RED[315]: 6 Jan 02:41:51 - [info] Node-RED version: v1.2.6
Jan  6 02:41:51 BedPi Node-RED[315]: 6 Jan 02:41:51 - [info] Node.js  version: v8.17.0
Jan  6 02:41:51 BedPi Node-RED[315]: 6 Jan 02:41:51 - [info] Linux 4.19.66-v7+ arm LE
Jan  6 06:52:32 BedPi systemd[600]: Time has been changed
Jan  6 06:52:32 BedPi systemd[1]: Time has been changed
Jan  6 06:52:32 BedPi systemd-timesyncd[276]: Synchronized to time server 178.63.9.212:123 (2.debian.pool.ntp.org).
Jan  6 06:52:32 BedPi systemd[551]: Time has been changed
Jan  6 06:52:32 BedPi systemd[1]: apt-daily-upgrade.timer: Adding 25min 18.710335s random time.
Jan  6 06:52:32 BedPi systemd[1]: apt-daily.timer: Adding 11h 15min 16.770201s random time.
Jan  6 06:52:32 BedPi systemd[1]: certbot.timer: Adding 6h 43min 6.279883s random time.
Jan  6 06:52:32 BedPi systemd[1]: Starting Clean php session files...
Jan  6 06:52:32 BedPi systemd[1]: Starting Daily apt upgrade and clean activities...
Jan  6 06:52:39 BedPi kernel: [   48.983874] FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
Jan  6 06:52:39 BedPi udisksd[782]: Mounted /dev/sda1 at /media/pi/06BB-C87D on behalf of uid 1000
Jan  6 06:52:43 BedPi systemd[1]: Started Clean php session files.
Jan  6 06:52:46 BedPi Node-RED[315]: 6 Jan 06:52:46 - [info] Loading palette nodes
Jan  6 06:52:47 BedPi systemd[1]: Started Daily apt upgrade and clean activities.
Jan  6 06:52:47 BedPi systemd[1]: apt-daily-upgrade.timer: Adding 45min 716.355ms random time.

All good at 02:00 then at 06:52 (probably after the reboot) all is good. So nothing really pointing to anything that I can see.

The pi crashed or there was a power failure. The 02:00 times are not correct, they are from before the time was synchronised. Note how the time in the log suddenly changes to 06:52 and there is a Time Synchronised message. I don't know whether the not properly mounted message only appears once after the crash or power fail. Reboot and see if it is still there. If it is then you need to run fsck to tidy the card up, and that may find some additional errors.

Yeah, but if this is an error log and something happened at 02:00.... Ok.... Then all was sweet until 06:xx.... When it all went yuck.

I got up at about 06:30 and attended the problem (power cycle alas) at about 06:52 when the log started again.

Best of my knowledge the time on the PI is correct.
Now: Time 09:04. RasPi showing "uptime" of 2:12. That means I did the power cycle at .... 7, 6: (4-12%60)
6:52

Which lines up with the log.

There is an external USB plugged in for writing logs, to reduce SD wear and tear.
But thanks for the head's up.

Um, I can't sudo fsck as there is only one partition on the SD card and it is kinda busy just now. :wink:

Shall command reboot and see what happens.

Ok, this is near the end of the log file:

Jan  6 09:10:38 BedPi Node-RED[282]: 6 Jan 09:10:38 - [info]
Jan  6 09:10:38 BedPi Node-RED[282]: Welcome to Node-RED
Jan  6 09:10:38 BedPi Node-RED[282]: ===================
Jan  6 09:10:38 BedPi Node-RED[282]: 6 Jan 09:10:38 - [info] Node-RED version: v1.2.6
Jan  6 09:10:38 BedPi Node-RED[282]: 6 Jan 09:10:38 - [info] Node.js  version: v8.17.0
Jan  6 09:10:38 BedPi Node-RED[282]: 6 Jan 09:10:38 - [info] Linux 4.19.66-v7+ arm LE
Jan  6 09:10:39 BedPi kernel: [   60.156239] FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
Jan  6 09:10:39 BedPi udisksd[798]: Mounted /dev/sda1 at /media/pi/06BB-C87D on behalf of uid 1000
Jan  6 09:10:42 BedPi Node-RED[282]: 6 Jan 09:10:42 - [info] Loading palette nodes
Jan  6 09:10:54 BedPi kernel: [   75.092328] random: crng init done
Jan  6 09:10:54 BedPi kernel: [   75.092349] random: 7 urandom warning(s) missed due to ratelimiting
Jan  6 09:10:54 BedPi vncserver-x11[403,root]: ServerManager: Server started
Jan  6 09:10:55 BedPi vncserver-x11[403,root]: ConsoleDisplay: Found running X server (pid=525, binary=/usr/lib/xorg/Xorg)
Jan  6 09:11:12 BedPi systemd[1]: dev-serial1.device: Job dev-serial1.device/start timed out.
Jan  6 09:11:12 BedPi systemd[1]: Timed out waiting for device dev-serial1.device.
Jan  6 09:11:12 BedPi systemd[1]: Dependency failed for Configure Bluetooth Modems connected by UART.
Jan  6 09:11:12 BedPi systemd[1]: hciuart.service: Job hciuart.service/start failed with result 'dependency'.
Jan  6 09:11:12 BedPi systemd[1]: dev-serial1.device: Job dev-serial1.device/start failed with result 'timeout'.
Jan  6 09:11:12 BedPi systemd[1]: Reached target Multi-User System.

Drats. Seems I may have to do something with the SD card.

But as it is the boot partition, how do I do the fsck?
I have to unmount it and run it. Kinda difficult if it is the boot partition.

Power down and plug into another machine?

if you create a file in the root of the drive called forcefsck - it should do it when it reboots...
sudo touch /forcefsck should do it

1 Like

So I just make a/the file forcefsck and put that in it.

Great.

I hope it survives. :wink:

Oh.... Quickie: I think the SD card has 2 partitions: boot and .... what ever the other one is called.

So it is in/on the other one - yes?
ie: NOT the boot partition.

update

All seems good now.

Not necessarily. You cannot necessarily apply meaning to the 02:00 timestamps as that is from before the time synced so the pi didn't know what time it was. You would have to look back in the log for the time before the start of that reboot to see what time it crashed. It might have stopped at 02:00 or it might not.

You are going to have to explain that to me as it seems you know something I don't.

The machine IS connected to the internet and the time should have been ok.

The time is not ok until the pi has fetched it from the internet and set the clock, you can see that in the log where the first of the 06:00 timestamps is. From the point of reboot to when it syncs the time it does not have the correct time, how could it?

The file (part) which I posted is a log of errors. NOT real time.

So if the poo hits the fan at 02:xx the logs will be time stamped at 02:xx.

The machine locks up. Nothing else happens.
(Oh, well ok: it has logged the errors before it locks up and calls out to the other machines telling them of the error/s)

I get up at 06:20 and see the notification.
I try to SSH to it: can't.
Try VNC: can't.

All I can do is power cycle it - at 06:10 (Or there abouts)
You can see Node-Red starting up.

The time is correct.

Yes, I get it that IF the clock was wrong at 02:xx (or when ever the error happened) I will see the wrong time stamp.

But in reality: it is in the past and it really doesn't matter other than: it is saying it happened at 02:xx.

The errors are exactly the same as the ones I got on 20 Dec @ 14:05 and posted a question on them then.

I was told that using a foreign node - advanced ping was the problem and to use the standard ping node.

I can't say that doing that fixed the problem, but that day the same error happened and I was just wanting to find out if there was anything to worry about.

So I am still not seeing / understanding how you are saying "the time is wrong".

This is the life of the machine for the past week - or so:

pi@BedPi:/media/pi/06BB-C87D/logs/reboot $ cat 2021-01/Reboot*
2020-12-31 06:36:40
up 1 week, 3 days, 10 hours, 16 minutes

2020-12-31 08:19:03
up 1 hour, 42 minutes

pi@BedPi:/media/pi/06BB-C87D/logs/reboot $ cat Reb*
2021-01-06 06:48:53
up 5 days, 20 hours, 11 minutes

2021-01-06 09:09:17
up 2 hours, 17 minutes

2021-01-06 09:21:26
up 11 minutes

pi@BedPi:/media/pi/06BB-C87D/logs/reboot $ cat last_alive.db 
2021-01-07 07:22:35
up 21 hours, 59 minutes

pi@BedPi:/media/pi/06BB-C87D/logs/reboot $ 

It has been alive for 1 week, 3 days 10 hours and 16 minutes.
Something happened. (Probably rebooted) I can get that if you want.

New years eve: 08:19:03 something happened after 1 hour 42 minutes.

Jan 6: 06:48:53 again something happened after 5 days, 20 hours and 11 minutes.

And so on.
Here are the commands that were sent to it. Though not definitive.

2020-12-02 15:02:32  >>  Backup  <<
2020-12-20 14:08:10  >>  Reboot  <<
2020-12-20 16:22:18  >>  Backup  <<
2020-12-21 12:19:01  >>  Backup  <<
2020-12-22 19:08:21  >>  Backup  <<
2020-12-26 13:54:08  >>  Backup  <<
2020-12-26 17:54:59  >>  Backup  <<
2020-12-27 12:25:12  >>  Backup  <<
2020-12-28 22:11:16  >>  Backup  <<
2020-12-29 10:58:43  >>  Backup  <<
2020-12-29 17:23:54  >>  Backup  <<
2020-12-29 19:57:30  >>  Backup  <<
2020-12-31 06:55:26  >>  Backup  <<
2021-01-03 18:51:20  >>  Backup  <<
2021-01-05 17:36:20  >>  Backup  <<
2021-01-06 06:49:09  >>  Reboot  <<
2021-01-06 07:33:26  >>  Backup  <<
2021-01-06 09:09:21  >>  Reboot  <<
2021-01-06 09:21:24  >>  Reboot  <<

Can you (again) explain how your theory of it not knowing what time it was when the crash/errors happened works?

Do you mean that this, posted above, was not an direct extract from syslog?

Jan  6 02:41:51 BedPi Node-RED[315]: Welcome to Node-RED
Jan  6 02:41:51 BedPi Node-RED[315]: ===================
Jan  6 02:41:51 BedPi Node-RED[315]: 6 Jan 02:41:51 - [info] Node-RED version: v1.2.6
Jan  6 02:41:51 BedPi Node-RED[315]: 6 Jan 02:41:51 - [info] Node.js  version: v8.17.0
Jan  6 02:41:51 BedPi Node-RED[315]: 6 Jan 02:41:51 - [info] Linux 4.19.66-v7+ arm LE
Jan  6 06:52:32 BedPi systemd[600]: Time has been changed
Jan  6 06:52:32 BedPi systemd[1]: Time has been changed
Jan  6 06:52:32 BedPi systemd-timesyncd[276]: Synchronized to time server 178.63.9.212:123 (2.debian.pool.ntp.org).
Jan  6 06:52:32 BedPi systemd[551]: Time has been changed
Jan  6 06:52:32 BedPi systemd[1]: apt-daily-upgrade.timer: Adding 25min 18.710335s random time.
Jan  6 06:52:32 BedPi systemd[1]: apt-daily.timer: Adding 11h 15min 16.770201s random time.
Jan  6 06:52:32 BedPi systemd[1]: certbot.timer: Adding 6h 43min 6.279883s random time.
Jan  6 06:52:32 BedPi systemd[1]: Starting Clean php session files...
Jan  6 06:52:32 BedPi systemd[1]: Starting Daily apt upgrade and clean activities...
Jan  6 06:52:39 BedPi kernel: [   48.983874] FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

Not that when the time jumps from 02:nn to 06:nn it says that the time has been changed due to a time synchronisation.
Also note the last line, [ 48.983874] means that this is 48 seconds after the start of reboot.

Yes, it was a direct copy from the syslog.

Yes, it says "time has been changed". I get that.

So help me understand what happened.

I have had a lot of fun with machines which are not connected to the net and their times resume to the previous last known when booted up subsequently.

So (say) it is synced and it is .... 12:00:00

I power it down and 3 hours later I power it up. After the initial messing around, it says it is 12:00:00 (give or take) as per when it was shut down.

So:

It is .... 02:00. The $hit hits the fan.

(Hang on.)
Here is one extract from my error log:


===================
When 2020-12-31 06:36:40
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/real world control/undefined
Where 286d9c48.9ce52c
What Error: spawn EIO
===================

===================
When 2020-12-31 06:36:40
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/Machine_Health/undefined
Where 8d97fb44.084ed8
What Error: spawn EIO
===================

===================
When 2020-12-31 06:36:40
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/UPLINK monitor/undefined
Where 174717e5.1ffe3
What Error: spawn EIO
===================

===================
When 2021-01-03 18:27:41
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/real world control/GATE1
Where 1297a10a.392d2f
What ReferenceError: msg1 is not defined (line 6, col 5)
===================

===================
When 2021-01-03 18:27:45
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/real world control/
Where 1297a10a.392d2f
What ReferenceError: msg1 is not defined (line 14, col 5)
===================

===================
When 2021-01-03 18:30:41
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/real world control/GATE1
Where 1297a10a.392d2f
What ReferenceError: msg1 is not defined (line 6, col 5)
===================

===================
When 2021-01-03 18:30:46
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/real world control/
Where 1297a10a.392d2f
What ReferenceError: msg1 is not defined (line 14, col 5)
===================

===================
When 2021-01-03 18:34:01
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/real world control/GATE1
Where 1297a10a.392d2f
What ReferenceError: msg1 is not defined (line 6, col 5)
===================

New Year's eve. (So even after the original detection of this problem on 20 Dec)
You see the errors happening.

Towards the bottom/end you see a couple of test injections.

When 2021-01-03 18:30:46
Who ERROR_REPORT/BedPi/ERROR_REPORT/BedPi/real world control/
Where 1297a10a.392d2f
What ReferenceError: msg1 is not defined (line 14, col 5)

That is my error detection test injection.

So it is working.

That is line 49500 of (quite a lot more)

Then the next entry is:

===================
When 2021-01-06 02:48:28
Who ERROR_REPORT/BedPi/Main Telemetry/undefined
Where e615a8e.9bc6358
What Error: spawn EIO
===================

6 Jan 2021 02:48:28

That goes on for......

29216 more lines.
Given each report is 6 lines. Call it 7. That is 4173 more times. (There about)

With times slowly increasing.

But this is the last one logged:

===================
When 2021-01-06 06:49:14
Who ERROR_REPORT/BedPi/Main Telemetry/DO_THIS
Where 8e519742.daa74
What Error: spawn EIO
===================

Which is, yes confusing, given the times shown in the log I posted.

So: What ever time the machine thinks it is.... 02:xx.
I unplug it, plug it back in and it "boots".
Originally it will have what ever time it last knew and then when connected it will sync.
Which is probably what you are showing me in the log extract.

But what ever that is: I can see the .... 4173 (odd) entries of the error which started at about 02:00 on 6 Jan.

My question is more about should I be worried about this - also given on 20 Dec' when I had the problem and (supposedly) fixed it - it is back with vengeance.
And that it also happened New Year's eve.

Exactly when it happened is a bit academic as it is in the past and I can only go on the times I am given.
Again: Not really important, but are included because I have them.

The last line:
Yeah, that is probably when I got it rebooted the first time.