Mender Client Software Freezes after aborting deployment from deployment server

[Cevat Bostancıoğlu]

Hello, i am successfully done with secure/usb rootfs update with mender but when i try to update rootfs and sent deployment, i click abort deployment on server and device mender binary is just freezes.

Mender client is not sending any requests or not responding anything.

I don't remember it happened before and i just added state scripts and certificate. 

my state scripts are just writing some data to file. that file is not opened any other program.

certificates are working. maybe app has a bug with secure updates. 

Do you guys have any suggestions ?

[Kristian Amlie]

Do you have the client logs from the device?

journalctl -u mender

--
Kristian

[Cevat Bostancıoğlu]

[Cevat Bostancıoğlu]

As you can see in photos, it just freezes there. after reboot journal log is :

Jan 01 00:00:06 raspberrypi3 systemd[1]: Started Mender OTA update service.

Feb 26 18:33:26 raspberrypi3 mender[371]: level=info msg="State transition: init [none] -> init [none]" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: time="2018-02-26T18:33:26Z" level=info msg="State transition: init [none] -> init [none]" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: level=info msg="State transition: init [none] -> idle [Idle]" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: time="2018-02-26T18:33:26Z" level=info msg="State transition: init [none] -> idle [Idle]" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: level=info msg="authorization data present and valid" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: time="2018-02-26T18:33:26Z" level=info msg="authorization data present and valid" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: time="2018-02-26T18:33:26Z" level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender

Feb 26 18:33:26 raspberrypi3 mender[371]: time="2018-02-26T18:33:26Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender

Feb 26 18:33:30 raspberrypi3 mender[371]: level=error msg="failed to submit inventory data: Patch https://docker.mender.io/api/devices/v1/inventory/device/attributes: dial tcp 10.224.172.137:443: getso

Feb 26 18:33:30 raspberrypi3 mender[371]: level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed: Patch https://docker.mender.io/api/devices/v1/invento

Feb 26 18:33:30 raspberrypi3 mender[371]: time="2018-02-26T18:33:30Z" level=error msg="failed to submit inventory data: Patch https://docker.mender.io/api/devices/v1/inventory/device/attributes: dial t

Feb 26 18:33:30 raspberrypi3 mender[371]: time="2018-02-26T18:33:30Z" level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed: Patch https://docker.mend

Feb 26 18:33:30 raspberrypi3 mender[371]: time="2018-02-26T18:33:30Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender

Feb 26 18:33:30 raspberrypi3 mender[371]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender

Feb 26 18:33:30 raspberrypi3 mender[371]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender

Feb 26 18:33:30 raspberrypi3 mender[371]: time="2018-02-26T18:33:30Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: level=error msg="Error receiving scheduled update data: update check request failed: Get https://docker.mender.io/api/devices/v1/deployments/device/deployments

Feb 26 18:33:33 raspberrypi3 mender[371]: level=error msg="update check failed: transient error: update check request failed: Get https://docker.mender.io/api/devices/v1/deployments/device/deployments/

Feb 26 18:33:33 raspberrypi3 mender[371]: time="2018-02-26T18:33:33Z" level=error msg="Error receiving scheduled update data: update check request failed: Get https://docker.mender.io/api/devices/v1/de

Feb 26 18:33:33 raspberrypi3 mender[371]: time="2018-02-26T18:33:33Z" level=error msg="update check failed: transient error: update check request failed: Get https://docker.mender.io/api/devices/v1/dep

Feb 26 18:33:33 raspberrypi3 mender[371]: time="2018-02-26T18:33:33Z" level=info msg="State transition: update-check [Sync] -> error [Error]" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: level=info msg="State transition: update-check [Sync] -> error [Error]" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: level=info msg="handling error state, current error: transient error: update check request failed: Get https://docker.mender.io/api/devices/v1/deployments/devi

Feb 26 18:33:33 raspberrypi3 mender[371]: level=info msg="State transition: error [Error] -> idle [Idle]" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: time="2018-02-26T18:33:33Z" level=info msg="handling error state, current error: transient error: update check request failed: Get https://docker.mender.io/api

Feb 26 18:33:33 raspberrypi3 mender[371]: time="2018-02-26T18:33:33Z" level=info msg="State transition: error [Error] -> idle [Idle]" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: level=info msg="authorization data present and valid" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: time="2018-02-26T18:33:33Z" level=info msg="authorization data present and valid" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: time="2018-02-26T18:33:33Z" level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: time="2018-02-26T18:33:33Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender

Feb 26 18:33:33 raspberrypi3 mender[371]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender

[Drew Moseley]

Are you running Mender in managed or standalone mode?  The term "USB rootfs update" sounds like standalone but the logs look like managed?

From the log below it looks like something is messed up in your networking.  Note the failure in connecting to tcp 10.224.172.137.

Drew

--
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/.

[Cevat Bostancıoğlu]

i am running in managed mode. 

[Drew Moseley]

Any idea why the networking would be messed up in the new image?

Drew

[Cevat Bostancıoğlu]

The problem is about when i aborting rootfs update in Downloading state, mender just freezes there. my device can access to the server and server is working when you are not aborting the process. the network errors causes another wifi hotspot feature and they are not concern anymore. they are just logged there but there are not the issue.

[Cevat Bostancıoğlu]

Server still can send updates but it is waiting in pending state. 

[Kristian Amlie]

On 27/02/18 10:59, Cevat Bostancıoğlu wrote:
> Server still can send updates but it is waiting in pending state.

Are you sure that it isn't coming back after some time? The client
doesn't query the server while the download is ongoing, so it may take
some time to discover that the update has been aborted. Basically the
client checks the deployment status at every state change.

I just tried it locally and I couldn't reproduce your problem, although
you're right that it did stay in the pending state for a couple of
minutes while the previous download completed.

--
Kristian

>>> dial tcp 10.224.172.137:443 <http://10.224.172.137:443>:

>>> <https://lh3.googleusercontent.com/-NmTmT_M5L_g/WpQnSNzGn5I/AAAAAAAADsU/Zdw6CBuV45YoMw_XOgd21fXe06bAkciLgCLcBGAs/s1600/mender_error.jpg>

>>> <http://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/

>>> <https://groups.google.com/a/lists.mender.io/group/mender/>.

>>
>> --
>> You received this message because you are subscribed to the

>> Google Groups "Mender List mender.io <http://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/

>> <https://groups.google.com/a/lists.mender.io/group/mender/>.

>
> --
> 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

> <mailto:mender+un...@lists.mender.io>.

> To post to this group, send email to men...@lists.mender.io

> <mailto:men...@lists.mender.io>.

[Cevat Bostancıoğlu]

it's been seven minutes, my test setup as follows:

- pkill mender(on device)

- mender --daemon --debug(on device, success certificates etc)

- send deployment from server(pending -> downloading)

- while in downloading state i abort deployment from server.

- my mender certificates are working without errors etc.

- my mender example scripts as follows(i writed every script for every state but just few of them showing in /etc/mender/scripts folder)  :

$ ls -all /etc/mender/scripts

total 40

drwxr-xr-x 2 root root 4096 Feb 26 14:02 .

drwxr-xr-x 3 root root 4096 Feb 26 18:11 ..

-rwxr-xr-x 1 root root   65 Feb 12 07:49 Download_Enter_00

-rwxr-xr-x 1 root root   65 Feb 12 07:49 Download_Error_00

-rwxr-xr-x 1 root root   65 Feb 12 07:49 Download_Leave_00

-rwxr-xr-x 1 root root   65 Feb 12 07:49 Idle_Enter_00

-rwxr-xr-x 1 root root   65 Feb 12 07:49 Idle_Leave_00

-rwxr-xr-x 1 root root   65 Feb 12 07:49 Sync_Enter_00

-rwxr-xr-x 1 root root   65 Feb 12 07:49 Sync_Leave_00

-rw-r--r-- 1 root root    1 Feb 12 07:49 version

cat /etc/mender/scripts/Download_Enter_00

#!/bin/sh

MAPFILE="/tmp/updateState.file"

echo "30" > $MAPFILE

so all other scripts is like that. they are just writing their uniqe number to some file. that file is just reading from another program. i closed that program so no ones reading that. that file is not reading with fifo or something like blocking.

so i tried again and wait like 8-10 minutes but nothing happened. 

i also tried with moving /etc/mender/scripts folder to /etc/mender/scripts_ so scripts are disabled. but still have freezing issue.

DEBU[0000] Reading Mender configuration from file /etc/mender/mender.conf  module=config

DEBU[0000] block type: RSA PRIVATE KEY                   module=keystore

INFO[0000] State transition: init [none] -> init [none]  module=mender

DEBU[0000] no state data stored                          module=state

INFO[0000] State transition: init [none] -> idle [Idle]  module=mender

INFO[0000] authorization data present and valid          module=mender

INFO[0000] State transition: idle [Idle] -> check-wait [Idle]  module=mender

DEBU[0000] handle check wait state                       module=state

DEBU[0000] check wait state; next checks: (update: 0001-01-01 00:00:05 +0000 UTC) (inventory: 0001-01-01 00:00:00 +0000 UTC)  module=state

DEBU[0000] next check: 0001-01-01 00:00:00 +0000 UTC:&{{4 2}}, (2018-02-27 18:16:47.628312792 +0000 UTC)  module=state

DEBU[0000] check wait returned: &{{4 2}}                 module=state

INFO[0000] State transition: check-wait [Idle] -> inventory-update [Sync]  module=mender

DEBU[0000] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0000] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0000] Current manifest data: raspberrypi3           module=mender

DEBU[0000] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0000] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0000] Current manifest data: D_v03.00.02            module=mender

DEBU[0000] inventory update sent, response &{200 OK 200 HTTP/2.0 2 0 map[X-Inventory-Version:[unknown] X-Frame-Options:[DENY] X-Content-Type-Options:[nosniff] Cache-Control:[no-cache, no-store] Server:         [openresty/1.13.6.1] Content-Type:[application/json; charset=utf-8] Vary:[Accept-Encoding] X-Men-Requestid:[d2e8e42e-f8a3-4c9e-aa6a-6b0914dd44f2] Strict-Transport-Security:[max-age=63072000; includeSub         domains; preload] X-Xss-Protection:[1; mode=block] Date:[Tue, 27 Feb 2018 15:17:45 GMT] Pragma:[no-cache]] 0x109df3c0 -1 [] false false map[] 0x1095eb80 0x109d5f80}  module=client_inventory

DEBU[0000] inventory refresh complete                    module=state

INFO[0000] State transition: inventory-update [Sync] -> check-wait [Idle]  module=mender

DEBU[0000] handle check wait state                       module=state

DEBU[0000] check wait state; next checks: (update: 0001-01-01 00:00:05 +0000 UTC) (inventory: 2018-02-27 18:16:52.630520552 +0000 UTC)  module=state

DEBU[0000] next check: 0001-01-01 00:00:05 +0000 UTC:&{{6 2}}, (2018-02-27 18:16:47.798853365 +0000 UTC)  module=state

DEBU[0000] check wait returned: &{{6 2}}                 module=state

INFO[0000] State transition: check-wait [Idle] -> update-check [Sync]  module=mender

DEBU[0000] handle update check state                     module=state

DEBU[0000] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0000] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0000] Current manifest data: D_v03.00.02            module=mender

DEBU[0000] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0000] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0000] Current manifest data: raspberrypi3           module=mender

DEBU[0000] Received response:204 No Content              module=client_update

DEBU[0000] No update available                           module=client_update

DEBU[0000] no updates available                          module=mender

INFO[0000] State transition: update-check [Sync] -> check-wait [Idle]  module=mender

DEBU[0000] handle check wait state                       module=state

DEBU[0000] check wait state; next checks: (update: 2018-02-27 18:16:52.799755084 +0000 UTC) (inventory: 2018-02-27 18:16:52.630520552 +0000 UTC)  module=state

DEBU[0000] next check: 2018-02-27 18:16:52.630520552 +0000 UTC:&{{4 2}}, (2018-02-27 18:16:47.854023938 +0000 UTC)  module=state

DEBU[0000] waiting 4.776496614s for the next state       module=state

DEBU[0005] wait complete                                 module=state

INFO[0005] State transition: check-wait [Idle] -> inventory-update [Sync]  module=mender

DEBU[0005] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0005] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0005] Current manifest data: raspberrypi3           module=mender

DEBU[0005] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0005] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0005] Current manifest data: D_v03.00.02            module=mender

DEBU[0005] inventory update sent, response &{200 OK 200 HTTP/2.0 2 0 map[Date:[Tue, 27 Feb 2018 15:17:50 GMT] Vary:[Accept-Encoding] X-Frame-Options:[DENY] X-Content-Type-Options:[nosniff] Cache-Contro         l:[no-cache, no-store] Pragma:[no-cache] X-Men-Requestid:[2a61f7f4-6623-4941-91ab-2f909858e8a1] Content-Type:[application/json; charset=utf-8] X-Inventory-Version:[unknown] X-Xss-Protection:[1; mode=bl         ock] Server:[openresty/1.13.6.1] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload]] 0x10aa2590 -1 [] false false map[] 0x109fea00 0x109d5f80}  module=client_inventory

DEBU[0005] inventory refresh complete                    module=state

INFO[0005] State transition: inventory-update [Sync] -> check-wait [Idle]  module=mender

DEBU[0005] handle check wait state                       module=state

DEBU[0005] check wait state; next checks: (update: 2018-02-27 18:16:52.799755084 +0000 UTC) (inventory: 2018-02-27 18:16:57.631902998 +0000 UTC)  module=state

DEBU[0005] next check: 2018-02-27 18:16:52.799755084 +0000 UTC:&{{6 2}}, (2018-02-27 18:16:52.729390082 +0000 UTC)  module=state

DEBU[0005] waiting 70.365002ms for the next state        module=state

DEBU[0005] wait complete                                 module=state

INFO[0005] State transition: check-wait [Idle] -> update-check [Sync]  module=mender

DEBU[0005] handle update check state                     module=state

DEBU[0005] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0005] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0005] Current manifest data: D_v03.00.02            module=mender

DEBU[0005] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0005] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0005] Current manifest data: raspberrypi3           module=mender

DEBU[0005] Received response:204 No Content              module=client_update

DEBU[0005] No update available                           module=client_update

DEBU[0005] no updates available                          module=mender

INFO[0005] State transition: update-check [Sync] -> check-wait [Idle]  module=mender

DEBU[0005] handle check wait state                       module=state

DEBU[0005] check wait state; next checks: (update: 2018-02-27 18:16:57.80109305 +0000 UTC) (inventory: 2018-02-27 18:16:57.631902998 +0000 UTC)  module=state

DEBU[0005] next check: 2018-02-27 18:16:57.631902998 +0000 UTC:&{{4 2}}, (2018-02-27 18:16:52.81282055 +0000 UTC)  module=state

DEBU[0005] waiting 4.819082448s for the next state       module=state

DEBU[0010] wait complete                                 module=state

INFO[0010] State transition: check-wait [Idle] -> inventory-update [Sync]  module=mender

DEBU[0010] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0010] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0010] Current manifest data: raspberrypi3           module=mender

DEBU[0010] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0010] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0010] Current manifest data: D_v03.00.02            module=mender

DEBU[0010] inventory update sent, response &{200 OK 200 HTTP/2.0 2 0 map[Server:[openresty/1.13.6.1] Vary:[Accept-Encoding] X-Men-Requestid:[43829d89-ed92-45f0-892a-39b25115f6a9] Strict-Transport-Secur         ity:[max-age=63072000; includeSubdomains; preload] X-Frame-Options:[DENY] Date:[Tue, 27 Feb 2018 15:17:55 GMT] X-Xss-Protection:[1; mode=block] Cache-Control:[no-cache, no-store] Pragma:[no-cache] Cont         ent-Type:[application/json; charset=utf-8] X-Inventory-Version:[unknown] X-Content-Type-Options:[nosniff]] 0x10a06170 -1 [] false false map[] 0x109fed80 0x109d5f80}  module=client_inventory

DEBU[0010] inventory refresh complete                    module=state

INFO[0010] State transition: inventory-update [Sync] -> check-wait [Idle]  module=mender

DEBU[0010] handle check wait state                       module=state

DEBU[0010] check wait state; next checks: (update: 2018-02-27 18:16:57.80109305 +0000 UTC) (inventory: 2018-02-27 18:17:02.633229038 +0000 UTC)  module=state

DEBU[0010] next check: 2018-02-27 18:16:57.80109305 +0000 UTC:&{{6 2}}, (2018-02-27 18:16:57.72744133 +0000 UTC)  module=state

DEBU[0010] waiting 73.65172ms for the next state         module=state

DEBU[0010] wait complete                                 module=state

INFO[0010] State transition: check-wait [Idle] -> update-check [Sync]  module=mender

DEBU[0010] handle update check state                     module=state

DEBU[0010] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0010] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0010] Current manifest data: D_v03.00.02            module=mender

DEBU[0010] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0010] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0010] Current manifest data: raspberrypi3           module=mender

DEBU[0010] Received response:204 No Content              module=client_update

DEBU[0010] No update available                           module=client_update

DEBU[0010] no updates available                          module=mender

INFO[0010] State transition: update-check [Sync] -> check-wait [Idle]  module=mender

DEBU[0010] handle check wait state                       module=state

DEBU[0010] check wait state; next checks: (update: 2018-02-27 18:17:02.802790601 +0000 UTC) (inventory: 2018-02-27 18:17:02.633229038 +0000 UTC)  module=state

DEBU[0010] next check: 2018-02-27 18:17:02.633229038 +0000 UTC:&{{4 2}}, (2018-02-27 18:16:57.818957632 +0000 UTC)  module=state

DEBU[0010] waiting 4.814271406s for the next state       module=state

DEBU[0015] wait complete                                 module=state

INFO[0015] State transition: check-wait [Idle] -> inventory-update [Sync]  module=mender

DEBU[0015] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0015] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0015] Current manifest data: raspberrypi3           module=mender

DEBU[0015] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0015] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0015] Current manifest data: D_v03.00.02            module=mender

DEBU[0015] inventory update sent, response &{200 OK 200 HTTP/2.0 2 0 map[X-Frame-Options:[DENY] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload] Content-Type:[application/json;          charset=utf-8] Vary:[Accept-Encoding] X-Inventory-Version:[unknown] X-Men-Requestid:[9d5e9f23-a3b1-4892-8615-5d30ec3d1199] X-Xss-Protection:[1; mode=block] Cache-Control:[no-cache, no-store] X-Content-         Type-Options:[nosniff] Pragma:[no-cache] Server:[openresty/1.13.6.1] Date:[Tue, 27 Feb 2018 15:18:00 GMT]] 0x10a07410 -1 [] false false map[] 0x109f0480 0x109d5f80}  module=client_inventory

DEBU[0015] inventory refresh complete                    module=state

INFO[0015] State transition: inventory-update [Sync] -> check-wait [Idle]  module=mender

DEBU[0015] handle check wait state                       module=state

DEBU[0015] check wait state; next checks: (update: 2018-02-27 18:17:02.802790601 +0000 UTC) (inventory: 2018-02-27 18:17:07.634667161 +0000 UTC)  module=state

DEBU[0015] next check: 2018-02-27 18:17:02.802790601 +0000 UTC:&{{6 2}}, (2018-02-27 18:17:02.738417005 +0000 UTC)  module=state

DEBU[0015] waiting 64.373596ms for the next state        module=state

DEBU[0015] wait complete                                 module=state

INFO[0015] State transition: check-wait [Idle] -> update-check [Sync]  module=mender

DEBU[0015] handle update check state                     module=state

DEBU[0015] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0015] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0015] Current manifest data: D_v03.00.02            module=mender

DEBU[0015] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0015] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0015] Current manifest data: raspberrypi3           module=mender

DEBU[0015] Received response:204 No Content              module=client_update

DEBU[0015] No update available                           module=client_update

DEBU[0015] no updates available                          module=mender

INFO[0015] State transition: update-check [Sync] -> check-wait [Idle]  module=mender

DEBU[0015] handle check wait state                       module=state

DEBU[0015] check wait state; next checks: (update: 2018-02-27 18:17:07.804401015 +0000 UTC) (inventory: 2018-02-27 18:17:07.634667161 +0000 UTC)  module=state

DEBU[0015] next check: 2018-02-27 18:17:07.634667161 +0000 UTC:&{{4 2}}, (2018-02-27 18:17:02.889790599 +0000 UTC)  module=state

DEBU[0015] waiting 4.744876562s for the next state       module=state

DEBU[0020] wait complete                                 module=state

INFO[0020] State transition: check-wait [Idle] -> inventory-update [Sync]  module=mender

DEBU[0020] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0020] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0020] Current manifest data: raspberrypi3           module=mender

DEBU[0020] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0020] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0020] Current manifest data: D_v03.00.02            module=mender

DEBU[0020] inventory update sent, response &{200 OK 200 HTTP/2.0 2 0 map[Vary:[Accept-Encoding] X-Frame-Options:[DENY] Content-Type:[application/json; charset=utf-8] Strict-Transport-Security:[max-age=         63072000; includeSubdomains; preload] X-Xss-Protection:[1; mode=block] Cache-Control:[no-cache, no-store] Server:[openresty/1.13.6.1] Date:[Tue, 27 Feb 2018 15:18:05 GMT] X-Inventory-Version:[unknown]          X-Content-Type-Options:[nosniff] Pragma:[no-cache] X-Men-Requestid:[587387dd-4464-414e-a842-993165ff9b1c]] 0x1070c930 -1 [] false false map[] 0x1070a400 0x109d5f80}  module=client_inventory

DEBU[0020] inventory refresh complete                    module=state

INFO[0020] State transition: inventory-update [Sync] -> check-wait [Idle]  module=mender

DEBU[0020] handle check wait state                       module=state

DEBU[0020] check wait state; next checks: (update: 2018-02-27 18:17:07.804401015 +0000 UTC) (inventory: 2018-02-27 18:17:12.636210336 +0000 UTC)  module=state

DEBU[0020] next check: 2018-02-27 18:17:07.804401015 +0000 UTC:&{{6 2}}, (2018-02-27 18:17:07.732863149 +0000 UTC)  module=state

DEBU[0020] waiting 71.537866ms for the next state        module=state

DEBU[0020] wait complete                                 module=state

INFO[0020] State transition: check-wait [Idle] -> update-check [Sync]  module=mender

DEBU[0020] handle update check state                     module=state

DEBU[0020] Read data from device manifest file: artifact_name=D_v03.00.02  module=mender

DEBU[0020] Found needed line: artifact_name=D_v03.00.02  module=mender

DEBU[0020] Current manifest data: D_v03.00.02            module=mender

DEBU[0020] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0020] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0020] Current manifest data: raspberrypi3           module=mender

DEBU[0020] Received response:200 OK                      module=client_update

DEBU[0020] Have update available                         module=client_update

INFO[0020] Correct request for getting image from: https://s3.docker.mender.io:9000/mender-artifact-storage/79ba21cc-fff9-4cdf-92c5-e9eaf54e3380?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=minio%         2F20180227%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20180227T151805Z&X-Amz-Expires=3600&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=0af26db204d55c         fb190e6acfeb240415aefb11dac2183f62bd8d177fa12aca3f [name: 0x200b34; devices: [raspberrypi3]]  module=client_update

DEBU[0020] received update response: {{{https://s3.docker.mender.io:9000/mender-artifact-storage/79ba21cc-fff9-4cdf-92c5-e9eaf54e3380?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=minio%2F20180227%         2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20180227T151805Z&X-Amz-Expires=3600&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=0af26db204d55cfb190e6acfe         b240415aefb11dac2183f62bd8d177fa12aca3f 2018-02-27T16:18:05.657602825Z} [raspberrypi3] D_v03.00.03} 8a0e25cc-f21d-4fbb-8185-2b9f77f915b8}  module=mender

INFO[0020] State transition: update-check [Sync] -> update-fetch [Download]  module=mender

DEBU[0020] handle update fetch state                     module=state

DEBU[0020] status reported, response &{204 No Content 204 HTTP/2.0 2 0 map[X-Deployments-Version:[unknown] X-Men-Requestid:[82365105-a213-49a2-9e51-46bba59ca1a0] Strict-Transport-Security:[max-age=6307         2000; includeSubdomains; preload] X-Frame-Options:[DENY] Pragma:[no-cache] Cache-Control:[no-cache, no-store] Server:[openresty/1.13.6.1] Date:[Tue, 27 Feb 2018 15:18:05 GMT] Content-Encoding:[gzip] Va         ry:[Accept-Encoding] X-Content-Type-Options:[nosniff] X-Xss-Protection:[1; mode=block]] 0x10aa3f70 0 [] false false map[] 0x109fef00 0x109d5f80}  module=client_status

DEBU[0020] Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[Accept-Ranges:[bytes] Etag:["b675578b3e08c6fc9c6f8b834c93d046"] Server:[openresty/1.11.2.2] X-Amz-Request-Id:[5NRUJJOLZ0S2NS47] X         -Frame-Options:[DENY] X-Content-Type-Options:[nosniff] Connection:[keep-alive] Last-Modified:[Mon, 26 Feb 2018 14:41:40 GMT] Vary:[Origin] Date:[Tue, 27 Feb 2018 15:18:05 GMT] Content-Type:[application         /vnd.mender-artifact] Content-Length:[127592448] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload]] 0x109de0c0 127592448 [] false false map[] 0x109ff000 0x10b544e0}+  module=clie         nt_update

INFO[0020] State transition: update-fetch [Download] -> update-store [Download]  module=mender

DEBU[0020] handle update install state                   module=state

DEBU[0020] status reported, response &{204 No Content 204 HTTP/2.0 2 0 map[Pragma:[no-cache] Server:[openresty/1.13.6.1] X-Deployments-Version:[unknown] X-Men-Requestid:[ec5186fb-4c9c-4c04-bcf0-2ecbe06         72360] X-Content-Type-Options:[nosniff] X-Frame-Options:[DENY] X-Xss-Protection:[1; mode=block] Cache-Control:[no-cache, no-store] Date:[Tue, 27 Feb 2018 15:18:05 GMT] Content-Encoding:[gzip] Vary:[Acc         ept-Encoding] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload]] 0x109de940 0 [] false false map[] 0x10760b00 0x109d5f80}  module=client_status

DEBU[0020] Read data from device manifest file: device_type=raspberrypi3  module=mender

DEBU[0020] Found needed line: device_type=raspberrypi3   module=mender

DEBU[0020] Current manifest data: raspberrypi3           module=mender

DEBU[0020] checking if device [raspberrypi3] is on compatibile device list: [raspberrypi3]

  module=installer

DEBU[0020] installing update rpi-basic-image-raspberrypi3.ext4 of size 947912704  module=installer

DEBU[0020] Trying to install update of size: 947912704   module=device

DEBU[0020] Have U-Boot variable: mender_boot_part=2      module=bootenv

DEBU[0020] List of U-Boot variables:map[mender_boot_part:2]  module=bootenv

DEBU[0020] Setting active partition from mount candidate: /dev/mmcblk0p2  module=partitions

DEBU[0020] Detected inactive partition /dev/mmcblk0p3, based on active partition /dev/mmcblk0p2  module=partitions

INFO[0020] opening device /dev/mmcblk0p3 for writing     module=block_device

INFO[0020] partition /dev/mmcblk0p3 size: 947912704      module=block_device

[   89.978932] random: crng init done

[Kristian Amlie]

And what is the last number in the file? 30 from Download_Enter?

> so i tried again and wait like 8-10 minutes but nothing happened. 
>
> i also tried with moving /etc/mender/scripts folder to
> /etc/mender/scripts_ so scripts are disabled. but still have freezing issue.
>

> ...

From the looks of it, Mender is still writing.

Here is something you can check: While you are waiting, run:

ls -l /proc/`pgrep mender`/fd

You should be able to identify the file descriptor that Mender has open
for writing to the partition. Once you know which one, run:

cat /proc/`pgrep mender`/fdinfo/<FD>

There should be a field, "pos", in that file, which tells you at what
position Mender is in the writing. This number should be increasing
steadily, approaching the size of the partition. If it's not, then there
is something seriously wrong, and we will need to investigate that.

If it is increasing, then at least you get some understanding of how
long the process will take, since it is very dependent on both partition
size and storage speed.

--
Kristian

[Cevat Bostancıoğlu]

-- Yes 30 from Download_Enter and Download_Leave. Every state has a value in my system. Errors and Aborts are State*10 + 1, if something happened in download i should see 31 in file etc.

-- i will check that fd issues and let you know. 

Thank you.

[Hasan MEN]

Hi. I had the same problem. Mender try to running scripts according to value which is StateScriptTimeoutSeconds from "/etc/mender/mender.conf". On each fails it waits up to "StateScriptRetryTimeoutSeconds": 3 sec and when   "StateScriptTimeoutSeconds": 180 sec done, mender runs your Download_error and then runs Sync, Idle Enter scripts. Actually mender did not freeze, it just tried to download again and again. If you reduce TimeoutSeconds you will see your changes.

26 Şubat 2018 Pazartesi 18:06:43 UTC+3 tarihinde Cevat Bostancıoğlu yazdı:

[Cevat Bostancıoğlu]

I solved problem. Thank you Hasan. You saved my day. God bless you.

[Aurélien]

Also note that in the very worse case there is a 4 hours timeout in the source code: https://github.com/mendersoftware/mender/blob/6046a8c/client/client.go#L59

Whatever happens, if downloading a mender artifact takes more than 4 hours, mender would abort and go back to normal.