Mender Client Software Freezes after aborting deployment from deployment server

135 views
Skip to first unread message

Cevat Bostancıoğlu

unread,
Feb 26, 2018, 10:06:43 AM2/26/18
to Mender List mender.io
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

unread,
Feb 26, 2018, 10:11:51 AM2/26/18
to men...@lists.mender.io, Cevat Bostancıoğlu
Do you have the client logs from the device?

journalctl -u mender

--
Kristian

Cevat Bostancıoğlu

unread,
Feb 26, 2018, 10:27:09 AM2/26/18
to Mender List mender.io, ceva...@gmail.com

Cevat Bostancıoğlu

unread,
Feb 26, 2018, 10:35:32 AM2/26/18
to Mender List mender.io, ceva...@gmail.com
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

unread,
Feb 27, 2018, 4:28:54 AM2/27/18
to men...@lists.mender.io

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

unread,
Feb 27, 2018, 4:33:21 AM2/27/18
to Mender List mender.io
i am running in managed mode. 

Drew Moseley

unread,
Feb 27, 2018, 4:39:02 AM2/27/18
to men...@lists.mender.io

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

Drew

Cevat Bostancıoğlu

unread,
Feb 27, 2018, 4:58:19 AM2/27/18
to Mender List mender.io
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

unread,
Feb 27, 2018, 4:59:31 AM2/27/18
to Mender List mender.io
Server still can send updates but it is waiting in pending state. 

Kristian Amlie

unread,
Feb 27, 2018, 8:19:10 AM2/27/18
to men...@lists.mender.io, Cevat Bostancıoğlu
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

unread,
Feb 27, 2018, 10:21:22 AM2/27/18
to Mender List mender.io, ceva...@gmail.com
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

unread,
Feb 28, 2018, 3:00:28 AM2/28/18
to Cevat Bostancıoğlu, mender
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

unread,
Mar 1, 2018, 2:42:05 AM3/1/18
to Mender List mender.io, ceva...@gmail.com
-- 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

unread,
Mar 2, 2018, 6:05:13 AM3/2/18
to Mender List mender.io

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

unread,
Mar 2, 2018, 6:08:59 AM3/2/18
to Mender List mender.io
I solved problem. Thank you Hasan. You saved my day. God bless you.

Aurélien

unread,
Feb 14, 2019, 4:48:28 AM2/14/19
to Mender List mender.io
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. 
Reply all
Reply to author
Forward
0 new messages