Hi folks,
I’m working on a A/B deploy setup for loraserver.io’s LoRa-Gateway-OS and I’ve hit the following problem in the logs:
root@raspberrypi3:~# mender -forcebootstrap -bootstrap -debug -trusted-certs /etc/mender/server.crt -skipverify
INFO[0000] Configuration file does not exist: /var/lib/mender/mender.conf module=config
DEBU[0000] Reading Mender configuration from file /etc/mender/mender.conf module=config
INFO[0000] Loaded configuration file: /etc/mender/mender.conf module=config
DEBU[0000] Merged configuration = main.menderConfig{ClientProtocol:"", ArtifactVerifyKey:"", HttpsClient:struct { Certificate string; Key string; SkipVerify bool }{Certificate:"", Key:"", SkipVerify:false}, RootfsPartA:"/dev/mmcblk0p2", RootfsPartB:"/dev/mmcblk0p3", UpdatePollIntervalSeconds:1800, InventoryPollIntervalSeconds:1800, RetryPollIntervalSeconds:300, StateScriptTimeoutSeconds:0, StateScriptRetryTimeoutSeconds:0, StateScriptRetryIntervalSeconds:0, ServerCertificate:"", ServerURL:"https://< my mender server>/", UpdateLogPath:"", TenantToken:"", Servers:[]client.MenderServer{client.MenderServer{ServerURL:"https://<my mender server>"}}} module=config
DEBU[0000] Have U-Boot variable: mender_check_saveenv_canary=1 module=bootenv
DEBU[0000] List of U-Boot variables:map[mender_check_saveenv_canary:1] module=bootenv
DEBU[0000] Have U-Boot variable: mender_saveenv_canary=1 module=bootenv
DEBU[0000] List of U-Boot variables:map[mender_saveenv_canary:1] module=bootenv
DEBU[0000] Have U-Boot variable: mender_boot_part=2 module=bootenv
DEBU[0000] List of U-Boot variables:map[mender_boot_part:2] module=bootenv
DEBU[0000] Setting active partition from configuration and environment: /dev/mmcblk0p2 module=partitions
INFO[0000] Mender running on partition: /dev/mmcblk0p2 module=main
DEBU[0000] block type: RSA PRIVATE KEY module=keystore
WARN[0000] Server certificate not provided. Trusting all servers. module=client
WARN[0000] certificate verification skipped.. module=client
INFO[0000] device keys not present or bootstrap forced, generating module=mender
DEBU[0033] tenant token: module=auth
DEBU[0033] authorization data: {{"mac":"b8:27:eb:b8:cd:6d"} -----BEGIN PUBLIC KEY-----
MIIBojANBgkqhkiG9w0BAQEFAAOCAY8AMIIBigKCAYEAzoIsGIvvEi+NDNJLnTcf
vT3gdADt5F8XA58KIzNarfod8/R6ILxoCZOJMfIgGKHUO1VQzYkf/CnMxawlRLpr
fUK/qVT3sVvvLHvqaJRbEyDKlK2zi0rYuEnGIYV/Od0CvHACLX0OkwuOPRvf6Lbr
363QcSAfp3ItutVtTQSQ4EJWh/bhe1354QZa+6p6dk14KGktiaOcpWWyH+8al3L9
Zz8NG0nu2BBopsIpVMVnthIfJ3aJcmXzxF07B5dzk0dc1WuObYByacFjJfEkOhdT
DHZzpcXrM/4gngyrnUsl4lv1mCGPY2wf8FZQ32X8gkZEUUsl6DfmH5FNxsMDatQP
VKsIrXG6w9YcQkFeoC+PQIqLP1/Z1lEWNmsSZ21HazfPI6aJAzR1C6cKdE20OO/T
jUi0dT5T7pzMBFoAh8ZSyAFfd2xHPtLmwntv/xG9vEtJqm1BJJfdvEP0G9HJvLRN
25uGw9v9agTDxu1g5l0IfQpg7a9JsTcuUp1coyALRpwxAgMBAAE=
-----END PUBLIC KEY-----
} module=auth
DEBU[0033] making authorization request to server https://<mymenderserver> module=client_auth
DEBU[0033] got response: &{401 Unauthorized 401 HTTP/1.1 1 1 map[Server:[openresty/1.13.6.2] Date:[Sun, 19 May 2019 10:33:48 GMT] X-Authentication-Version:[unknown] Content-Type:[application/json; charset=utf-8] Connection:[keep-alive] Vary:[Accept-Encoding] X-Men-Requestid:[1073aee3-caac-4b8a-887d-6377e7590c67] Access-Control-Allow-Origin:[*]] 0x1b46050 -1 [] false true map[] 0x18ae280 0x1870e40} module=client_auth
ERRO[0033] authorization request failed: (request_id: ): authentication request rejected server error message: dev auth: unauthorized module=main
This is a self-hosted mender, and the demo image works fine.
I have copied the server cert from the demo image to the relevant location, and my config currently shows the following:
{
"InventoryPollIntervalSeconds": 1800,
"RetryPollIntervalSeconds": 300,
"RootfsPartA": "/dev/mmcblk0p2",
"RootfsPartB": "/dev/mmcblk0p3",
"ServerURL": "https://<MyMenderServer>/",
"UpdatePollIntervalSeconds": 1800
}
On the server, the logs show:
time="2019-05-19T09:33:07Z" level=warning msg="Failed to extract identity from header: malformed authorization data" file=middleware.go func="identity.(*IdentityMiddleware).MiddlewareFunc.func1" line=47 request_id=9b55460d-9c3b-4f4d-a2d2-5ae4e5a29600
time="2019-05-19T09:33:07Z" level=warning msg="dev auth: unauthorized: dev auth: unauthorized" file=response_helpers.go func=rest_utils.RestErrWithWarningMsg line=55 request_id=9b55460d-9c3b-4f4d-a2d2-5ae4e5a29600
time="2019-05-19T09:33:07Z" level=info msg="401 32242μ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=9b55460d-9c3b-4f4d-a2d2-5ae4e5a29600
I’ve checked the date/time and it’s identical on the server and the client.
Where do I start with debugging this?