Mender enterprise - client cannot update inventory

General Discussions
1

I’m trying to stand up an enterprise mender cluster for evaluation and I cannot get the mender client on a board to to update the inventory. I tried this with the config from 2.2.0b1 and now 2.2.0. I’m running this in kubernetes, but I follow the config from the integration repo carefully. We already run mender 2.0.0 in kubernetes without issue, and the 2.2.x install is totally isolated from 2.0.0.

A few notes about the config:

  • The mender-api-gateway and mender-gui are configured with HAVE_MULTITENANT=1 HAVE_ENTERPRISE=1.
  • DEVICEAUTH_DEFAULT_TENANT_TOKEN is unset because I created a tenant token with the first user and used that.
  • We used S3 instead of Minio.
  • I used the docker images from the 2.2.0b1 version of the integrations repo.
  • The device has been authorized in the GUI.

I’m able to make a user and a tenant org. I build and up-to-date client, install it on the board, and configure it to use the tenant token before it tries to connect. The client is able to register itself with the server, but when I run mender -send-inventory, it errors like so.

==> mender client <==
Oct 24 16:09:56 full-sierra mender[8557]: level=warning msg="failed to refresh inventory: failed to submit inventory data: (request_id: ): inventory submit failed, bad status 401 server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
Oct 24 16:09:56 full-sierra mender[8557]: time="2019-10-24T16:09:56-04:00" level=error msg="got unexpected HTTP status when submitting to inventory: 401" module=client_inventory
Oct 24 16:09:56 full-sierra mender[8557]: time="2019-10-24T16:09:56-04:00" level=warning msg="failed to refresh inventory: failed to submit inventory data: (request_id: ): inventory submit failed, bad status 401 server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
Oct 24 16:09:56 full-sierra mender[8557]: time="2019-10-24T16:09:56-04:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Oct 24 16:09:56 full-sierra mender[8557]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Oct 24 16:09:56 full-sierra mender[8557]: time="2019-10-24T16:09:56-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
Oct 24 16:09:56 full-sierra mender[8557]: time="2019-10-24T16:09:56-04:00" level=debug msg="handle check wait state" module=state
Oct 24 16:09:56 full-sierra mender[8557]: time="2019-10-24T16:09:56-04:00" level=debug msg="check wait state; next checks: (update: 2019-10-24 17:08:33.249501075 -0400 EDT m=+3600.689335887) (inventory: 2019-10-25 16:08:32.598446354 -0400 EDT m=+86400.038281246)" module=state
Oct 24 16:09:56 full-sierra mender[8557]: time="2019-10-24T16:09:56-04:00" level=debug msg="next check: 2019-10-24 17:08:33.249501075 -0400 EDT m=+3600.689335887:update-check, (2019-10-24 16:09:56.603186915 -0400 EDT m=+84.043021647)" module=state
Oct 24 16:09:56 full-sierra mender[8557]: time="2019-10-24T16:09:56-04:00" level=debug msg="waiting 58m36.64631424s for the next state" module=state

The following logs are all from the various services within the mendor cluster.

==> mender-device-auth <==
2019-10-24T19:58:10.625744335Z time="2019-10-24T19:58:10Z" level=error msg="Token ddd34ae7-ced1-4d4e-aac6-9f903260b0bd not found" device_id=5db0c90621b3a80001106e58 file=devauth.go func="devauth.(*DevAuth).VerifyToken" line=906 request_id=f52b59a7-3d55-45d9-a83f-11c8f955e3f8
2019-10-24T19:58:10.626012712Z time="2019-10-24T19:58:10Z" level=error msg="token not found" device_id=5db0c90621b3a80001106e58 file=api_devauth.go func="http.(*DevAuthApiHandlers).VerifyTokenHandler-fm" line=84 request_id=f52b59a7-3d55-45d9-a83f-11c8f955e3f8

==> mender-api-gateway <==
2019-10-24T19:58:10.585940908Z 10.52.8.25 - - [24/Oct/2019:19:58:10 +0000] "PATCH /api/devices/v1/inventory/device/attributes HTTP/1.1" 401 201 "-" "Go-http-client/1.1" "205.201.16.55" request ID "-" 0.008

==> mender-device-auth <==
2019-10-24T19:58:10.630690226Z time="2019-10-24T19:58:10Z" level=info msg="401 6421μs POST /api/internal/v1/devauth/tokens/verify HTTP/1.0 - Go-http-client/1.1" device_id=5db0c90621b3a80001106e58 file=middleware.go func="accesslog.(*AccessLogMiddleware).MiddlewareFunc.func1" line=60 request_id=f52b59a7-3d55-45d9-a83f-11c8f955e3f8
2019-10-24T19:58:11.06140592Z time="2019-10-24T19:58:11Z" level=warning msg="dev auth: unauthorized: dev auth: unauthorized" file=response_helpers.go func=rest_utils.RestErrWithWarningMsg line=55 request_id=b2dab429-6040-404f-8894-9e274a6e8f2b sub=5db1ff17512fb400101c5f84 tenant_id=5db1ff17512fb400101c5f84

==> mender-api-gateway <==
2019-10-24T19:58:11.021291935Z 10.52.8.25 - - [24/Oct/2019:19:58:11 +0000] "POST /api/devices/v1/authentication/auth_requests HTTP/1.1" 401 109 "-" "Go-http-client/1.1" "205.201.16.55" request ID "b2dab429-6040-404f-8894-9e274a6e8f2b" 0.035

==> mender-device-auth <==
2019-10-24T19:58:11.065654752Z time="2019-10-24T19:58:11Z" level=info msg="401 30713μs POST /api/devices/v1/authentication/auth_requests HTTP/1.0 - Go-http-client/1.1" file=middleware.go func="accesslog.(*AccessLogMiddleware).MiddlewareFunc.func1" line=60 request_id=b2dab429-6040-404f-8894-9e274a6e8f2b sub=5db1ff17512fb400101c5f84 tenant_id=5db1ff17512fb400101c5f84
2019-10-24T19:58:11.097756604Z time="2019-10-24T19:58:11Z" level=warning msg="Failed to extract identity from header: malformed authorization data" file=middleware.go func="identity.(*IdentityMiddleware).MiddlewareFunc.func1" line=47 request_id=7df2f7e1-6d8f-4090-9296-4a460c14fcab

==> mender-api-gateway <==
2019-10-24T19:58:11.053713335Z 10.52.8.25 - - [24/Oct/2019:19:58:11 +0000] "GET /api/devices/v1/deployments/device/deployments/next?artifact_name=nightly-development-20190827T044701Z&device_type=trident HTTP/1.1" 401 201 "-" "Go-http-client/1.1" "205.201.16.55" request ID "-" 0.002

==> mender-device-auth <==
2019-10-24T19:58:11.097808685Z time="2019-10-24T19:58:11Z" level=error msg="Token  invalid: token contains an invalid number of segments" file=devauth.go func="devauth.(*DevAuth).VerifyToken" line=889 request_id=7df2f7e1-6d8f-4090-9296-4a460c14fcab
2019-10-24T19:58:11.0978149Z time="2019-10-24T19:58:11Z" level=error msg="jwt: token invalid" file=api_devauth.go func="http.(*DevAuthApiHandlers).VerifyTokenHandler-fm" line=84 request_id=7df2f7e1-6d8f-4090-9296-4a460c14fcab
2019-10-24T19:58:11.097819348Z time="2019-10-24T19:58:11Z" level=info msg="401 184μs POST /api/internal/v1/devauth/tokens/verify HTTP/1.0 - Go-http-client/1.1" file=middleware.go func="accesslog.(*AccessLogMiddleware).MiddlewareFunc.func1" line=60 request_id=7df2f7e1-6d8f-4090-9296-4a460c14fcab
2019-10-24T19:58:11.408095071Z time="2019-10-24T19:58:11Z" level=warning msg="dev auth: unauthorized: dev auth: unauthorized" file=response_helpers.go func=rest_utils.RestErrWithWarningMsg line=55 request_id=cba4b4e9-0193-4207-9cd0-2facdc9c0338 sub=5db1ff17512fb400101c5f84 tenant_id=5db1ff17512fb400101c5f84

==> mender-api-gateway <==
2019-10-24T19:58:11.366537159Z 10.52.8.25 - - [24/Oct/2019:19:58:11 +0000] "POST /api/devices/v1/authentication/auth_requests HTTP/1.1" 401 110 "-" "Go-http-client/1.1" "205.201.16.55" request ID "cba4b4e9-0193-4207-9cd0-2facdc9c0338" 0.028

==> mender-device-auth <==
2019-10-24T19:58:11.411806524Z time="2019-10-24T19:58:11Z" level=info msg="401 24487μs POST /api/devices/v1/authentication/auth_requests HTTP/1.0 - Go-http-client/1.1" file=middleware.go func="accesslog.(*AccessLogMiddleware).MiddlewareFunc.func1" line=60 request_id=cba4b4e9-0193-4207-9cd0-2facdc9c0338 sub=5db1ff17512fb400101c5f84 tenant_id=5db1ff17512fb400101c5f84
2019-10-24T19:58:11.724666818Z time="2019-10-24T19:58:11Z" level=warning msg="dev auth: unauthorized: dev auth: unauthorized" file=response_helpers.go func=rest_utils.RestErrWithWarningMsg line=55 request_id=9a9fc528-76e8-4c2c-b007-381fb5a437c5 sub=5db1ff17512fb400101c5f84 tenant_id=5db1ff17512fb400101c5f84
2019-10-24T19:58:11.72840468Z time="2019-10-24T19:58:11Z" level=info msg="401 23180μs POST /api/devices/v1/authentication/auth_requests HTTP/1.0 - Go-http-client/1.1" file=middleware.go func="accesslog.(*AccessLogMiddleware).MiddlewareFunc.func1" line=60 request_id=9a9fc528-76e8-4c2c-b007-381fb5a437c5 sub=5db1ff17512fb400101c5f84 tenant_id=5db1ff17512fb400101c5f84

==> mender-api-gateway <==
2019-10-24T19:58:11.68391074Z 10.52.8.25 - - [24/Oct/2019:19:58:11 +0000] "POST /api/devices/v1/authentication/auth_requests HTTP/1.1" 401 112 "-" "Go-http-client/1.1" "205.201.16.55" request ID "9a9fc528-76e8-4c2c-b007-381fb5a437c5" 0.027

==> mender-mongo <==
2019-10-24T19:58:13.353837832Z 2019-10-24T19:58:13.353+0000 I NETWORK  [conn27] received client metadata from 10.53.160.31:45732 conn27: { driver: { name: "mgo", version: "globalsign" }, os: { type: "linux", architecture: "amd64" } }

This final log is from the nginx gateway for the entire cluster. We run this in front of mender 2.0.0 without issue.

==> Nginx Reverse Proxy <==
│2019-10-24T20:24:26.63835895Z 205.201.16.55 - [205.201.16.55] - - [24/Oct/2019:20:24:26 +0000] "PATCH /api/devices/v1/inventory/device/attributes HTTP/1.1" 401 201 "-" "Go-http-client/1.1" 1139 0.005 [ent-staging-mender-mender-api-gateway-8080] [] 10.53.227.4:443 201 0.005 401 f32fcfa09c0f1d0d34886e6249cc7de5      │
│2019-10-24T20:24:27.091679286Z 205.201.16.55 - [205.201.16.55] - - [24/Oct/2019:20:24:27 +0000] "POST /api/devices/v1/authentication/auth_requests HTTP/1.1" 200 600 "-" "Go-http-client/1.1" 2833 0.039 [ent-staging-mender-mender-api-gateway-8080] [] 10.53.227.4:443 600 0.039 200 3bab54eba38546bc591ec187fbc51d54     │
│2019-10-24T20:24:27.140750448Z 205.201.16.55 - [205.201.16.55] - - [24/Oct/2019:20:24:27 +0000] "PATCH /api/devices/v1/inventory/device/attributes HTTP/1.1" 401 201 "-" "Go-http-client/1.1" 1139 0.003 [ent-staging-mender-mender-api-gateway-8080] [] 10.53.227.4:443 201 0.003 401 949cf5d2f7600e62ce11c4047ac06a1f     │

Any idea why this might be happening?

2

Can you also share the output of journalctl -a -u mender on the device?

3

Sure. This is startup.

Oct 25 11:41:53 full-sierra systemd[1]: Started Mender OTA update service.
time="2019-10-25T11:41:53-04:00" level=debug msg="Configuration file does not exist: /var/lib/mender/mender.conf" module=config
time="2019-10-25T11:41:53-04:00" level=debug msg="Reading Mender configuration from file /etc/mender/mender.conf" module=config
level=info msg="Loaded configuration file: /etc/mender/mender.conf" module=config
time="2019-10-25T11:41:53-04:00" level=info msg="Loaded configuration file: /etc/mender/mender.conf" module=config
time="2019-10-25T11:41:53-04:00" level=debug msg="Merged configuration = &main.menderConfig{menderConfigFromFile:main.menderConfigFromFile{ClientProtocol:\"https\", ArtifactVerifyKey:\"\", HttpsClient:struct { Certificate string; Key string; SkipVerify bool }{Certificate:\"\", Key:\"\", SkipVerify:true}, RootfsPartA:\"/dev/mmcblk0p1\", RootfsPartB:\"/dev/mmcblk0p2\", DeviceTypeFile:\"/data/mender/courtney_device_file\", UpdatePollIntervalSeconds:1800, InventoryPollIntervalSeconds:86400, RetryPollIntervalSeconds:60, StateScriptTimeoutSeconds:0, StateScriptRetryTimeoutSeconds:0, StateScriptRetryIntervalSeconds:0, ModuleTimeoutSeconds:0, ServerCertificate:\"\", ServerURL:\"https://ent-testing-mender.my.company.domain.com/\", UpdateLogPath:\"/data/mender/updates.log\", TenantToken:\"xxxxx\", Servers:[]client.MenderServer{client.MenderServer{ServerURL:\"https://ent-testing-mender.my.company.domain.com\"}}}, ModulesPath:\"/usr/share/mender/modules/v3\", ModulesWorkPath:\"/var/lib/mender/modules/v3\", ArtifactInfoFile:\"/etc/mender/artifact_info\", ArtifactScriptsPath:\"/var/lib/mender/scripts\", RootfsScriptsPath:\"/etc/mender/scripts\"}" module=config
time="2019-10-25T11:41:53-04:00" level=debug msg="Have U-Boot variable: mender_boot_part=1" module=bootenv
time="2019-10-25T11:41:53-04:00" level=debug msg="List of U-Boot variables:map[mender_boot_part:1]" module=bootenv
time="2019-10-25T11:41:53-04:00" level=debug msg="Setting active partition from mount candidate: /dev/mmcblk0p1" module=partitions
time="2019-10-25T11:41:53-04:00" level=info msg="Mender running on partition: /dev/mmcblk0p1" module=main
level=info msg="Mender running on partition: /dev/mmcblk0p1" module=main
time="2019-10-25T11:41:53-04:00" level=debug msg="block type: RSA PRIVATE KEY" module=keystore
level=warning msg="certificate verification skipped.." module=client
time="2019-10-25T11:41:53-04:00" level=warning msg="certificate verification skipped.." module=client
time="2019-10-25T11:41:53-04:00" level=debug msg="ModuleTimeoutSeconds not set. Defaulting to 14400 seconds" module=modules
level=info msg="State transition: init [none] -> init [none]" module=mender
time="2019-10-25T11:41:53-04:00" level=info msg="State transition: init [none] -> init [none]" module=mender
time="2019-10-25T11:41:53-04:00" level=debug msg="no state data stored" module=state
level=info msg="State transition: init [none] -> idle [Idle]" module=mender
time="2019-10-25T11:41:53-04:00" level=info msg="State transition: init [none] -> idle [Idle]" module=mender
time="2019-10-25T11:41:53-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
time="2019-10-25T11:41:53-04:00" level=info msg="authorization data present and valid" module=mender
time="2019-10-25T11:41:53-04:00" level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender
level=info msg="authorization data present and valid" module=mender
time="2019-10-25T11:41:53-04:00" level=debug msg="handle check wait state" module=state
time="2019-10-25T11:41:53-04:00" level=debug msg="check wait state; next checks: (update: 0001-01-01 00:30:00 +0000 UTC) (inventory: 0001-01-01 00:00:00 +0000 UTC)" module=state
time="2019-10-25T11:41:53-04:00" level=debug msg="next check: 0001-01-01 00:00:00 +0000 UTC:inventory-update, (2019-10-25 11:41:53.349798709 -0400 EDT m=+0.035618142)" module=state
time="2019-10-25T11:41:53-04:00" level=debug msg="check wait returned: inventory-update" module=state
level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender
time="2019-10-25T11:41:53-04:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
time="2019-10-25T11:41:53-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
time="2019-10-25T11:41:53-04:00" level=debug msg="Returning artifact name from /etc/mender/artifact_info file." module=device
time="2019-10-25T11:41:53-04:00" level=debug msg="Read data from device manifest file: artifact_name=nightly-development-20190827T044701Z" module=device
time="2019-10-25T11:41:53-04:00" level=debug msg="Current manifest data: nightly-development-20190827T044701Z" module=device
time="2019-10-25T11:41:53-04:00" level=debug msg="Read data from device manifest file: device_type=trident" module=device
time="2019-10-25T11:41:53-04:00" level=debug msg="Current manifest data: trident" module=device
level=info msg="Device unauthorized; attempting reauthorization" module=client
time="2019-10-25T11:41:53-04:00" level=info msg="Device unauthorized; attempting reauthorization" module=client
time="2019-10-25T11:41:53-04:00" level=debug msg="tenant token: xxxxx" module=auth
time="2019-10-25T11:41:53-04:00" level=debug msg="authorization data: {{\"serial_number\":\"full-sierra\"} xxxxx -----BEGIN PUBLIC KEY-----\nyyyyy=\n-----END PUBLIC KEY-----\n}" module=auth
time="2019-10-25T11:41:53-04:00" level=debug msg="making an authorization request () to server https://ent-testing-mender.my.company.domain.com" module=client_auth
time="2019-10-25T11:41:53-04:00" level=debug msg="got response: &{200 OK 200 HTTP/1.1 1 1 map[Pragma:[no-cache] X-Frame-Options:[DENY] X-Content-Type-Options:[nosniff] Cache-Control:[no-cache, no-store] Date:[Fri, 25 Oct 2019 15:41:53 GMT] Content-Type:[application/json; charset=utf-8] Connection:[keep-alive] Strict-Transport-Security:[max-age=15724800; includeSubDomains] X-Xss-Protection:[1; mode=block] Server:[openresty/1.15.8.1] Vary:[Accept-Encoding] X-Authentication-Version:[unknown] X-Men-Requestid:[84ead767-de3a-4459-a972-ffb5bd7c7afe]] 0x1080d0b0 -1 [] false true map[] 0x109e6100 0x108f7200}" module=client_auth
time="2019-10-25T11:41:53-04:00" level=debug msg="receive response data" module=client_auth
time="2019-10-25T11:41:53-04:00" level=debug msg="received response data:  [101 121 74 104 98 71 99 105 79 105 74 83 85 122 73 49 78 105 73 115 73 110 82 53 99 67 73 54 73 107 112 88 86 67 74 57 46 101 121 74 108 101 72 65 105 79 106 69 49 78 122 73 50 77 106 73 53 77 84 77 115 73 109 112 48 97 83 73 54 73 106 86 105 78 87 86 104 78 87 73 53 76 84 85 122 90 84 85 116 78 68 99 121 78 83 48 52 78 68 77 51 76 84 81 121 90 84 66 107 89 87 73 121 78 122 85 120 77 67 73 115 73 109 108 122 99 121 73 54 73 107 49 108 98 109 82 108 99 105 73 115 73 110 78 49 89 105 73 54 73 106 86 107 89 106 73 119 77 106 85 122 78 106 65 53 78 109 70 105 77 68 65 119 77 87 69 51 90 84 99 120 77 121 73 115 73 109 49 108 98 109 82 108 99 105 53 107 90 88 90 112 89 50 85 105 79 110 82 121 100 87 86 57 46 98 51 95 74 88 50 73 75 80 111 101 87 68 50 103 75 65 108 95 108 69 81 100 101 104 99 83 90 51 66 114 86 51 106 89 78 107 102 51 70 78 70 104 90 100 115 80 66 75 54 86 54 57 105 85 68 87 104 49 109 67 67 65 67 110 95 84 67 79 81 71 105 117 101 122 109 49 98 69 116 84 86 53 119 107 71 99 106 97 66 100 72 74 95 114 51 99 69 111 85 45 107 78 57 75 69 76 67 119 115 71 107 121 84 77 87 98 83 51 98 55 79 84 114 54 101 78 57 55 121 102 102 90 67 107 103 53 74 106 55 69 74 55 86 78 82 76 51 84 57 107 88 66 115 117 86 86 111 74 89 74 107 117 49 53 88 65 116 102 76 73 77 49 111 49 111 52 72 100 101 101 79 86 115 97 75 56 89 70 50 85 84 110 98 113 71 83 103 98 108 86 114 101 72 85 80 105 103 51 98 56 111 81 106 54 69 83 116 55 51 104 49 106 116 100 86 107 104 111 70 101 95 82 50 99 69 65 102 68 121 45 45 107 106 49 111 90 85 103 83 115 79 54 122 54 54 116 80 101 77 70 70 114 50 90 71 66 49 80 85 106 86 121 108 114 82 90 78 76 111 52 117 84 68 105 118 66 76 76 99 104 68 50 85 65 113 106 52 119 109 90 72 106 56 88 51 65 71 112 101 120 118 82 117 107 122 106 116 56 73 118 88 115 84 52 90 76 72 71 98 100 50 116 98 74 74 109 111 115 113 86 54 72 95 75 73 108 72 101 109 83 53 77 69 80 66 71 78 86 113 109 122 87 71 52 70 57 50 78 113 117 102 114 50 117 98 102 109 95 116 109 77 105 89 72 120 55 56 105 120 118 70 57 71 113 101 99 122 48 48 88 117 74 86 57 85 70 88 75 53 50 104 117 48 107 50 49 82 106 111 101 65 68 104 112 122 52 82 82 113 103 121 82 69 105 113 112 116 73 55 87 118 50 122 83 78 88 120 113 52 118 109 55 73 90 52 110 45 120 86 89 50 87 83 104 113 111 86 50 106 52 72 105 116 97 48 73 88 74 51 122 95 99 50 52 105 99 76 80 45 84 56 55 117 68 87 66 116 81 85 113 85 57 110 69 85 54 83 121 109 71 118]" module=client_auth
level=error msg="got unexpected HTTP status when submitting to inventory: 401" module=client_inventory
level=warning msg="failed to refresh inventory: failed to submit inventory data: (request_id: ): inventory submit failed, bad status 401 server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
time="2019-10-25T11:41:53-04:00" level=error msg="got unexpected HTTP status when submitting to inventory: 401" module=client_inventory
time="2019-10-25T11:41:53-04:00" level=warning msg="failed to refresh inventory: failed to submit inventory data: (request_id: ): inventory submit failed, bad status 401 server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
time="2019-10-25T11:41:53-04:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
time="2019-10-25T11:41:53-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
time="2019-10-25T11:41:53-04:00" level=debug msg="handle check wait state" module=state
time="2019-10-25T11:41:53-04:00" level=debug msg="check wait state; next checks: (update: 0001-01-01 00:30:00 +0000 UTC) (inventory: 2019-10-26 11:41:53.349798709 -0400 EDT m=+86400.035618142)" module=state
time="2019-10-25T11:41:53-04:00" level=debug msg="next check: 0001-01-01 00:30:00 +0000 UTC:update-check, (2019-10-25 11:41:53.975888609 -0400 EDT m=+0.661708082)" module=state
time="2019-10-25T11:41:53-04:00" level=debug msg="check wait returned: update-check" module=state
time="2019-10-25T11:41:53-04:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
time="2019-10-25T11:41:53-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
time="2019-10-25T11:41:53-04:00" level=debug msg="handle update check state" module=state
time="2019-10-25T11:41:53-04:00" level=debug msg="Returning artifact name from /etc/mender/artifact_info file." module=device
time="2019-10-25T11:41:53-04:00" level=debug msg="Read data from device manifest file: artifact_name=nightly-development-20190827T044701Z" module=device
time="2019-10-25T11:41:53-04:00" level=debug msg="Current manifest data: nightly-development-20190827T044701Z" module=device
time="2019-10-25T11:41:53-04:00" level=debug msg="Read data from device manifest file: device_type=trident" module=device
time="2019-10-25T11:41:53-04:00" level=debug msg="Current manifest data: trident" module=device
level=info msg="Device unauthorized; attempting reauthorization" module=client
time="2019-10-25T11:41:54-04:00" level=info msg="Device unauthorized; attempting reauthorization" module=client
time="2019-10-25T11:41:54-04:00" level=debug msg="tenant token: xxxxx" module=auth
time="2019-10-25T11:41:54-04:00" level=debug msg="authorization data: {{\"serial_number\":\"full-sierra\"} xxxxx -----BEGIN PUBLIC KEY-----\nyyyyy=\n-----END PUBLIC KEY-----\n}" module=auth
time="2019-10-25T11:41:54-04:00" level=debug msg="making an authorization request () to server https://ent-testing-mender.my.company.domain.com" module=client_auth
time="2019-10-25T11:41:54-04:00" level=debug msg="got response: &{200 OK 200 HTTP/1.1 1 1 map[Strict-Transport-Security:[max-age=15724800; includeSubDomains] X-Frame-Options:[DENY] X-Content-Type-Options:[nosniff] X-Xss-Protection:[1; mode=block] Server:[openresty/1.15.8.1] Pragma:[no-cache] X-Authentication-Version:[unknown] X-Men-Requestid:[5438da06-a76f-401c-952e-f1151539a570] Cache-Control:[no-cache, no-store] Date:[Fri, 25 Oct 2019 15:41:54 GMT] Connection:[keep-alive] Vary:[Accept-Encoding] Content-Type:[application/json; charset=utf-8]] 0x10a35990 -1 [] false true map[] 0x108b8500 0x108f74a0}" module=client_auth
time="2019-10-25T11:41:54-04:00" level=debug msg="receive response data" module=client_auth
time="2019-10-25T11:41:54-04:00" level=debug msg="received response data:  [101 121 74 104 98 71 99 105 79 105 74 83 85 122 73 49 78 105 73 115 73 110 82 53 99 67 73 54 73 107 112 88 86 67 74 57 46 101 121 74 108 101 72 65 105 79 106 69 49 78 122 73 50 77 106 73 53 77 84 81 115 73 109 112 48 97 83 73 54 73 109 90 105 77 109 89 51 78 68 73 50 76 84 100 107 79 68 69 116 78 68 107 119 77 83 48 52 77 122 86 105 76 84 69 52 78 87 78 104 90 84 103 48 78 84 77 48 77 83 73 115 73 109 108 122 99 121 73 54 73 107 49 108 98 109 82 108 99 105 73 115 73 110 78 49 89 105 73 54 73 106 86 107 89 106 73 119 77 106 85 122 78 106 65 53 78 109 70 105 77 68 65 119 77 87 69 51 90 84 99 120 77 121 73 115 73 109 49 108 98 109 82 108 99 105 53 107 90 88 90 112 89 50 85 105 79 110 82 121 100 87 86 57 46 116 55 122 95 78 89 111 87 103 98 90 95 101 117 70 70 81 77 79 48 119 70 112 74 98 75 70 121 118 51 118 103 106 110 54 104 102 51 71 76 54 65 55 119 107 85 67 66 100 119 53 73 70 55 116 90 103 82 56 112 86 76 57 95 99 117 69 56 109 83 110 73 73 122 71 116 66 89 110 95 122 118 76 55 72 70 56 54 50 97 68 97 98 110 112 121 87 106 87 80 76 118 95 80 72 118 122 74 53 116 73 68 48 121 83 102 52 74 90 48 101 75 116 112 115 121 69 86 118 89 118 103 100 101 106 68 50 106 51 73 51 73 122 95 111 66 118 66 89 73 80 114 118 53 68 55 52 86 90 78 111 77 87 113 88 74 115 56 100 115 95 55 95 119 69 57 69 90 67 121 120 51 76 105 110 76 68 108 82 56 90 116 72 81 73 105 53 66 120 45 101 55 111 70 73 52 78 114 56 117 82 79 73 88 88 113 108 65 99 71 122 97 114 57 107 71 112 81 85 50 67 99 110 81 107 86 114 118 110 90 83 68 87 71 75 68 65 115 110 73 56 78 108 82 57 84 114 109 89 80 106 90 81 89 105 120 117 122 118 107 100 76 119 83 111 106 99 72 89 95 76 97 108 72 88 55 106 70 118 70 84 99 102 90 77 76 80 69 98 76 51 84 85 68 109 89 83 90 76 74 90 89 45 110 54 66 51 121 79 113 88 101 119 109 66 52 98 87 70 105 107 122 109 100 110 66 112 99 65 56 76 121 67 55 116 75 74 104 120 106 56 117 108 108 74 79 77 45 49 71 115 77 85 111 105 103 117 84 72 99 56 54 78 55 106 122 99 66 119 66 108 51 122 68 71 104 57 51 89 110 99 79 109 98 120 102 111 79 49 75 122 107 75 116 70 70 55 119 108 110 87 45 68 70 112 71 100 84 114 67 50 67 116 76 122 111 56 70 48 45 107 90 90 74 53 101 102 108 83 50 114 120 52 45 99 67 80 112 75 72 71 84 112 49 86 75 102 112 100 82 51 78 83 88 55 68 119 120 104 51 121 122 50 107 115 53 109 56 122 81 99 118 73 49 99 99 68 109 67 52 77 68 100 57 119 116 95 105 56 70 84 54 83 67 119 101 84 97 55 49 110 118]" module=client_auth
time="2019-10-25T11:41:54-04:00" level=debug msg="Received response:401 Unauthorized" module=client_update
time="2019-10-25T11:41:54-04:00" level=warning msg="Client not authorized to get update schedule." module=client_update
level=warning msg="Client not authorized to get update schedule." module=client_update
level=error msg="Error receiving scheduled update data: (request_id: ): client not authorized server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=mender
level=error msg="update check failed: transient error: (request_id: ): client not authorized server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
time="2019-10-25T11:41:54-04:00" level=error msg="Error receiving scheduled update data: (request_id: ): client not authorized server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=mender
time="2019-10-25T11:41:54-04:00" level=error msg="update check failed: transient error: (request_id: ): client not authorized server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
time="2019-10-25T11:41:54-04:00" level=info msg="State transition: update-check [Sync] -> error [Error]" module=mender
time="2019-10-25T11:41:54-04:00" level=debug msg="transitioning to error state" module=mender
level=info msg="State transition: update-check [Sync] -> error [Error]" module=mender
time="2019-10-25T11:41:54-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
time="2019-10-25T11:41:54-04:00" level=info msg="handling error state, current error: transient error: (request_id: ): client not authorized server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
time="2019-10-25T11:41:54-04:00" level=info msg="State transition: error [Error] -> idle [Idle]" module=mender
time="2019-10-25T11:41:54-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
level=info msg="handling error state, current error: transient error: (request_id: ): client not authorized server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
time="2019-10-25T11:41:54-04:00" level=info msg="State transition: idle [Idle] -> authorize-wait [Idle]" module=mender
time="2019-10-25T11:41:54-04:00" level=debug msg="handle authorize wait state" module=state
time="2019-10-25T11:41:54-04:00" level=debug msg="wait 0s before next authorization attempt" module=state
time="2019-10-25T11:41:54-04:00" level=info msg="State transition: authorize-wait [Idle] -> authorize [Sync]" module=mender
time="2019-10-25T11:41:54-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
time="2019-10-25T11:41:54-04:00" level=debug msg="handle authorize state" module=state
level=info msg="State transition: error [Error] -> idle [Idle]" module=mender
level=info msg="State transition: idle [Idle] -> authorize-wait [Idle]" module=mender
level=info msg="State transition: authorize-wait [Idle] -> authorize [Sync]" module=mender
time="2019-10-25T11:41:54-04:00" level=debug msg="tenant token: xxxxx" module=auth
time="2019-10-25T11:41:54-04:00" level=debug msg="authorization data: {{\"serial_number\":\"full-sierra\"} xxxxx -----BEGIN PUBLIC KEY-----\nyyyyy=\n-----END PUBLIC KEY-----\n}" module=auth
time="2019-10-25T11:41:54-04:00" level=debug msg="making an authorization request () to server https://ent-testing-mender.my.company.domain.com" module=client_auth
time="2019-10-25T11:41:54-04:00" level=debug msg="got response: &{200 OK 200 HTTP/1.1 1 1 map[Strict-Transport-Security:[max-age=15724800; includeSubDomains] X-Frame-Options:[DENY] X-Content-Type-Options:[nosniff] Cache-Control:[no-cache, no-store] Date:[Fri, 25 Oct 2019 15:41:54 GMT] Content-Type:[application/json; charset=utf-8] X-Authentication-Version:[unknown] Server:[openresty/1.15.8.1] X-Men-Requestid:[f84193c8-7e0e-4277-b560-88ede86b15a6] Connection:[keep-alive] Vary:[Accept-Encoding] X-Xss-Protection:[1; mode=block] Pragma:[no-cache]] 0x1080d6f0 -1 [] false true map[] 0x108b8700 0x108f74a0}" module=client_auth
time="2019-10-25T11:41:54-04:00" level=debug msg="receive response data" module=client_auth
time="2019-10-25T11:41:54-04:00" level=debug msg="received response data:  [101 121 74 104 98 71 99 105 79 105 74 83 85 122 73 49 78 105 73 115 73 110 82 53 99 67 73 54 73 107 112 88 86 67 74 57 46 101 121 74 108 101 72 65 105 79 106 69 49 78 122 73 50 77 106 73 53 77 84 81 115 73 109 112 48 97 83 73 54 73 109 73 52 89 122 90 104 77 68 81 51 76 84 69 50 79 84 99 116 78 68 73 48 89 121 48 53 78 50 73 53 76 .... it's the token as code points, you get the idea]" module=client_auth
level=info msg="successfully received new authorization data" module=mender
time="2019-10-25T11:41:54-04:00" level=info msg="successfully received new authorization data" module=mender
time="2019-10-25T11:41:54-04:00" level=info msg="State transition: authorize [Sync] -> check-wait [Idle]" module=mender
time="2019-10-25T11:41:54-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
time="2019-10-25T11:41:54-04:00" level=debug msg="handle check wait state" module=state
time="2019-10-25T11:41:54-04:00" level=debug msg="check wait state; next checks: (update: 2019-10-25 12:11:53.975888609 -0400 EDT m=+1800.661708082) (inventory: 2019-10-26 11:41:53.349798709 -0400 EDT m=+86400.035618142)" module=state
time="2019-10-25T11:41:54-04:00" level=debug msg="next check: 2019-10-25 12:11:53.975888609 -0400 EDT m=+1800.661708082:update-check, (2019-10-25 11:41:54.85420719 -0400 EDT m=+1.540026663)" module=state
time="2019-10-25T11:41:54-04:00" level=debug msg="waiting 29m59.121681419s for the next state" module=state
level=info msg="State transition: authorize [Sync] -> check-wait [Idle]" module=mender

mender -debug -send-inventory is run

time="2019-10-25T11:42:33-04:00" level=debug msg="SIGUSR2 signal received." module=main
time="2019-10-25T11:42:33-04:00" level=debug msg="Sent wake up!" module=main
time="2019-10-25T11:42:33-04:00" level=info msg="forced wake-up from sleep" module=state
time="2019-10-25T11:42:33-04:00" level=info msg="Forcing state machine to: inventory-update" module=daemon
time="2019-10-25T11:42:33-04:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
time="2019-10-25T11:42:33-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
time="2019-10-25T11:42:33-04:00" level=debug msg="Returning artifact name from /etc/mender/artifact_info file." module=device
time="2019-10-25T11:42:33-04:00" level=debug msg="Read data from device manifest file: artifact_name=nightly-development-20190827T044701Z" module=device
time="2019-10-25T11:42:33-04:00" level=debug msg="Current manifest data: nightly-development-20190827T044701Z" module=device
time="2019-10-25T11:42:33-04:00" level=debug msg="Read data from device manifest file: device_type=trident" module=device
time="2019-10-25T11:42:33-04:00" level=debug msg="Current manifest data: trident" module=device
level=info msg="forced wake-up from sleep" module=state
level=info msg="Forcing state machine to: inventory-update" module=daemon
level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
level=info msg="Device unauthorized; attempting reauthorization" module=client
time="2019-10-25T11:42:33-04:00" level=info msg="Device unauthorized; attempting reauthorization" module=client
time="2019-10-25T11:42:33-04:00" level=debug msg="tenant token: xxxxx" module=auth
time="2019-10-25T11:42:33-04:00" level=debug msg="authorization data: {{\"serial_number\":\"full-sierra\"} xxxxx -----BEGIN PUBLIC KEY-----\nyyyyy=\n-----END PUBLIC KEY-----\n}" module=auth
time="2019-10-25T11:42:33-04:00" level=debug msg="making an authorization request () to server https://ent-testing-mender.my.company.domain.com" module=client_auth
time="2019-10-25T11:42:33-04:00" level=debug msg="got response: &{200 OK 200 HTTP/1.1 1 1 map[Date:[Fri, 25 Oct 2019 15:42:33 GMT] Vary:[Accept-Encoding] X-Authentication-Version:[unknown] X-Frame-Options:[DENY] X-Xss-Protection:[1; mode=block] Content-Type:[application/json; charset=utf-8] Server:[openresty/1.15.8.1] Connection:[keep-alive] Strict-Transport-Security:[max-age=15724800; includeSubDomains] X-Content-Type-Options:[nosniff] Cache-Control:[no-cache, no-store] Pragma:[no-cache] X-Men-Requestid:[78e8bcdb-bb35-4058-bf6e-5cf7dc735772]] 0x1080dd80 -1 [] false true map[] 0x109e6580 0x108f7ec0}" module=client_auth
time="2019-10-25T11:42:33-04:00" level=debug msg="receive response data" module=client_auth
time="2019-10-25T11:42:33-04:00" level=debug msg="received response data:  [101 121 74 104 98 71 99 105 79 105 74 83 85 122 73 49 78 105 73 115 73 110 82 53 99 67 73 54 73 107 112 88 86 67 74 57 46 101 121 74 108 101 72 65 105 79 106 69 49 78 122 73 50 77 106 73 53 78 84 77 115 73 109 112 48 97 83 73 54 73 109 89 119 78 68 65 49 78 84 89 122 76 84 107 51 79 71 85 116 78 68 100 109 78 121 49 104 79 68 85 121 76 84 81 51 90 68 65 120 77 87 90 106 89 106 107 122 77 121 73 115 73 109 108 122 99 121 73 54 73 107 49 108 98 109 82 108 99 105 73 115 73 110 78 49 89 105 73 54 73 106 86 107 89 106 73 119 77 106 85 122 78 106 65 53 78 109 70 105 77 68 65 119 77 87 69 51 90 84 99 120 77 121 73 115 73 109 49 108 98 109 82 108 99 105 53 107 90 88 90 112 89 50 85 105 79 110 82 121 100 87 86 57 46 104 51 86 72 80 66 79 71 110 115 98 118 70 88 115 73 66 50 99 52 66 50 57 116 121 98 74 99 84 112 117 81 118 65 119 49 73 108 69 109 72 114 107 53 103 110 90 74 110 109 56 116 115 55 57 54 103 104 108 90 69 117 99 56 57 66 97 99 87 117 55 45 119 57 66 118 76 120 54 112 78 116 69 95 79 78 102 108 49 79 71 49 111 73 101 88 72 111 110 51 73 90 112 65 79 116 95 87 105 103 85 81 72 90 68 83 76 113 56 103 82 53 115 76 73 111 110 115 102 67 99 51 55 89 80 106 70 85 55 120 110 102 89 90 97 68 85 89 119 90 111 79 67 122 78 98 55 105 97 109 100 104 83 110 107 70 106 81 71 113 102 73 71 100 79 122 49 71 53 122 110 69 99 85 100 87 69 105 56 73 115 117 85 51 117 75 121 104 97 109 106 114 105 80 45 119 74 53 112 109 117 72 118 76 119 114 111 73 111 74 103 54 67 101 78 101 68 72 56 113 121 108 75 82 84 48 100 119 98 51 73 95 45 83 67 109 105 121 84 57 67 108 48 69 113 117 112 45 101 119 67 117 55 87 48 89 78 112 83 99 74 101 83 105 117 79 73 99 97 82 50 102 80 109 77 45 107 71 51 53 110 89 102 103 95 86 98 82 79 71 75 100 120 76 52 53 72 71 51 75 113 69 73 66 79 45 104 110 70 103 115 122 68 54 66 71 45 110 76 81 109 82 83 112 67 72 112 116 87 107 102 97 81 45 82 73 109 69 56 76 51 106 72 54 114 76 77 49 50 99 101 110 114 83 87 89 53 54 50 104 90 66 51 78 109 117 95 95 48 56 86 50 49 86 113 54 68 55 74 108 76 99 82 65 57 90 72 78 102 106 66 51 65 70 99 109 82 87 45 101 54 99 87 122 104 66 85 81 122 57 77 109 71 112 77 55 108 109 77 74 66 88 73 89 118 119 65 67 108 107 107 95 89 95 79 109 103 115 86 86 71 104 84 80 69 48 113 75 109 114 73 50 72 97 113 84 122 112 52 79 83 55 117 83 88 67 75 98 72 74 106 55 89 48 108 82 110 102 57 82 108 71 107 72 53 77 111 113 57 112 70 51 69 104 95 89 66 98 116 65 56 100]" module=client_auth
level=error msg="got unexpected HTTP status when submitting to inventory: 401" module=client_inventory
level=warning msg="failed to refresh inventory: failed to submit inventory data: (request_id: ): inventory submit failed, bad status 401 server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
time="2019-10-25T11:42:33-04:00" level=error msg="got unexpected HTTP status when submitting to inventory: 401" module=client_inventory
time="2019-10-25T11:42:33-04:00" level=warning msg="failed to refresh inventory: failed to submit inventory data: (request_id: ): inventory submit failed, bad status 401 server error message: failed to parse server response: invalid character '<' looking for beginning of value" module=state
time="2019-10-25T11:42:33-04:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
time="2019-10-25T11:42:33-04:00" level=debug msg="statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds" module=executor
time="2019-10-25T11:42:33-04:00" level=debug msg="handle check wait state" module=state
time="2019-10-25T11:42:33-04:00" level=debug msg="check wait state; next checks: (update: 2019-10-25 12:41:53.975888609 -0400 EDT m=+3600.661708082) (inventory: 2019-10-26 11:41:53.349798709 -0400 EDT m=+86400.035618142)" module=state
time="2019-10-25T11:42:33-04:00" level=debug msg="next check: 2019-10-25 12:41:53.975888609 -0400 EDT m=+3600.661708082:update-check, (2019-10-25 11:42:33.716852791 -0400 EDT m=+40.402672224)" module=state
time="2019-10-25T11:42:33-04:00" level=debug msg="waiting 59m20.259035858s for the next state" module=state
4

Also, what is the output of docker ps on the server?

5

It’s running on Kubernetes. I understand that’s not how you do it anymore, but I translated what you had done in the integration repo from docker to kube.

kubectl -n ent-staging-mender get deploy,po
NAME                                                      READY   UP-TO-DATE   AVAILABLE   AGE
deployment.extensions/mender-api-gateway                  1/1     1            1           3d19h
deployment.extensions/mender-conductor                    1/1     1            1           3d19h
deployment.extensions/mender-deployments                  1/1     1            1           3d19h
deployment.extensions/mender-device-auth                  1/1     1            1           3d19h
deployment.extensions/mender-elasticsearch                1/1     1            1           3d19h
deployment.extensions/mender-email-sender                 1/1     1            1           3d19h
deployment.extensions/mender-gui                          1/1     1            1           3d19h
deployment.extensions/mender-inventory                    1/1     1            1           3d19h
deployment.extensions/mender-mongo                        1/1     1            1           3d19h
deployment.extensions/mender-org-welcome-email-preparer   1/1     1            1           3d19h
deployment.extensions/mender-redis                        1/1     1            1           3d19h
deployment.extensions/mender-tenantadm                    1/1     1            1           3d19h
deployment.extensions/mender-useradm                      1/1     1            1           3d19h

NAME                                                     READY   STATUS    RESTARTS   AGE
pod/mender-api-gateway-85f7d8dfc6-bj6d8                  1/1     Running   0          2d16h
pod/mender-conductor-6fccffdcb7-9cdz6                    1/1     Running   1          3d19h
pod/mender-deployments-759c9dd848-gvpfh                  1/1     Running   2          3d19h
pod/mender-device-auth-5bdcc67dc6-tjsxx                  1/1     Running   2          3d19h
pod/mender-elasticsearch-597884c45c-vnsqz                1/1     Running   0          2d8h
pod/mender-email-sender-5df764b7f7-lvbkn                 1/1     Running   1          3d19h
pod/mender-gui-5f85c47984-fbgbs                          1/1     Running   0          2d16h
pod/mender-inventory-7c49bf59fd-5dgb6                    1/1     Running   2          3d19h
pod/mender-mongo-65b9bbc7c7-8dgsr                        1/1     Running   0          3d19h
pod/mender-org-welcome-email-preparer-84ff5dd6b7-zlvb5   1/1     Running   1          3d19h
pod/mender-redis-6f8fd6464c-6wfjk                        1/1     Running   0          3d19h
pod/mender-tenantadm-64b45d79c6-cjbpf                    1/1     Running   0          3d19h
pod/mender-useradm-765686597d-xbwsc                      1/1     Running   0          3d19h
6

hello, thanks for using Mender!

could you double check the URL of the server, and try to manually invoke the API (Device inventory | Mender documentation)?

peter

7

I had the same problem today.
I decomissioned the corresponding device and it started working again.
Any update on this issue ?

8

Hello Jerry,

thanks for using Mender.
judging by the time frame we are working in here, what you have is probably a different issue.
could you elaborate and share the logs?

best regards,
peter

9

Hello Peter, i finally managed to make it work by de-provisionning device in mender server a couple of time.