Occasional device not found during upgrade

[Pelle Windestam]

Hi,

I am having a strange issue with swupdate, occasionally I will get the following error message when trying to upgrade:
[TRACE] : SWUPDATE running : [install_raw_image] : Device /dev/mmcblk0p1 cannot be opened: No such file or directory

The setup is a single-copy update, where I have placed swupdate in an initrd-image which is booted if the upgrade_available variable is set in u-boot. I am using swupdate version 2018.03.

In the shell I can see that /dev/mmcblk0p1 is present, and I can hexdump from the device so it is definitely there. I can even mount it and look around in the file system.

Any ideas what could be causing this? I have checked the source code for the raw_handler and I cannot understand what's going wrong, it seems like it is simply calling open() on the device, which I assume what hexdump would use as well. Most of the time if I do a board reset and try the update again, the error is not occurring.

My sw-description looks like this:
software =
{
version = "1.0";
description = "Firmware upgrade"

firmware = {
hardware-compatibility: [ "1.0" ];
images: (
{
filename = "firmware-image-base-imx8qxp-var-som.ext4.gz";
type = "raw";
compressed = true;
device = "/dev/mmcblk0p1";
filesystem = "ext4";
sha256 = "@firmware-image-base-imx8qxp-var-som.ext4.gz" ;
}
);
scripts: (
{
filename = "update.sh";
type = "shellscript";
sha256 = "@update.sh";
}
);
};
}

//Pelle

[Stefano Babic]

On 31/01/20 08:29, Pelle Windestam wrote:
> Hi,
>
> I am having a strange issue with swupdate, occasionally I will get the following error message when trying to upgrade:
> [TRACE] : SWUPDATE running : [install_raw_image] : Device /dev/mmcblk0p1 cannot be opened: No such file or directory
>
> The setup is a single-copy update, where I have placed swupdate in an initrd-image which is booted if the upgrade_available variable is set in u-boot. I am using swupdate version 2018.03.
>
> In the shell I can see that /dev/mmcblk0p1 is present, and I can hexdump from the device so it is definitely there. I can even mount it and look around in the file system.
>
> Any ideas what could be causing this? I have checked the source code for the raw_handler and I cannot understand what's going wrong,

I think you are looking to the wrong place because this does not seem
related to SWUpdate. You run from initramfs, and I can suppose there is
a race condition and when SWUpdate tries to access via open() to the
eMMC, the device is not yot availabl and the kernel returns an error.
When yopu check in the shell, you are much more later and device is
available. And I guess that SWUPdate will run then if you restart it
into this shell.

it seems like it is simply calling open() on the device, which I assume
what hexdump would use as well. Most of the time if I do a board reset
and try the update again, the error is not occurring.
>
> My sw-description looks like this:
> software =
> {
> version = "1.0";
> description = "Firmware upgrade"
>
> firmware = {
> hardware-compatibility: [ "1.0" ];
> images: (
> {
> filename = "firmware-image-base-imx8qxp-var-som.ext4.gz";
> type = "raw";
> compressed = true;
> device = "/dev/mmcblk0p1";
> filesystem = "ext4";
> sha256 = "@firmware-image-base-imx8qxp-var-som.ext4.gz" ;
> }
> );
> scripts: (
> {
> filename = "update.sh";
> type = "shellscript";
> sha256 = "@update.sh";

Check this thread, too.

https://groups.google.com/forum/#!searchin/swupdate/update$20of$20u-boot.imx%7Csort:date/swupdate/jASLNVWl98E/NgNCJzqSDgAJ


Best regards,
Stefano Babic

--
=====================================================================
DENX Software Engineering GmbH, Managing Director: Wolfgang Denk
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: +49-8142-66989-53 Fax: +49-8142-66989-80 Email: sba...@denx.de
=====================================================================

[Pelle Windestam]

> > Hi,
> >
> > I am having a strange issue with swupdate, occasionally I will get the
> following error message when trying to upgrade:
> > [TRACE] : SWUPDATE running : [install_raw_image] : Device
> > /dev/mmcblk0p1 cannot be opened: No such file or directory
> >
> > The setup is a single-copy update, where I have placed swupdate in an
> initrd-image which is booted if the upgrade_available variable is set in u-
> boot. I am using swupdate version 2018.03.
> >
> > In the shell I can see that /dev/mmcblk0p1 is present, and I can hexdump
> from the device so it is definitely there. I can even mount it and look
> around in the file system.
> >
> > Any ideas what could be causing this? I have checked the source code
> > for the raw_handler and I cannot understand what's going wrong,
>
> I think you are looking to the wrong place because this does not seem related
> to SWUpdate. You run from initramfs, and I can suppose there is a race
> condition and when SWUpdate tries to access via open() to the eMMC, the
> device is not yot availabl and the kernel returns an error.
> When yopu check in the shell, you are much more later and device is
> available. And I guess that SWUPdate will run then if you restart it into
> this shell.
>

Thanks for the hint, I did not consider that possibility. When this error happened, I tried to upload the same swu-file again, but it would yield the same error even the second time. Shouldn't enough time has passed at this point for the eMMC-device to become available? Logging into the shell and hexdumping from the device probably takes about as long time as it takes to upload/fail with the first attempt.

I would like to try to restart swupdate from the shell when this error has occurred, but unfortunately it is quite hard to reproduce.

//Pelle

[Pelle Windestam]

After some more testing, I managed to get the upgrade working by uploading the file again after a failure, so my initial test results were incorrect. It would seem then that the eMMC device is very slow to become ready. I did try to hold the start of swupdate until /dev/mmcblk0p1 becomes available, but that never stalls the startup so I guess that the device is available in the filesystem but for some reason not ready to be written to. Is there any way to handle this in swupdate? The only thing I can think of right now would be to modify the code that tries to open the device, and retry a few times (with a timeout).

This is from the boot log, before swupdate starts:

mmcblk0: mmc0:0001 AJTD4R 14.6 GiB
caam 31400000.caam: ERA source: device tree.
mmcblk0boot0: mmc0:0001 AJTD4R partition 1 4.00 MiB
mmcblk0boot1: mmc0:0001 AJTD4R partition 2 4.00 MiB
mmcblk0rpmb: mmc0:0001 AJTD4R partition 3 4.00 MiB
mmcblk0: p1 p2 p3

EXT4-fs (mmcblk0p1): mounted filesystem with ordered data mode. Opts: (null)
VFS: Mounted root (ext4 filesystem) on device 179:1.
devtmpfs: mounted
Freeing unused kernel memory: 512K
random: fast init done
INIT: version 2.88 booting
EXT4-fs (mmcblk0p2): recovery complete
EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
EXT4-fs (mmcblk0p3): recovery complete
EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null)

//Pelle

[Stefano Babic]

Why is this an issue in SWUpdate ? It is not. Is it not true that you
start your software adding "rootfswait" as kernel parameter ?

> The only thing I can think of right now would be to modify the code that tries to open the device, and retry a few times (with a timeout).

This is a nasty hack. You should solve this outside SWUpdate.

>
> This is from the boot log, before swupdate starts:
>
> mmcblk0: mmc0:0001 AJTD4R 14.6 GiB
> caam 31400000.caam: ERA source: device tree.
> mmcblk0boot0: mmc0:0001 AJTD4R partition 1 4.00 MiB
> mmcblk0boot1: mmc0:0001 AJTD4R partition 2 4.00 MiB
> mmcblk0rpmb: mmc0:0001 AJTD4R partition 3 4.00 MiB
> mmcblk0: p1 p2 p3
>
> EXT4-fs (mmcblk0p1): mounted filesystem with ordered data mode. Opts: (null)
> VFS: Mounted root (ext4 filesystem) on device 179:1.

But do not you run from initramfs ?

Best regards,
Stefano Babic

> devtmpfs: mounted
> Freeing unused kernel memory: 512K
> random: fast init done
> INIT: version 2.88 booting
> EXT4-fs (mmcblk0p2): recovery complete
> EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
> EXT4-fs (mmcblk0p3): recovery complete
> EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null)
>
> //Pelle
>

[Pelle Windestam]

Unfortunately that is not the issue:
# cat /proc/cmdline
console=ttyLP3,115200 earlycon=lpuart32,0x5a090000,115200

> > The only thing I can think of right now would be to modify the code that
> tries to open the device, and retry a few times (with a timeout).
>
> This is a nasty hack. You should solve this outside SWUpdate.
>
>
> >
> > This is from the boot log, before swupdate starts:
> >
> > mmcblk0: mmc0:0001 AJTD4R 14.6 GiB
> > caam 31400000.caam: ERA source: device tree.
> > mmcblk0boot0: mmc0:0001 AJTD4R partition 1 4.00 MiB
> > mmcblk0boot1: mmc0:0001 AJTD4R partition 2 4.00 MiB
> > mmcblk0rpmb: mmc0:0001 AJTD4R partition 3 4.00 MiB
> > mmcblk0: p1 p2 p3
> >
> > EXT4-fs (mmcblk0p1): mounted filesystem with ordered data mode. Opts:
> > (null)
> > VFS: Mounted root (ext4 filesystem) on device 179:1.
>
> But do not you run from initramfs ?
>

Oops I'm sorry, these were copied from another bootlog. Those messages are NOT present when booting the initrd with swupdate. The only thing related to the eMMC are these:
mmc0: Command Queue Engine enabled
mmc0: new HS400 Enhanced strobe MMC card at address 0001

mmcblk0: mmc0:0001 AJTD4R 14.6 GiB

mmcblk0boot0: mmc0:0001 AJTD4R partition 1 4.00 MiB

ledtrig-cpu: registered to indicate activity on CPUs

mmcblk0boot1: mmc0:0001 AJTD4R partition 2 4.00 MiB

caam 31400000.caam: ERA source: device tree.

mmcblk0rpmb: mmc0:0001 AJTD4R partition 3 4.00 MiB
mmcblk0: p1 p2 p3

Thanks for your help so far Stefano, very much appreciated. I'll try to dig a bit deeper and try to find a solution for this that does not involve hacking the swupdate handler code.

//Pelle