Unexpected EOF when updating from the Mender server

[Arnstein Kleven]

I am getting "error: failed to write image data to device /dev/mmcblk1p2: unexpected EOF" when updating my device from the Mender server. I have tried this with both the Mender client and server 1.0 as well as 1.2.

When putting the .mender file on the device and running mender -rootfs update.mender it works perfectly, however, creating a deployment on the server gives the unexpected EOF error.

Full log can be found here:

2017-09-21 13:28:11 +0000 UTC debug: handle update fetch state 2017-09-21 13:28:11 +0000 UTC info: Mender state: update-fetch -> update-install 2017-09-21 13:28:11 +0000 UTC debug: handle update install state 2017-09-21 13:28:11 +0000 UTC debug: Read data from device manifest file: device_type=firefly 2017-09-21 13:28:11 +0000 UTC debug: Found needed line: device_type=firefly 2017-09-21 13:28:11 +0000 UTC debug: Current manifest data: firefly 2017-09-21 13:28:11 +0000 UTC debug: Trying to install update of size: 3145728000 2017-09-21 13:28:11 +0000 UTC debug: Have U-Boot variable: mender_boot_part=3 2017-09-21 13:28:11 +0000 UTC debug: List of U-Boot variables:map[mender_boot_part:3] 2017-09-21 13:28:11 +0000 UTC debug: Setting active partition from mount candidate: /dev/mmcblk1p3 2017-09-21 13:28:11 +0000 UTC debug: Detected inactive partition /dev/mmcblk1p2, based on active partition /dev/mmcblk1p3 2017-09-21 13:28:11 +0000 UTC info: opening device /dev/mmcblk1p2 for writing 2017-09-21 13:28:11 +0000 UTC info: partition /dev/mmcblk1p2 size: 4194304000 2017-09-21 13:43:38 +0000 UTC error: failed to write image data to device /dev/mmcblk1p2: unexpected EOF 2017-09-21 13:43:38 +0000 UTC info: wrote 2167668224/3145728000 bytes of update to device /dev/mmcblk1p2 2017-09-21 13:43:39 +0000 UTC error: update install failed: installer: failed to read and install update: update: can not install update: &{linaro-rootfs.img 33188 1000 1000 3145728000 2017-09-18 13:40:27 +0200 CEST 48 0 0 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[]}: update: can not install: unexpected EOF 2017-09-21 13:43:39 +0000 UTC info: Mender state: update-install -> fetch-install-retry-wait 2017-09-21 13:43:39 +0000 UTC debug: handle fetch install retry state 2017-09-21 13:43:39 +0000 UTC debug: wait 1m0s before next fetch/install attempt 2017-09-21 13:44:39 +0000 UTC debug: wait complete 2017-09-21 13:44:39 +0000 UTC info: Mender state: fetch-install-retry-wait -> update-fetch 2017-09-21 13:44:39 +0000 UTC debug: handle update fetch state 2017-09-21 13:44:40 +0000 UTC info: Mender state: update-fetch -> update-install 2017-09-21 13:44:40 +0000 UTC debug: handle update install state 2017-09-21 13:44:40 +0000 UTC debug: Read data from device manifest file: device_type=firefly 2017-09-21 13:44:40 +0000 UTC debug: Found needed line: device_type=firefly 2017-09-21 13:44:40 +0000 UTC debug: Current manifest data: firefly 2017-09-21 13:44:40 +0000 UTC debug: Trying to install update of size: 3145728000 2017-09-21 13:44:40 +0000 UTC debug: Inactive partition: /dev/mmcblk1p2 2017-09-21 13:44:40 +0000 UTC info: opening device /dev/mmcblk1p2 for writing 2017-09-21 13:44:40 +0000 UTC info: partition /dev/mmcblk1p2 size: 4194304000 2017-09-21 13:59:45 +0000 UTC error: failed to write image data to device /dev/mmcblk1p2: unexpected EOF 2017-09-21 13:59:45 +0000 UTC info: wrote 2285633024/3145728000 bytes of update to device /dev/mmcblk1p2 2017-09-21 13:59:45 +0000 UTC error: update install failed: installer: failed to read and install update: update: can not install update: &{linaro-rootfs.img 33188 1000 1000 3145728000 2017-09-18 13:40:27 +0200 CEST 48 0 0 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[]}: update: can not install: unexpected EOF 2017-09-21 13:59:45 +0000 UTC info: Mender state: update-install -> fetch-install-retry-wait 2017-09-21 13:59:45 +0000 UTC debug: handle fetch install retry state 2017-09-21 13:59:45 +0000 UTC debug: wait 1m0s before next fetch/install attempt 2017-09-21 14:00:45 +0000 UTC debug: wait complete 2017-09-21 14:00:45 +0000 UTC info: Mender state: fetch-install-retry-wait -> update-fetch 2017-09-21 14:00:45 +0000 UTC debug: handle update fetch state 2017-09-21 14:00:45 +0000 UTC info: Mender state: update-fetch -> update-install 2017-09-21 14:00:45 +0000 UTC debug: handle update install state 2017-09-21 14:00:45 +0000 UTC debug: Read data from device manifest file: device_type=firefly 2017-09-21 14:00:45 +0000 UTC debug: Found needed line: device_type=firefly 2017-09-21 14:00:45 +0000 UTC debug: Current manifest data: firefly 2017-09-21 14:00:45 +0000 UTC debug: Trying to install update of size: 3145728000 2017-09-21 14:00:45 +0000 UTC debug: Inactive partition: /dev/mmcblk1p2 2017-09-21 14:00:45 +0000 UTC info: opening device /dev/mmcblk1p2 for writing 2017-09-21 14:00:45 +0000 UTC info: partition /dev/mmcblk1p2 size: 4194304000 2017-09-21 14:16:25 +0000 UTC error: failed to write image data to device /dev/mmcblk1p2: unexpected EOF 2017-09-21 14:16:25 +0000 UTC info: wrote 2283142656/3145728000 bytes of update to device /dev/mmcblk1p2 2017-09-21 14:16:27 +0000 UTC error: update install failed: installer: failed to read and install update: update: can not install update: &{linaro-rootfs.img 33188 1000 1000 3145728000 2017-09-18 13:40:27 +0200 CEST 48 0 0 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[]}: update: can not install: unexpected EOF 2017-09-21 14:16:27 +0000 UTC info: Mender state: update-install -> fetch-install-retry-wait 2017-09-21 14:16:27 +0000 UTC debug: handle fetch install retry state 2017-09-21 14:16:27 +0000 UTC debug: wait 1m0s before next fetch/install attempt 2017-09-21 14:17:27 +0000 UTC debug: wait complete 2017-09-21 14:17:27 +0000 UTC info: Mender state: fetch-install-retry-wait -> update-fetch 2017-09-21 14:17:27 +0000 UTC debug: handle update fetch state 2017-09-21 14:17:28 +0000 UTC info: Mender state: update-fetch -> update-install 2017-09-21 14:17:28 +0000 UTC debug: handle update install state 2017-09-21 14:17:28 +0000 UTC debug: Read data from device manifest file: device_type=firefly 2017-09-21 14:17:28 +0000 UTC debug: Found needed line: device_type=firefly 2017-09-21 14:17:28 +0000 UTC debug: Current manifest data: firefly 2017-09-21 14:17:28 +0000 UTC debug: Trying to install update of size: 3145728000 2017-09-21 14:17:28 +0000 UTC debug: Inactive partition: /dev/mmcblk1p2 2017-09-21 14:17:28 +0000 UTC info: opening device /dev/mmcblk1p2 for writing 2017-09-21 14:17:28 +0000 UTC info: partition /dev/mmcblk1p2 size: 4194304000 2017-09-21 14:20:06 +0000 UTC debug: handle update status report state 2017-09-21 14:20:06 +0000 UTC info: attempting to report data of deployment [8d1decee-81cd-4f15-8da6-a4de87fea6fd] to the backend; deployment status [failure], try 0 2017-09-21 14:20:06 +0000 UTC debug: attempting to upload deployment logs for failed update 2017-09-21 14:20:06 +0000 UTC info: attempting to report data of deployment [8d1decee-81cd-4f15-8da6-a4de87fea6fd] to the backend; deployment status [failure], try 0

[Maciej Borzecki]

On Fri, Sep 22, 2017 at 11:38 AM, Arnstein Kleven
<arnstei...@gmail.com> wrote:
> I am getting "error: failed to write image data to device /dev/mmcblk1p2:
> unexpected EOF" when updating my device from the Mender server. I have tried
> this with both the Mender client and server 1.0 as well as 1.2.
> When putting the .mender file on the device and running mender -rootfs
> update.mender it works perfectly, however, creating a deployment on the
> server gives the unexpected EOF error.

Can you attach backend log as well?

> --
> You received this message because you are subscribed to the Google Groups
> "Mender List mender.io" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mender+un...@lists.mender.io.
> To post to this group, send email to men...@lists.mender.io.
> Visit this group at
> https://groups.google.com/a/lists.mender.io/group/mender/.



--
Maciej Borzecki

[Arnstein Kleven]

Which command do I need to run to get the backend log? 

[Kristian Amlie]

There is a large time gap before the error. Could it be that since we are writing so much null data (free space at the end of the partition, which compresses to virtually nothing), the server times out because we are not asking for more data in a timely manner?

--
Kristian

[Kristian Amlie]

Arnstein, can you try making the update artificially smaller? Just set the rootfs size to a size which is just enough to hold the actual content (IOW we reduce the amount of free "null" space).

Then make a .mender update with that and try to deploy to a device which already has the full partition size.

--
Kristian

[Arnstein Kleven]

Yes, will do that and update you on monday!

Arnstein

[Arnstein Kleven]

This fixed the issue for me, after doing this I no longer get unexpected EOF.

Arnstein

[Kristian Amlie]

On 25/09/17 14:20, Arnstein Kleven wrote:
> This fixed the issue for me, after doing this I no longer get unexpected
> EOF.

Thanks Arnstein, that confirms the bug. I have created this ticket to
get this fixed in the client: https://tracker.mender.io/browse/MEN-1511

--
Kristian

[Diogo Piçarra]

Just tried to updated to board at the same time. One updated successfully. The other one keeps getting this error and is still trying to update for more than 2 hours.
The boards have a rootfs size of 2GB. I tried to change it to 1GB but the image generation ignored it.
I think it should have highest priority.

[Kristian Amlie]

On 28/09/17 12:36, Diogo Piçarra wrote:
> Just tried to updated to board at the same time. One updated
> successfully. The other one keeps getting this error and is still trying
> to update for more than 2 hours.
> The boards have a rootfs size of 2GB. I tried to change it to 1GB but
> the image generation ignored it.
> I think it should have highest priority.

Yes, I saw that you tried to adjust IMAGE_ROOTFS_SIZE. Note that rootfs
size and partition size are not the same thing; IMAGE_ROOTFS_SIZE does
not affect the latter at all, only MENDER_STORAGE_TOTAL_SIZE_MB does.
But IMAGE_ROOTFS_SIZE is the size of the update that ends up in the
.mender file.

Can you verify that the .ext4 file in the
build/tmp/deploy/images/<MACHINE>/ is the correct size according to the
IMAGE_ROOTFS_SIZE you have set?

--
Kristian

[Diogo Piçarra]

The ext4 file have the correct size.
Just checked the documentation and the MENDER_STORAGE_TOTAL_SIZE_MB value is generated automatically as I expected.
So removed that option and got this error:
"ERROR: ionseed-image-1.0-r0 do_image_mender: Size of rootfs is greater than the calculated partition space (1073741824 > 181403648). This image won't fit on a device with the current storage configuration. Try reducing IMAGE_OVERHEAD_FACTOR if it is higher than 1.0, or raise MENDER_STORAGE_TOTAL_SIZE_MB if the device in fact has more storage."

I guess that's why set the MENDER_STORAGE_TOTAL_SIZE_MB value. The OVERHEAD_FACTOR is 1.0.
The partition and the rootfs should have the same size.
I guess the partition size calculation is based on the content. I think the IMAGE_ROOTFS_SIZE should overwrite that when it's bigger.

Btw, the update worked after about 3 hours and many retries. That's still not good.

Thanks

[Kristian Amlie]

On 28/09/17 15:01, Diogo Piçarra wrote:
> The ext4 file have the correct size.
> Just checked the documentation and the MENDER_STORAGE_TOTAL_SIZE_MB
> value is generated automatically as I expected.
> So removed that option and got this error:
> "ERROR: ionseed-image-1.0-r0 do_image_mender: Size of rootfs is greater
> than the calculated partition space (1073741824 > 181403648). This image
> won't fit on a device with the current storage configuration. Try
> reducing IMAGE_OVERHEAD_FACTOR if it is higher than 1.0, or raise
> MENDER_STORAGE_TOTAL_SIZE_MB if the device in fact has more storage."
>
> I guess that's why set the MENDER_STORAGE_TOTAL_SIZE_MB value. The
> OVERHEAD_FACTOR is 1.0.
> The partition and the rootfs should have the same size.
> I guess the partition size calculation is based on the content. I think

> the IMAGE_ROOTFS_SIZEshould overwrite that when it's bigger.

Not sure I follow. MENDER_STORAGE_TOTAL_SIZE_MB cannot be automatically
adjusted, because this is the real physical storage size accessible on
the device. This is the *whole* storage, the entire size of the memory
card, not just partitions. IMAGE_ROOTFS_SIZE is calculated based on this
value, and you can set IMAGE_ROOTFS_SIZE to be smaller than the
calculated value (for example to avoid the EOF bug), but never bigger,
because this would not fit inside the generated partition.

> Btw, the update worked after about 3 hours and many retries. That's
> still not good.

Yes the EOF bug will need to be fixed obviously.

--
Kristian

[Diogo Piçarra]

I know what the MENDER_STORAGE_TOTAL_SIZE_MB is.
In the partition layout documentation it's written Default size=auto.
IMAGE_ROOTFS_SIZE
I think the mount point in the documentation is wrong. MENDER_STORAGE_TOTAL_SIZE_MB don't have a mount point.

MENDER_STORAGE_TOTAL_SIZE_MB should be:
MENDER_STORAGE_TOTAL_SIZE_MB=(IMAGE_ROOTFS_SIZE*2)+MENDER_DATA_PART_SIZE_MB+ boot partition, etc

The IMAGE_ROOTFS_SIZE value i'am using right now is not calculated. It's what I defined.
I can't change the IMAGE_ROOTFS_SIZE to the calculated partition size. It's too small.

[Maciej Borzecki]

I think the formula is actually reversed and IMAGE_ROOTFS_SIZE is the
output variable while all mender settings are inputs. It goes roughly
like this:

IMAGE_ROOTFS_SIZE = 0.5 * (MENDER_STORAGE_TOTAL_SIZE_MB
- MENDER_DATA_PART_SIZE_MB
- MENDER_BOOT_PART_SIZE_MB
- partitioning overhead
- MENDER_STORAGE_RESERVED_RAW_SPACE)

You are expected to not set IMAGE_ROOTFS_SIZE and have the code
calculate the right value.

Also, technically it is possible to have your rootfs larger than
IMAGE_ROOTFS_SIZE. This can happen if your filesystem uses compression,
such as ubifs, squashfs, btrfs and so on. There's an obscure variable
IMAGE_ROOTFS_MAXSIZE that you can use to apply an upper limit on rootfs
size:
https://git.yoctoproject.org/cgit/cgit.cgi/poky/tree/meta/classes/image.bbclass#n547

--
Maciej Borzecki