[MEN-1854] HTTP error 401 is not handled by all states - Northern.tech AS

XML

Word

Printable

Details

Type: Bug
Status: Done
Priority: Medium
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.5.0
Labels:
- Client
- Part
Environment:
Yocto Rocko + mender client 1.4.0

Sprint:
MEN Sprint 62
Backlog:
yes

Description

We have been performing some tests on Mender and came across something
"problematic" (edge case really but still) and wanted to bring it to
your attention.

I wanted to highlight following from the Mender docs regarding the JWT.

"The token does have an expiry date (one week period), but the Mender
client will obtain a fresh token automatically; the process is
transparent to the user. The only prerequisite is that the device's
authentication set has not been explicitly rejected in the meantime
via the Device Admission API."

We came across this using a much shorter expire time but it is still
valid I believe.

In the case of an expired JWT token, we have observed that it is only
refreshed from the "update-check" state. Which results in that IF the
JWT token expires after a started update the update will FAIL.

Note that HTTP error 401 is returned multiple times (unauthorized) but
the client ignores it and only handles it during the update-check
state.

Here is a log (some masked data but should be read-able).

NOTE that I forced booting my target part to get the full log
after it did a rollback (because the JWT token was expired and not
renewed during the report-status states).

Mar 28 13:15:08 hostname systemd[1]: Started Mender OTA update service.
< masked Certificates >
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=info msg="Issuer: [], Valid from: 2017-09-21 14:05:54 +0000 UTC, Valid to: 2027-09-19 14:05:54 +0000 UTC" module=client
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=info msg="State transition: init [none] -> init [none]" module=mender
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=info msg="handling loaded state: update-status-report" module=state
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=error msg="got invalid state: update-status-report" module=state
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=info msg="State transition: init [none] -> update-error [ArtifactFailure]" module=mender
Mar 28 13:15:08 hostname mender[352]: level=info msg="State transition: init [none] -> init [none]" module=mender
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=info msg="State transition: update-error [ArtifactFailure] -> update-status-report [none]" module=mender
Mar 28 13:15:08 hostname mender[352]: level=info msg="handling loaded state: update-status-report" module=state
Mar 28 13:15:08 hostname mender[352]: level=error msg="got invalid state: update-status-report" module=state
Mar 28 13:15:08 hostname mender[352]: level=info msg="State transition: init [none] -> update-error [ArtifactFailure]" module=mender
Mar 28 13:15:08 hostname mender[352]: level=info msg="State transition: update-error [ArtifactFailure] -> update-status-report [none]" module=mender
Mar 28 13:15:08 hostname mender[352]: level=error msg="got unexpected HTTP status when reporting status: 401" module="client_status"
Mar 28 13:15:08 hostname mender[352]: level=error msg="error reporting update status: reporting status failed, bad status 401" module=mender
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=error msg="got unexpected HTTP status when reporting status: 401" module="client_status"
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=error msg="error reporting update status: reporting status failed, bad status 401" module=mender
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=error msg="failed to send status to server: transient error: reporting status failed, bad status 401" module=state
Mar 28 13:15:08 hostname mender[352]: time="2018-03-28T13:15:08Z" level=info msg="State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]" module=mender
Mar 28 13:15:08 hostname mender[352]: level=error msg="failed to send status to server: transient error: reporting status failed, bad status 401" module=state
Mar 28 13:15:08 hostname mender[352]: level=info msg="State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]" module=mender
Mar 28 13:15:18 hostname mender[352]: level=info msg="State transition: update-retry-report [ArtifactFailure] -> update-status-report [ArtifactFailure]" module=mender
Mar 28 13:15:18 hostname mender[352]: time="2018-03-28T13:15:18Z" level=info msg="State transition: update-retry-report [ArtifactFailure] -> update-status-report [ArtifactFailure]" module=mender
Mar 28 13:15:19 hostname mender[352]: level=error msg="got unexpected HTTP status when reporting status: 401" module="client_status"
Mar 28 13:15:19 hostname mender[352]: level=error msg="error reporting update status: reporting status failed, bad status 401" module=mender
Mar 28 13:15:19 hostname mender[352]: time="2018-03-28T13:15:19Z" level=error msg="got unexpected HTTP status when reporting status: 401" module="client_status"
Mar 28 13:15:19 hostname mender[352]: time="2018-03-28T13:15:19Z" level=error msg="error reporting update status: reporting status failed, bad status 401" module=mender
Mar 28 13:15:19 hostname mender[352]: time="2018-03-28T13:15:19Z" level=error msg="failed to send status to server: transient error: reporting status failed, bad status 401" module=state
Mar 28 13:15:19 hostname mender[352]: time="2018-03-28T13:15:19Z" level=info msg="State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]" module=mender
Mar 28 13:15:19 hostname mender[352]: level=error msg="failed to send status to server: transient error: reporting status failed, bad status 401" module=state
Mar 28 13:15:19 hostname mender[352]: level=info msg="State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]" module=mender
Mar 28 13:15:29 hostname mender[352]: level=info msg="State transition: update-retry-report [ArtifactFailure] -> update-status-report [ArtifactFailure]" module=mender
Mar 28 13:15:29 hostname mender[352]: time="2018-03-28T13:15:29Z" level=info msg="State transition: update-retry-report [ArtifactFailure] -> update-status-report [ArtifactFailure]" module=mender
Mar 28 13:15:29 hostname mender[352]: level=error msg="got unexpected HTTP status when reporting status: 401" module="client_status"
Mar 28 13:15:29 hostname mender[352]: level=error msg="error reporting update status: reporting status failed, bad status 401" module=mender
Mar 28 13:15:29 hostname mender[352]: time="2018-03-28T13:15:29Z" level=error msg="got unexpected HTTP status when reporting status: 401" module="client_status"
Mar 28 13:15:29 hostname mender[352]: time="2018-03-28T13:15:29Z" level=error msg="error reporting update status: reporting status failed, bad status 401" module=mender
Mar 28 13:15:29 hostname mender[352]: time="2018-03-28T13:15:29Z" level=error msg="failed to send status to server: transient error: reporting status failed, bad status 401" module=state
Mar 28 13:15:29 hostname mender[352]: time="2018-03-28T13:15:29Z" level=info msg="State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]" module=mender
Mar 28 13:15:29 hostname mender[352]: level=error msg="failed to send status to server: transient error: reporting status failed, bad status 401" module=state
Mar 28 13:15:29 hostname mender[352]: level=info msg="State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: update-retry-report [ArtifactFailure] -> update-status-report [ArtifactFailure]" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: update-retry-report [ArtifactFailure] -> update-status-report [ArtifactFailure]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=error msg="got unexpected HTTP status when reporting status: 401" module="client_status"
Mar 28 13:15:39 hostname mender[352]: level=error msg="error reporting update status: reporting status failed, bad status 401" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=error msg="got unexpected HTTP status when reporting status: 401" module="client_status"
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=error msg="error reporting update status: reporting status failed, bad status 401" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=error msg="failed to send status to server: transient error: reporting status failed, bad status 401" module=state
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: update-retry-report [ArtifactFailure] -> status-report-error [ArtifactFailure]" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=error msg="handling report error state with status: failure" module=state
Mar 28 13:15:39 hostname mender[352]: level=error msg="failed to send status to server: transient error: reporting status failed, bad status 401" module=state
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=error msg="error while performing update: failure (<masked URL>)" module=state
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: status-report-error [ArtifactFailure] -> idle [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="authorization data present and valid" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: update-retry-report [ArtifactFailure] -> status-report-error [ArtifactFailure]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=error msg="handling report error state with status: failure" module=state
Mar 28 13:15:39 hostname mender[352]: level=error msg="error while performing update: failure (<masked URL>)" module=state
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: status-report-error [ArtifactFailure] -> idle [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="authorization data present and valid" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=error msg="got unexpected HTTP status when submitting to inventory: 401" module="client_inventory"
Mar 28 13:15:39 hostname mender[352]: level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 401" module=state
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=error msg="got unexpected HTTP status when submitting to inventory: 401" module="client_inventory"
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 401" module=state
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=warning msg="Client not authorized to get update schedule." module="client_update"
Mar 28 13:15:39 hostname mender[352]: level=error msg="Error receiving scheduled update data: client not authorized" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=warning msg="Client not authorized to get update schedule." module="client_update"
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=error msg="Error receiving scheduled update data: client not authorized" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=error msg="update check failed: transient error: client not authorized" module=state
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: update-check [Sync] -> error [Error]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=error msg="update check failed: transient error: client not authorized" module=state
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="handling error state, current error: transient error: client not authorized" module=state
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: error [Error] -> idle [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: idle [Idle] -> authorize [Sync]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: update-check [Sync] -> error [Error]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="handling error state, current error: transient error: client not authorized" module=state
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: error [Error] -> idle [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: idle [Idle] -> authorize [Sync]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="successfuly received new authorization data" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="successfuly received new authorization data" module=mender
Mar 28 13:15:39 hostname mender[352]: time="2018-03-28T13:15:39Z" level=info msg="State transition: authorize [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:39 hostname mender[352]: level=info msg="State transition: authorize [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:49 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:15:49 hostname mender[352]: time="2018-03-28T13:15:49Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:15:49 hostname mender[352]: level=error msg="got unexpected HTTP status when submitting to inventory: 500" module="client_inventory"
Mar 28 13:15:49 hostname mender[352]: level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 500" module=state
Mar 28 13:15:49 hostname mender[352]: time="2018-03-28T13:15:49Z" level=error msg="got unexpected HTTP status when submitting to inventory: 500" module="client_inventory"
Mar 28 13:15:49 hostname mender[352]: time="2018-03-28T13:15:49Z" level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 500" module=state
Mar 28 13:15:49 hostname mender[352]: time="2018-03-28T13:15:49Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:49 hostname mender[352]: time="2018-03-28T13:15:49Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:15:49 hostname mender[352]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:49 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:15:49 hostname mender[352]: level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:49 hostname mender[352]: time="2018-03-28T13:15:49Z" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:59 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:15:59 hostname mender[352]: time="2018-03-28T13:15:59Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:15:59 hostname mender[352]: level=error msg="got unexpected HTTP status when submitting to inventory: 500" module="client_inventory"
Mar 28 13:15:59 hostname mender[352]: level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 500" module=state
Mar 28 13:15:59 hostname mender[352]: time="2018-03-28T13:15:59Z" level=error msg="got unexpected HTTP status when submitting to inventory: 500" module="client_inventory"
Mar 28 13:15:59 hostname mender[352]: time="2018-03-28T13:15:59Z" level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 500" module=state
Mar 28 13:15:59 hostname mender[352]: time="2018-03-28T13:15:59Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:59 hostname mender[352]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:59 hostname mender[352]: time="2018-03-28T13:15:59Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:15:59 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:15:59 hostname mender[352]: level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:15:59 hostname mender[352]: time="2018-03-28T13:15:59Z" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:16:09 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:16:09 hostname mender[352]: time="2018-03-28T13:16:09Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:16:09 hostname mender[352]: level=error msg="got unexpected HTTP status when submitting to inventory: 500" module="client_inventory"
Mar 28 13:16:09 hostname mender[352]: level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 500" module=state
Mar 28 13:16:09 hostname mender[352]: time="2018-03-28T13:16:09Z" level=error msg="got unexpected HTTP status when submitting to inventory: 500" module="client_inventory"
Mar 28 13:16:09 hostname mender[352]: time="2018-03-28T13:16:09Z" level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 500" module=state
Mar 28 13:16:09 hostname mender[352]: time="2018-03-28T13:16:09Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:16:09 hostname mender[352]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:16:09 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:16:09 hostname mender[352]: time="2018-03-28T13:16:09Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:16:09 hostname mender[352]: level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:16:09 hostname mender[352]: time="2018-03-28T13:16:09Z" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:16:19 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Mar 28 13:16:19 hostname mender[352]: level=error msg="got unexpected HTTP status when submitting to inventory: 500" module="client_inventory"
Mar 28 13:16:19 hostname mender[352]: level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 500" module=state
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=error msg="got unexpected HTTP status when submitting to inventory: 500" module="client_inventory"
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=warning msg="failed to refresh inventory: failed to submit inventory data: inventory submit failed, bad status 500" module=state
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:16:19 hostname mender[352]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Mar 28 13:16:19 hostname mender[352]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Mar 28 13:16:19 hostname mender[352]: level=info msg="Correct request for getting image from: < masked URL> [name: 0x203be8; devices: [hostname]]" module="client_update"
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=info msg="Correct request for getting image from: < masked URL> [name: 0x203be8; devices: [hostname]]" module="client_update"
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=info msg="State transition: update-check [Sync] -> update-fetch [Download]" module=mender
Mar 28 13:16:19 hostname mender[352]: level=info msg="State transition: update-check [Sync] -> update-fetch [Download]" module=mender
Mar 28 13:16:19 hostname mender[352]: level=info msg="State transition: update-fetch [Download] -> update-store [Download]" module=mender
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=info msg="State transition: update-fetch [Download] -> update-store [Download]" module=mender
Mar 28 13:16:19 hostname mender[352]: level=info msg="opening device /dev/mmcblk2p2 for writing" module="block_device"
Mar 28 13:16:19 hostname mender[352]: level=info msg="partition /dev/mmcblk2p2 size: 1040187392" module="block_device"
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=info msg="opening device /dev/mmcblk2p2 for writing" module="block_device"
Mar 28 13:16:19 hostname mender[352]: time="2018-03-28T13:16:19Z" level=info msg="partition /dev/mmcblk2p2 size: 1040187392" module="block_device"
Mar 28 13:17:38 hostname systemd[1]: Stopping Mender OTA update service...
Mar 28 13:17:40 hostname systemd[1]: Stopped Mender OTA update service.

Attachments

Activity

People

Assignee:: Alf-Rune Siqveland

Reporter:: Mirza Krak

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 04/Apr/18 11:31 AM

Updated:: 29/May/18 11:39 AM

Resolved:: 29/May/18 11:39 AM