Preauthorization process fail

General Discussions
, , ,
1

Hello everyone,

I’m reaching out because I’m facing an issue I didn’t have so far in my preauthorization process, which breaks it and make it impossible to connect to my board.
Those are the logs on the client side:

systemd[1]: Started Mender OTA update service.
mender[1584]: time="2023-09-20T11:35:02+02:00" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
mender[1584]: time="2023-09-20T11:35:02+02:00" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
mender[1584]: time="2023-09-20T11:35:02+02:00" level=info msg="'UpdateControlMapExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 2*UpdatePollIntervalSeconds"
mender[1584]: time="2023-09-20T11:35:02+02:00" level=info msg="'UpdateControlMapBootExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 600 seconds"
mender[1584]: time="2023-09-20T11:35:04+02:00" level=info msg="Mender running on partition: /dev/mmcblk0p2"
mender[1584]: time="2023-09-20T11:35:06+02:00" level=info msg="State transition: init [none] -> init [none]"
mender[1584]: time="2023-09-20T11:35:06+02:00" level=info msg="State transition: init [none] -> idle [Idle]"
mender[1584]: time="2023-09-20T11:35:06+02:00" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
mender[1584]: time="2023-09-20T11:35:06+02:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
mender[1584]: time="2023-09-20T11:35:06+02:00" level=warning msg="Returning artifact name from /etc/mender/artifact_info file. This is a fallback, in case the information can not be retrieved from the database, and is only expected when an update has never been installed before."
mender[1584]: time="2023-09-20T11:35:07+02:00" level=info msg="Device unauthorized; attempting reauthorization"
mender[1584]: time="2023-09-20T11:35:07+02:00" level=error msg="Failed to authorize with \"https://mender.jaunefabrique.com\": unexpected authorization status 500 server error message: internal error"
mender[1584]: time="2023-09-20T11:35:07+02:00" level=warning msg="Reauthorization failed with error: transient error: authorization request failed"
mender[1584]: time="2023-09-20T11:35:07+02:00" level=error msg="Failed to submit inventory data: transient error: authorization request failed"
mender[1584]: time="2023-09-20T11:35:07+02:00" level=error msg="inventory submit failed: transient error: authorization request failed"
mender[1584]: time="2023-09-20T11:35:07+02:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: transient error: authorization request failed"
mender[1584]: time="2023-09-20T11:35:07+02:00" level=info msg="State transition: inventory-update [Sync] -> inventory-update-retry-wait [Sync]"
mender[1584]: time="2023-09-20T11:35:07+02:00" level=info msg="Handle update inventory retry state try: 0"
mender[1584]: time="2023-09-20T11:35:07+02:00" level=warning msg="Returning artifact name from /etc/mender/artifact_info file. This is a fallback, in case the information can not be retrieved from the database, and is only expected when an update has never been installed before."

And those are the logs on server side, running docker logs menderproduction_mender-device-auth_1 on a 3.1 Mender Server:

time="2023-09-20T09:35:07Z" level=warning msg="Failed to parse extracted JWT: identity: incorrect token format" file=middleware.go func="identity.(*IdentityMiddleware).MiddlewareFunc.func1" line=182 request_id=bef092d4-ed0c-4ad5-bd83-4f38905681bb
time="2023-09-20T09:35:07Z" level=error msg="provision device request POST http://mender-workflows-server:8080/api/v1/workflow/provision_device failed with status 400 Bad Request, response text: {\"error\":\"Missing input parameters: [device status]\"}" file=client_orchestrator.go func="orchestrator.(*Client).SubmitProvisionDeviceJob" line=201 request_id=bef092d4-ed0c-4ad5-bd83-4f38905681bb
time="2023-09-20T09:35:07Z" level=error msg="internal error: submit device provisioning job error: submit provision device request failed with status 400 Bad Request" file=response_helpers.go func=rest_utils.restErrWithLogMsg line=110 request_id=bef092d4-ed0c-4ad5-bd83-4f38905681bb
time="2023-09-20T09:35:07Z" level=info msg="500 9200μs POST /api/devices/v1/authentication/auth_requests HTTP/1.1 - Go-http-client/1.1" byteswritten=78 file=middleware.go func="accesslog.(*AccessLogMiddleware).MiddlewareFunc.func1" line=71 method=POST path=/api/devices/v1/authentication/auth_requests qs= request_id=bef092d4-ed0c-4ad5-bd83-4f38905681bb responsetime=0.009200849 status=500 ts="2023-09-20 09:35:07.572126754 +0000 UTC" type=http

So far it was working well, the only noticable change was to move from 3.0 to 3.1 some months ago. Any help on that issue will be very appreciated.

2

I just check my devices inventories, and it seems that the new preauthorized device is missing its “status” attribute. Actually some other devices miss it too. @peter it seems to be related to our last changes Cleaning inventory and device-auth sync commands - #10 by peter

3

hey. it maybe related, 500 server error message: on auth is a very bad thing. I think there is an inconsistency in the deviceauth db. but I need to see all the logs I requested in the other thread (private). once we talcke that I will send the update here as well.

pg