Dietpi: Dietpi-Update Problems on 2 Systems

[PoldiMUC]

Creating a bug report/issue:

Dietpi-Update Problems on 2 Systems

Required Information:

                             System 1 and System 2

• DietPi version | 6.4 and 6.9
• Distro version | stretch 9.4 and stretch 9.4
• Kernel version | Linux DietPi 4.9.80-v7+ #1098 SMP Fri Mar 9 19:11:42 GMT 2018 armv7l GNU/Linux and Linux FHEM 4.14.34-v7+ #1110 SMP Mon Apr 16 15:18:51 BST 2018 armv7l GNU/Linux
• SBC device | RPi 3 Model B (armv7l) and RPi 3 Model B (armv7l)
• Power supply used | 5V 2,5A and 5V up to 8A multiport (Anker Power Port 5)
• SDcard used | unknown and SanDisk Ultra 16GB 10

Additional Information (if applicable):

Installed software system 1:

• failtoban
• FHEM home automation (perl)
• RPi-monitor
• Dietpi-bugreport-no: 7b0541df-5216-4f92-acae-120818727f91-0

Installed software system 2:

• failtoban
• FHEM home automation (perl)
• RPi-monitor
• mosquitto
• boinc

Steps to reproduce:

System 1

1. Login and see that an update is waiting
2. run the update without errors
3. reboot
4. see that the version isn`t change. It is still 6.4

System 2

1. Login and see that an update is waiting
2. run the update
3. update stop with error (see screenshot)
   /DietPi/dietpi/dietpi-update: line 205: /tmp/dietpi-update/update.zip: No such file or directory
   [FAILED] DietPi-Update | Download failed, unable to run update. Please try running dietpi-update again.

Expected behaviour:

• update works ;-)

Actual behaviour:

System 1: Version is the old one
System 2: Update stops run with error

Extra details:

• ...

[PoldiMUC]

After several reboots the update at System 2 works now. So only the problem on system 1 is actual.
Greetings

[MichaIng]

@PoldiMUC
Thanks for your report.

System 2

• https://github.com/Fourdee/DietPi/blob/9039399bbebba61285e77618b86c6523e660693e/dietpi/dietpi-update#L205
• /tmp/dietpi-update ($FILEPATH_TEMP) is not available
• But it's created at beginning of script: https://github.com/Fourdee/DietPi/blob/9039399bbebba61285e77618b86c6523e660693e/dietpi/dietpi-update#L278
• ... and was successfully used to obtain server version: https://github.com/Fourdee/DietPi/blob/9039399bbebba61285e77618b86c6523e660693e/dietpi/dietpi-update#L106
• Only thing I can think of is filled /tmp fs and/or unstable mount somehow. That it is no real code bug, is also shown by the fact, that it finally worked.
• But as a fail safe, we could add mkdir -p $FILEPATH_TEMP right in front of curl execution?

System 1

• dietpi-ramdisk issue?
• To check:
  
  
  
  • cat /etc/systemd/system/dietpi-ramdisk.service # to check if rootfs file update got applied
  
  
  • cat /var/tmp/dietpi/logs/dietpi-ramdisk.log # to check if service was successfully stopped (RAMdisk sync to /boot)
  
  
• Also I heard of a similar issue on Nextcloud forum, where Nextcloud web update was not applied after reboot. There it was a broken SD card, which silently was in readonly mode. I/O buffer somehow kept (aware) changes until reboot. Could you test, if another larger change on the SD survives reboot?

[PoldiMUC]

Thank You for your fast reply.
I don`t understand what you want to say to system 2. But it works now fine so perhaps it will help you if someone have similar problems.

On System 1 i got following when i run the things you ask for:

root@DietPi:~# cat /etc/systemd/system/dietpi-ramdisk.service
[Unit]
Description=DietPi-RAMdisk
After=local-fs.target boot.mount
Before=rsyslog.service syslog.service

[Service]
Type=forking
RemainAfterExit=yes
ExecStartPre=/bin/mkdir -p /var/tmp/dietpi/logs
ExecStart=/bin/bash -c '/boot/dietpi/dietpi-ramdisk 0 &>> /var/tmp/dietpi/logs/d ietpi-ramdisk.log'
ExecStop=/bin/bash -c '/DietPi/dietpi/dietpi-ramdisk 1 &>> /var/tmp/dietpi/logs/ dietpi-ramdisk.log'

[Install]
WantedBy=local-fs.target
root@DietPi:~#

and

root@DietPi:~# cat /var/tmp/dietpi/logs/dietpi-ramdisk.log
Sun 18 Feb 20:33:01 GMT 2018 | DietPi-Ramdisk: Starting
Sun 18 Feb 20:33:01 GMT 2018 | DietPi-Ramdisk: Completed
Sun 18 Feb 20:33:53 GMT 2018 | DietPi-Ramdisk: Stopping
Sun 18 Feb 20:33:53 GMT 2018 | DietPi-Ramdisk: Completed
Sun 18 Feb 20:39:21 GMT 2018 | DietPi-Ramdisk: Starting
Sun 18 Feb 20:39:21 GMT 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 14:43:03 GMT 2018 | DietPi-Ramdisk: Stopping
Mon 12 Mar 14:43:03 GMT 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 14:43:05 GMT 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 14:43:05 GMT 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 15:50:52 CET 2018 | DietPi-Ramdisk: Stopping
Mon 12 Mar 15:50:52 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 15:50:54 CET 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 15:50:54 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:08:53 CET 2018 | DietPi-Ramdisk: Stopping
Mon 12 Mar 16:08:54 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:08:57 CET 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 16:08:58 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:21:53 CET 2018 | DietPi-Ramdisk: Stopping
Mon 12 Mar 16:21:53 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:22:00 CET 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 16:22:01 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:24:25 CET 2018 | DietPi-Ramdisk: Stopping
Mon 12 Mar 16:24:25 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:24:28 CET 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 16:24:29 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:24:28 CET 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 16:24:29 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:33:42 CET 2018 | DietPi-Ramdisk: Stopping
Mon 12 Mar 16:33:42 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 16:33:45 CET 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 16:33:46 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 17:11:38 CET 2018 | DietPi-Ramdisk: Stopping
Mon 12 Mar 17:11:38 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 17:11:41 CET 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 17:11:42 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 17:53:19 CET 2018 | DietPi-Ramdisk: Stopping
Mon 12 Mar 17:53:19 CET 2018 | DietPi-Ramdisk: Completed
Mon 12 Mar 17:53:21 CET 2018 | DietPi-Ramdisk: Starting
Mon 12 Mar 17:53:22 CET 2018 | DietPi-Ramdisk: Completed
Thu 15 Mar 22:42:44 CET 2018 | DietPi-Ramdisk: Stopping
Thu 15 Mar 22:42:44 CET 2018 | DietPi-Ramdisk: Completed
Thu 15 Mar 22:42:47 CET 2018 | DietPi-Ramdisk: Starting
Thu 15 Mar 22:42:48 CET 2018 | DietPi-Ramdisk: Completed
root@DietPi:~#

The larger change test on sd-card takes longer time cause it is a remote device. ;-)
Greetings

[Fourdee]

@PoldiMUC

In regards to System 1:
Dietpi-bugreport-no: 7b0541df-5216-4f92-acae-120818727f91-0. I was unable to find this on our server.
I believe its a hardware instability (SD card issue), however, check the following for any errors:

dmesg | grep mmc
dmesg | grep ext
dmesg | grep volt

---

@MichaIng

We already force a sync on the ramdisk: https://github.com/Fourdee/DietPi/blob/master/dietpi/dietpi-ramdisk#L141-L149

So yep, I believe system 1 is hardware related issue, where disk changes are not being saved, due to instability.

[Fourdee]

https://linux.die.net/man/8/sync
On Linux, sync is only guaranteed to schedule the dirty blocks for writing; it can actually take a short time before all the blocks are finally written. The reboot(8) and halt(8) commands take this into account by sleeping for a few seconds after calling sync(2).

Hmm, so there is no guarantee that sync will complete the changes?
We could add additional sleep but this is no real solution, and again, might not be enough time for the disk to sync changes.

Ideally, we'd need a more solid way of knowing when the disk changes are completed.

---

Mmm, maybe the following, after ramdisk is finished could ensure sync?:

echo 1 > /boot/.justincase
sync

[MichaIng]

@PoldiMUC
Don't mind about my System 2 comments, it's more a collection of my thoughts 😄. As the update finally went well, it will be hard to track down the real reason anyway.

Thu 15 Mar 22:42:48 CET 2018 | DietPi-Ramdisk: Completed

Is this really the last entry in /var/tmp/dietpi/logs/dietpi-ramdisk.log or was it just capped at the end? Last entry should be dated to last startup, otherwise it would be a hint that dietpi-ramdisk service is no correctly active. Otherwise this should lead to dietpi-update not running at all, not any other DietPi related script 🤔. systemctl status dietpi-ramdisk to test.

@Fourdee

We already force a sync on the ramdisk

Jep, in the case I mentioned, the SDcard/system never showed any error when writing to it, but after reboot always every change was lost. The attempt then was to format it on another system. But there error showed up that SD is read-only, also formatting didn't work with this error. Final assumption was that SDcard must be broken.

[Fourdee]

@MichaIng

I considered adding -v to cp commands in dietpi-ramdisk:

cp -Rfv $FILEPATH_RAM/* /boot/

However, any errors would already be printed in the logs. This would only add to the logfile size and disk write usage.

[MichaIng]

@Fourdee

The reboot(8) and halt(8) commands take this into account by sleeping for a few seconds after calling sync(2).

I think, if there would be a reliable way to determine when disk changes are synced completely, those commands would already use them(?).
This seems to be lowest kernel/hardware level.

Jep, AFAIK cp etc. have no chance to notice if a file change was done on disk level or I/O buffer.

@PoldiMUC
If I/O buffer on slow SDcard is really the issue, you could test the following:

dietpi-update 1
sed -i '/^[[:blank:]]*sync/a sleep 10' /DietPi/dietpi/dietpi-ramdisk
reboot

This updates without automated reboot, then adds 10 seconds sleep after calling sync to write I/O buffer to disk, finally reboots. The reboot should then take 10 seconds longer, which should give enough time for every SD to sync our ~1,5M DietPi size to disk.

[PoldiMUC]

I will do a backup from System 1 and write it on a fresh new SD-Card. I hope that will solve the problem. But cause the system is ~600km away it will take a little time.
I will report the result.

Thank you all for your quick and big support.
;-)

@Fourdee
Here the results you ask for:

root@DietPi:~# dmesg | grep mmc
[ 0.661401] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[ 0.777638] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 0.781232] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[ 0.782792] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[ 0.854542] mmc0: host does not support reading read-only switch, assuming write-enable
[ 0.918843] mmc0: new high speed SDHC card at address 59b4
[ 0.921859] mmcblk0: mmc0:59b4 USD 14.7 GiB
[ 0.928131] mmcblk0: p1 p2
[ 0.938877] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 0.943557] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.946656] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.950940] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 1.004028] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 1.038923] mmc1: new high speed SDIO card at address 0001
[ 3.342018] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 4.169495] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

root@DietPi:~# dmesg | grep ext
[ 0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=1280 bcm2708_fb.fbheight=720 bcm2708_fb.fbdepth=16 b cm2708_fb.fbswap=1 vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000 dwc_otg.lpm_enable=0 console=tty1 root=PARTUUID=6 f0c83bc-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
.text : 0x80008000 - 0x80800000 (8160 kB)
[ 0.029148] CPU: Virtualization extensions available.
[ 1.005643] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 4.923058] Adding 1097724k swap on /var/swap. Priority:-1 extents:3 across:2449404k SSFS

root@DietPi:~# dmesg | grep volt

root@DietPi:~#

[MichaIng]

[ 1.005643] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 3.342018] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 4.169495] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

Not sure, about the first /root readonly, as it then got remounted.

@PoldiMUC
Could you do:

umount /dev/mmcblk0p1
fsck /dev/mmcblk0p1
mount /dev/mmcblk0p1 /boot
lsblk

[PoldiMUC]

Hi MichaIng
here the results:

root@DietPi:~# umount /boot

root@DietPi:~# fsck mmcblk0p1
fsck from util-linux 2.29.2

root@DietPi:~# mount /dev/mmcblk0p1 /boot

root@DietPi:~# lsblk
NAME MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
mmcblk0 179:0 0 14.7G 0 disk
├─mmcblk0p1 179:1 0 41.5M 0 part /boot
└─mmcblk0p2 179:2 0 14.7G 0 part /

root@DietPi:~# dmesg | grep mmc
[ 0.661401] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[ 0.777638] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 0.781232] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[ 0.782792] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[ 0.854542] mmc0: host does not support reading read-only switch, assuming write-enable
[ 0.918843] mmc0: new high speed SDHC card at address 59b4
[ 0.921859] mmcblk0: mmc0:59b4 USD 14.7 GiB
[ 0.928131] mmcblk0: p1 p2
[ 0.938877] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 0.943557] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.946656] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.950940] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 1.004028] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 1.038923] mmc1: new high speed SDIO card at address 0001
[ 3.342018] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 4.169495] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[17201.127033] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

[MichaIng]

@PoldiMUC
Hehe sorry forgot to add /dev/.. in the fsck command. The following should run proper fsck:

umount /dev/mmcblk0p1
fsck /dev/mmcblk0p1
mount /dev/mmcblk0p1 /boot

But as umount /boot does work as well (as long as drive is mounted there), the error message indicates already an issue there:
[17201.127033] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

But no readonly flag at least: mmcblk0p2 179:2 0 14.7G **0** part /

Please run fsck again with commands as above. If errors were found (they should not be auto repaired), then, I would not go on until you are at the RPis place. Fsck fix attempts can also break stuff, and as this is /boot fs, it can easily lead to device being unbootable or boot into unexpected stage. So you should do required backups there and be able to access via monitor and keyboard directly, just in case.

Also kernel reinstall (apt install --reinstall raspberrypi-kernel raspberrypi-bootloader) could prevent boot issues, as possible corrupted kernel/bootloader data gets renewed 😉.

[PoldiMUC]

fsck say:
0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
it ask me "remove dirty bit" or no action?
is that repair or someting else so can i do it?

[MichaIng]

@PoldiMUC
Dirty bit is set, if the kernel thinks it might be good to check the system and AFAIK should lead to an automated check on reboot.
So reason should be the not properly unmounted. You can agree to remove it.

[PoldiMUC]

So i do this:
root@DietPi:~# fsck /dev/mmcblk0p1
fsck from util-linux 2.29.2
fsck.fat 4.1 (2017-01-24)
0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
1) Remove dirty bit
2) No action
? 1
Perform changes ? (y/n) y
/dev/mmcblk0p1: 255 files, 45399/83705 clusters

root@DietPi:~# mount /dev/mmcblk0p1 /boot

root@DietPi:~# dmesg | grep mmc
[ 0.661401] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[ 0.777638] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 0.781232] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[ 0.782792] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[ 0.854542] mmc0: host does not support reading read-only switch, assuming write-enable
[ 0.918843] mmc0: new high speed SDHC card at address 59b4
[ 0.921859] mmcblk0: mmc0:59b4 USD 14.7 GiB
[ 0.928131] mmcblk0: p1 p2
[ 0.938877] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 0.943557] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.946656] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.950940] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 1.004028] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 1.038923] mmc1: new high speed SDIO card at address 0001
[ 3.342018] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 4.169495] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[17201.127033] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[19704.248977] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

root@DietPi:~# umount /dev/mmcblk0p1

root@DietPi:~# fsck /dev/mmcblk0p1
fsck from util-linux 2.29.2
fsck.fat 4.1 (2017-01-24)
0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
1) Remove dirty bit
2) No action
? 2
There are differences between boot sector and its backup.
This is mostly harmless. Differences: (offset:original/backup)
65:01/00
1) Copy original to backup
2) Copy backup to original
3) No action
? 3
/dev/mmcblk0p1: 255 files, 45399/83705 clusters

root@DietPi:~# mount /dev/mmcblk0p1 /boot

I think i have to be at the system. If noone have any suggests i stop today and report what happens when i backup and repair with fsck and perhaps with kernel reinstall.
Big thanks for your help.
Great Project

[Fourdee]

General cleanup, i'll mark this as closed due to hardware related issues. If problems persist, please let us know.