emonSDexpand on 30Oct18 Raspbian Stretch Image

I’ve just tested using emonSDexpand and it worked fine on the new image, this error should just be ignored. Its interesting emonDexpand did not work for you. It will take about 30-40min then require a reboot.

Does mariadb eventually start correctly? Did you try and loadup Emoncms? I think that error is just due to mariadb starting up before the logfiles have been created in tmpfs /var/log, this is nothing to worry about since the service should then restart and run correctly after log files have been created.

The permission denied error for /home/pi/data/emonpiupdate.log is strange, I’ll take another look but I’ve not seen this happen on the new image before. Have you any idea how emonpiupdate.log has changed permissions?

Update: just double checked, and I’ve been unable to replicate the permissions issue emonpiupdate.log should be owned by user pi:pi

pi@emonpi:~ $ ls -la data/emonpiupdate.log 
-rw-rw-rw- 1 pi pi 13206 Nov 13 15:07 data/emonpiupdate.log

You can fix this by:

sudo chown pi:pi /home/pi/data/emonpiupdate.log

It would be interesting to try and figure out why the permissions changed, could this have happened during the expansion process? Here are the default permissions for the ~/data

pi@emonpi:~/data $ ls -la
total 48
drwxrwxrwx  9 pi       pi        1024 Nov 13 15:12 .
drwxr-xr-x 20 pi       pi        4096 Oct 31 00:59 ..
drwxrwxrwx  3 root     root      1024 Oct 31 01:01 @eaDir
-rw-rw-r--  1 pi       www-data     0 Oct 31 00:59 emoncms.conf
-rw-r--r--  1 pi       pi        1718 Nov 13 15:12 emoncms-wifiscan.log
-rw-rw-rw-  1 pi       www-data  7463 Oct 31 00:59 emonhub.conf
-rw-rw-rw-  1 pi       pi       13206 Nov 13 15:07 emonpiupdate.log
drwx------  2 pi       pi       12288 Aug 16 15:29 lost+found
drwxrwxrwx  5 mysql    mysql     1024 Nov 13 15:08 mysql
drwxr-xr-x  2 www-data root      1024 Oct 31 00:59 phpfina
drwxr-xr-x  2 www-data root      1024 Oct 31 00:59 phptimeseries
drwxrwxrwt  2 root     root      1024 Oct 18 17:33 @tmp
drwxr-xr-x  2 www-data root      1024 Oct 22 01:02 uploads
-rw-r--r--  1 root     root       137 Nov 13 15:20 wificheck.log

To anyone else following this thread, we sell ready expanded 16GB cards pre-loaded SD cards with the new image via our store:

https://openenergymonitor.com/emonsd-pre-loaded-raspberry-pi-sd-card/

I had a similar issue a while ago and raised this issue - Log file permissions and ownership · Issue #806 · emoncms/emoncms · GitHub I thought the issue might be logrotate but could not prove it.

@icenov could you do a ls -la on the log file directory and the parent directory please.

The issue your referred to is a separate issue. emoncms.log is handled via a different service and logrotate does not take effect to directories outside of /var/log

1 Like

Thanks for quick reply - it is now mostly up, after a couple of hangups and reboots. Permissions look correct:

drwxr-xr-x 13 root      root        580 Nov 14 10:56 .
drwxr-xr-x 12 root      root       4096 Aug  2 20:53 ..
drwxr-xr-x  2 root      adm         100 Nov 14 10:06 apache2
drwxr-xr-x  2 root      root        100 Nov 14 10:56 apt
-rw-r-----  1 root      adm       10782 Nov 14 11:00 auth.log
-rw-r--r--  1 root      root       6039 Nov 14 10:06 boot.log
-rw-------  1 root      utmp          0 Nov 14 10:06 btmp
-rw-r-----  1 root      adm       33060 Nov 14 10:57 daemon.log
-rw-r-----  1 root      adm        1177 Nov 14 10:06 debug
-rw-r--r--  1 root      root       3123 Nov 14 10:56 dpkg.log
-rw-rw-rw-  1 root      root        372 Nov 14 10:06 emoncms.log
drwxr-xr-x  2 emonhub   root         60 Nov 14 10:06 emonhub
drwxr-xr-x  2 pi        root         60 Nov 14 10:06 emonpilcd
-rw-r-----  1 root      adm       32534 Nov 14 11:00 kern.log
drwxr-xr-x  2 pi        pi           40 Nov 14 10:06 logrotate
-rw-r-----  1 root      adm       28204 Nov 14 11:00 messages
drwxr-xr-x  2 mosquitto mosquitto    60 Nov 14 10:06 mosquitto
-rw-rw-rw-  1 root      root          0 Nov 14 10:06 mqtt_input.log
drwxr-xr-x  2 mysql     adm          60 Nov 14 10:06 mysql
-rw-rw-rw-  1 root      root          0 Nov 14 10:06 mysql.log
drwxr-xr-x  2 ntp       ntp          40 Feb 15  2018 ntpstats
-rw-rw-rw-  1 root      root          0 Nov 14 10:06 ntp_update.log
drwxr-xr-x  2 root      root         40 Nov 14 10:06 openhab
drwxr-xr-x  2 redis     redis        60 Nov 14 10:06 redis
-rw-rw-rw-  1 root      root          0 Nov 14 10:06 service-runner.log
drwxr-xr-x  2 root      root         60 Nov 14 10:06 supervisor
-rw-r-----  1 root      adm       67782 Nov 14 11:00 syslog
-rw-r-----  1 root      adm         190 Nov 14 10:06 user.log
-rw-rw-r--  1 root      utmp       1920 Nov 14 10:47 wtmp

and parent directory:

drwxr-xr-x 12 root root       4096 Aug  2 20:53 .
drwxrwxrwx 24 root root       4096 Oct 19 04:33 ..
drwxr-xr-x  2 root root       4096 Nov 13 17:25 backups
drwxr-xr-x 10 root root       4096 Aug  8 03:38 cache
drwxr-xr-x 38 root root       4096 Aug 18 01:30 lib
drwxrwsr-x  2 root staff      4096 Mar 13  2018 local
lrwxrwxrwx  1 root root          9 Jun 27 10:03 lock -> /run/lock
drwxr-xr-x 13 root root        580 Nov 14 10:56 log
drwxrwsr-x  2 root mail       4096 Jun 27 10:03 mail
drwxr-xr-x  2 root root       4096 Jun 27 10:03 opt
lrwxrwxrwx  1 root root          4 Jun 27 10:03 run -> /run
drwxr-xr-x  4 root root       4096 Jun 27 10:11 spool
-rw-------  1 root root  104857600 Jun 27 11:09 swap
drwxrwxrwt  5 root root        100 Nov 14 11:09 tmp
drwxr-xr-x  4 pi   root       4096 Aug 15 22:05 www

Yes, DB is now up - so maybe this was the issue.
A couple of other observations for others if they have problems:
looks like ntp service is not installed so local (Australia) time wasn’t recognised. apt-get install ntp and tzone adjust has worked.
Worth adding ssh.txt file into boot directory as ssh is so much more convenient (IMHO) to check logs and updates etc - especially if the emon unit is in an awkward spot!
Import of backup data has mostly worked (sigh of relief!) but a couple of nodes have not come back to life. I’m working on those now.
A very nice update - thanks to all involved.

It look like i ran out of disk space, so i have expanded the storage on the SD card
pi@emonpi:~ $ df -h --total
Filesystem Size Used Avail Use% Mounted on
/dev/root 3.9G 1.7G 2.1G 45% /
devtmpfs 484M 0 484M 0% /dev
tmpfs 489M 0 489M 0% /dev/shm
tmpfs 489M 13M 476M 3% /run
tmpfs 5.0M 4.0K 5.0M 1% /run/lock
tmpfs 489M 0 489M 0% /sys/fs/cgroup
tmpfs 1.0M 0 1.0M 0% /var/tmp
tmpfs 30M 0 30M 0% /tmp
tmpfs 50M 1.5M 49M 3% /var/log
/dev/mmcblk0p1 43M 22M 21M 52% /boot
/dev/mmcblk0p3 11G 3.1G 6.8G 32% /home/pi/data
tmpfs 98M 0 98M 0% /run/user/1000
total 17G 4.7G 11G 31% -

Here is some more information. its looks like the SQL wont start.

journalctl -xe
Nov 19 08:31:36 emonpi sudo[5602]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/systemctl status mysql.service
Nov 19 08:31:36 emonpi sudo[5602]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Nov 19 08:32:14 emonpi systemd[1]: mqtt_input.service: Service hold-off time over, scheduling restart.
Nov 19 08:32:14 emonpi systemd[1]: Stopped Emoncms MQTT Input Script.
-- Subject: Unit mqtt_input.service has finished shutting down
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Unit mqtt_input.service has finished shutting down.
Nov 19 08:32:14 emonpi systemd[1]: Started Emoncms MQTT Input Script.
-- Subject: Unit mqtt_input.service has finished start-up
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Unit mqtt_input.service has finished starting up.
--
-- The start-up result is done.
Nov 19 08:32:14 emonpi mqtt_input[10844]: PHP Fatal error:  Uncaught ErrorException: mysqli::__construct(): (HY000/2002): Connection refused in /var/www/emoncms/scripts/phpmqtt_input.php:61
Nov 19 08:32:14 emonpi mqtt_input[10844]: Stack trace:
Nov 19 08:32:14 emonpi mqtt_input[10844]: #0 [internal function]: exceptions_error_handler(2, 'mysqli::__const...', '/var/www/emoncm...', 61, Array)
Nov 19 08:32:14 emonpi mqtt_input[10844]: #1 /var/www/emoncms/scripts/phpmqtt_input.php(61): mysqli->__construct('127.0.0.1', 'emoncms', 'emonpiemoncmsmy...', 'emoncms', '3306')
Nov 19 08:32:14 emonpi mqtt_input[10844]: #2 {main}
Nov 19 08:32:14 emonpi mqtt_input[10844]:   thrown in /var/www/emoncms/scripts/phpmqtt_input.php on line 61
Nov 19 08:32:14 emonpi mqtt_input[10844]: Fatal error: Uncaught ErrorException: mysqli::__construct(): (HY000/2002): Connection refused in /var/www/emoncms/scripts/phpmqtt_input.php:61
Nov 19 08:32:14 emonpi mqtt_input[10844]: Stack trace:
Nov 19 08:32:14 emonpi mqtt_input[10844]: #0 [internal function]: exceptions_error_handler(2, 'mysqli::__const...', '/var/www/emoncm...', 61, Array)
Nov 19 08:32:14 emonpi mqtt_input[10844]: #1 /var/www/emoncms/scripts/phpmqtt_input.php(61): mysqli->__construct('127.0.0.1', 'emoncms', 'emonpiemoncmsmy...', 'emoncms', '3306')
Nov 19 08:32:14 emonpi mqtt_input[10844]: #2 {main}
Nov 19 08:32:14 emonpi mqtt_input[10844]:   thrown in /var/www/emoncms/scripts/phpmqtt_input.php on line 61
Nov 19 08:32:14 emonpi systemd[1]: mqtt_input.service: Main process exited, code=exited, status=255/n/a
Nov 19 08:32:14 emonpi systemd[1]: mqtt_input.service: Unit entered failed state.
Nov 19 08:32:14 emonpi systemd[1]: mqtt_input.service: Failed with result 'exit-code'.
Nov 19 08:32:20 emonpi sudo[5602]: pam_unix(sudo:session): session closed for user root
Nov 19 08:32:26 emonpi sudo[12497]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/systemctl start mysql.service
Nov 19 08:32:26 emonpi sudo[12497]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Nov 19 08:32:26 emonpi systemd[1]: Starting MariaDB database server...
-- Subject: Unit mariadb.service has begun start-up
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Unit mariadb.service has begun starting up.
Nov 19 08:32:27 emonpi mysqld[12803]: 2018-11-19  8:32:27 1988702208 [Note] /usr/sbin/mysqld (mysqld 10.1.23-MariaDB-9+deb9u1) starting as process 12803 ...
Nov 19 08:32:30 emonpi systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
Nov 19 08:32:30 emonpi systemd[1]: Failed to start MariaDB database server.
-- Subject: Unit mariadb.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Unit mariadb.service has failed.
--
-- The result is failed.
Nov 19 08:32:30 emonpi systemd[1]: mariadb.service: Unit entered failed state.
Nov 19 08:32:30 emonpi systemd[1]: mariadb.service: Failed with result 'exit-code'.
Nov 19 08:32:30 emonpi sudo[12497]: pam_unix(sudo:session): session closed for user root

and from the status of sql

pi@emonpi:~ $ sudo systemctl status mysql.service
● mariadb.service - MariaDB database server
   Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Mon 2018-11-19 08:32:30 UTC; 5min ago
  Process: 12803 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=1/FAILURE)
  Process: 12628 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`/usr/bin/galera_recovery`; [ $? -eq 0 ]   && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=e
  Process: 12573 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
  Process: 12511 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
 Main PID: 12803 (code=exited, status=1/FAILURE)
   Status: "MariaDB server is down"

Nov 19 08:32:26 emonpi systemd[1]: Starting MariaDB database server...
Nov 19 08:32:27 emonpi mysqld[12803]: 2018-11-19  8:32:27 1988702208 [Note] /usr/sbin/mysqld (mysqld 10.1.23-MariaDB-9+deb9u1) starting as process 12803 ...
Nov 19 08:32:30 emonpi systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
Nov 19 08:32:30 emonpi systemd[1]: Failed to start MariaDB database server.
Nov 19 08:32:30 emonpi systemd[1]: mariadb.service: Unit entered failed state.
Nov 19 08:32:30 emonpi systemd[1]: mariadb.service: Failed with result 'exit-code'.

Any Ideas?

Is this a new or old SD Card? I wonder if the card is close to failure or if new, a fake card?

I suggest trying with a new card if this is a recycled one or test if it is fake (search Google to find out how to check)…

Hi @borpin

its not a fake card and is in good condition.

I did not expand the card when i first installed it and it looks like it ran out of space so i ran sudo emonSDexpand

Paul

My feeling is something got corrupted when it ran out of space. I’d be inclined to start from scratch, expand before anything else and see what happens.

I think you are right.

I think the SD card became full and thus damaged the SQL database.

I got another SD card and kept getting errors on start up,


So got a new card and it wrote ok, expanded ok and then restored the backup.

1 Like

Hi can I buy a new pre loaded SDcard with 30Oct18. If I can are there instructions then on how to copy data across and to insert it into the Pi.

Regards
John

I seem to be having an issue with expanding the sd card after flashing it with this new version. on running emonSDexpand I eventually get the following screens:

It works fine if I don’t run emonSDexpand, but once I do the card appears to be unreadable, ctrl-D doesn’t do anything

Did you want about 30min for the emonSDexpand process to expand the file-system? Did the Pi power off when it was finished?

Sure, we all pre-loaded SD card with the latest image via our online store:

https://openenergymonitor.com/emonsd-pre-loaded-raspberry-pi-sd-card/

Follow instructions here for how to use the backup Module to backup and move you data to the new image:

https://guide.openenergymonitor.org/setup/import/

Thanks for your quick reply Glyn.

Nope, didn’t power off the Pi manually at all.

I ran the emonSDexpand command, then almost immediately the first 2 images showed up on an HDMI attached monitor, then it rebooted itself after around 30 seconds, and on boot the final image was shown (after about 30 seconds of other things saying ok) and nothing happened from that point.

After it reboots you need to leave it for 20-30min to apply the changes. You might not see any process running on the display when this happens. I’ve never actually run emonSDexpand with a hdmi monitor connected, I usually work with the emonPi headless. emonSDexpand worked when I used it last week.

What SD card are you using? Maybe it cannot handle the expansion process?

If your still having trouble we sell a pre-loaded and pre-expanded 16GB emonSD card via our online store:

https://openenergymonitor.com/emonsd-pre-loaded-raspberry-pi-sd-card/

I have the same issue with emonSDexpand. After rebooting, it cannot mount /home/pi/data

I’ve had a bit of a look at the script, and I think the problem is with the way the script handles /etc/fstab. The script contains:

# Ensure that the /data partition is unmounted after a reboot
sed -i 's/\/dev\/mmcblk0p3/#\/dev\/mmcblk0p3/' /etc/fstab

However, /etc/fstab uses PARTUUID to identify the partitions:

proc                  /proc           proc    defaults          0       0
PARTUUID=50c2568e-01  /boot           vfat    defaults          0       2
PARTUUID=50c2568e-02  /               ext4    defaults,noatime,nodiratime  0       1
PARTUUID=50c2568e-03  /home/pi/data   ext2    defaults,noatime,nodiratime  0       2

I’ve modified sdpart_imagefile and it now works for me. I’ve created a pull request for the change:

1 Like

That’s great, good spot. I’ve just tested and merged. Thank a lot :+1:

This fix will be included in all emonPi/emonBase/emonSD units by default. Existing users can pull in the fix via admin > emonpiupdate.

For reference here is the output I got expanding to a 16Gb card:

Current Disk Info:
Disk /dev/mmcblk0: 14.5 GiB, 15552479232 bytes, 30375936 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x50c2568e

Device         Boot   Start      End  Sectors  Size Id Type
/dev/mmcblk0p1         8192    96663    88472 43.2M  c W95 FAT32 (LBA)
/dev/mmcblk0p2        98304  8290303  8192000  3.9G 83 Linux
/dev/mmcblk0p3      8290304 30273536 21983233 10.5G 83 Linux

======================================================

Proposed changes to be made:
 SD card total disk size = 14.484375Gb
 Data Partition size     = 10.4824223518Gb

Are you sure you want to proceed? [Y/n] 

Command (m for help): The partition table has been altered.
Calling ioctl() to re-read partition table.
Re-reading the partition table failed.: Device or resource busy

The kernel still uses the old table. The new table will be used at the next reboot or after you run partprobe(8) or kpartx(8).

This error message can however be disregarded, because your system
is about to be rebooted, and the new partition table will then be
read by your operating system.

Writing the resize2fs_once script


======================================================================

So far, so good... in 20s your system will reboot
and resize the /home/pi/data filesystem to fill the resized partition.
**THIS OPERATION WILL TAKE UP TO 20 MINUTES**
When completed the Pi will poweroff and close down.
PLEASE DO NOT UNPLUG THE POWER FOR AT LEAST 30min
because it will likely result in an unusable filesystem.

=====================================================================

Then after waiting for the unit to shutdown then reboot:


pi@emonpi:~ $ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root       3.9G  1.6G  2.2G  42% /
devtmpfs        484M     0  484M   0% /dev
tmpfs           489M     0  489M   0% /dev/shm
tmpfs           489M  6.6M  482M   2% /run
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
tmpfs           489M     0  489M   0% /sys/fs/cgroup
tmpfs            50M  208K   50M   1% /var/log
tmpfs           1.0M     0  1.0M   0% /var/tmp
tmpfs            30M     0   30M   0% /tmp
/dev/mmcblk0p1   43M   22M   21M  52% /boot
/dev/mmcblk0p3   11G  113M  9.7G   2% /home/pi/data
tmpfs            98M     0   98M   0% /run/user/1000

Mmm it seems mariadb is down after the expansion process using the update emonSDexpand. Has anyone else experienced this?

● mariadb.service - MariaDB database server
   Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: 
   Active: failed (Result: exit-code) since Tue 2018-11-27 15:54:04 UTC; 4min 54
  Process: 838 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSR
  Process: 743 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR=
  Process: 739 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_
  Process: 735 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run
 Main PID: 838 (code=exited, status=1/FAILURE)
   Status: "MariaDB server is down"

Nov 27 15:53:56 emonpi systemd[1]: Starting MariaDB database server...
Nov 27 15:53:58 emonpi mysqld[838]: 2018-11-27 15:53:58 1988366336 [Note] /usr/s
Nov 27 15:54:04 emonpi systemd[1]: mariadb.service: Main process exited, code=ex
Nov 27 15:54:04 emonpi systemd[1]: Failed to start MariaDB database server.
Nov 27 15:54:04 emonpi systemd[1]: mariadb.service: Unit entered failed state.
Nov 27 15:54:04 emonpi systemd[1]: mariadb.service: Failed with result 'exit-cod

It worked for me

● mariadb.service - MariaDB database server
Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
Active: active (running) since Tue 2018-11-27 00:31:05 UTC; 1 day 18h ago
Main PID: 860 (mysqld)
Status: "Taking your SQL requests now..."
CGroup: /system.slice/mariadb.service
└─860 /usr/sbin/mysql

Nov 27 00:31:00 emonpi systemd[1]: Starting MariaDB database server...
Nov 27 00:31:02 emonpi mysqld[860]: 2018-11-27 0:31:02 1988608000 [Note] /usr/sbin/mysqld (mysqld 10.1.23-MariaDB-9+deb9u1) starting as process 860 ...
Nov 27 00:31:05 emonpi systemd[1]: Started MariaDB database server.