Mender-connect is unable to connect to mender-server

General Discussions
,
1

Hi,

Currently we are using mender server 3.0.1 (self hosted) in conjunction with mender-client 3.1.0 successfully. As a backup solution to remotely access our devices, I would like to use mender-connect.

I installed mender-connect (1.2.0) via apt on of our Ubuntu 20 based devices and started the service as explained in the documentation. Btw. I did not alter the mender-connect config file.

However it seems that mender-connect cannot connect to the mender-server.
The following log info is generated:

INFO[2021-09-30T13:37:36+02:00] Loaded configuration file: /etc/mender/mender-connect.conf
WARN[2021-09-30T13:37:36+02:00] No server URL(s) specified in mender configuration.
WARN[2021-09-30T13:37:36+02:00] ShellArguments is empty, defaulting to [--login]
WARN[2021-09-30T13:37:36+02:00] Server entry 1 has no associated server URL.
WARN[2021-09-30T13:37:36+02:00] The server certificate cannot be loaded: no file provided
ERRO[2021-09-30T13:37:36+02:00] connection manager failed to connect to https://xxxxxxxx.com/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 1/0); len(token)=978
WARN[2021-09-30T13:37:41+02:00] The server certificate cannot be loaded: no file provided

My assumption was that mender-connect is using the same info as mender-client to make a connection to the server implying I did not have to alter the config. But probably my assumption is wrong here.

Any ideas what is missing? Do I need to open additional ports besides 80 and 443?

Thanks in advance.

2

Hello Dave,

thank you for using Mender. nice idea to keep remote access as a backup channel.
could you try adding this to the /etc/medner/mender-connect.conf file:

"SkipVerify": true

peter

3

Hi @peter. Thanks for the reply. I added the SkipVerify option and rebooted the device but unfortunately it does not solve the issue. I still get the same logging.

Or could it be a server side issue (e.g. Web Application Firewall we are using)? OTA updates work fine. Does mender-connect need additional ports for communication? If so, then I need open them in our WAF.

4

Hey Dave,

ok I would require additional information: complete mender.conf, mender-connect.conf, mender-connect logs with debug info, could you modify the way you run mender-connect (or stop it and run by hand): mender-connect --trace daemon. Also could you check output of this command:

# dbus-send --system --dest=io.mender.AuthenticationManager --print-reply /io/mender/AuthenticationManager io.mender.Authentication1.GetJwtToken

(do not send me the long string it is the token for the device)
As a last thing, could you check this scenario:

  1. stop both mender-client and mender-connect: systemctl stop mender-connect; systemctl stop mender-client;
  2. start mender-client: systemctl restart mender-client
  3. check the above dbus-send command if it outputs the token and correct ServerURL
  4. start mender-connect: systemctl restart mender-connect

sorry for requesting loads for things/actions.

peter

5

Hey @peter ,

Thanks for your support.

Please find the requested info:

mender.conf:

> {
>   "ServerCertificate": "/etc/mender/server.crt",
>   "InventoryPollIntervalSeconds": 900,
>   "RetryPollIntervalSeconds": 30,
>   "ServerURL": "https://xxxxx.com",
>   "ArtifactVerifyKey": "/etc/mender/artifact-verify-key.pem",
>   "UpdatePollIntervalSeconds": 900
> }

mender-connect.conf:

{
  "ShellCommand": "/bin/bash",
  "User": "user",
  "SkipVerify": false
}

mender-connect --trace daemon logging:

INFO[2021-10-01T11:19:03+02:00] Loaded configuration file: /etc/mender/mender-connect.conf
WARN[2021-10-01T11:19:03+02:00] No server URL(s) specified in mender configuration.
WARN[2021-10-01T11:19:03+02:00] ShellArguments is empty, defaulting to [--login]
WARN[2021-10-01T11:19:03+02:00] Server entry 1 has no associated server URL.
TRAC[2021-10-01T11:19:03+02:00] daemon Run starting
TRAC[2021-10-01T11:19:03+02:00] mender-connect connecting to dbus
TRAC[2021-10-01T11:19:03+02:00] GetJWTToken().len=978
TRAC[2021-10-01T11:19:03+02:00] mender-connect got len(JWT)=978
WARN[2021-10-01T11:19:03+02:00] The server certificate cannot be loaded: no file provided
ERRO[2021-10-01T11:19:04+02:00] connection manager failed to connect to https://xxxxx.com/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 1/0); len(token)=978

Output of dbus command:

```method return time=1633080233.470600 sender=:1.38 -> destination=:1.41 serial=7 reply_serial=2
   string "eyJib..................cfIH"
   string "https://xxxxxx.com"

I also ran the scenario you mentioned. Unfortunately the same result that it is not working.

6

just after a quick glance, could you switch to SkipVerify: true in the mender-connet.conf and restart?
and also could you add "ServerCertificate": "/etc/mender/server.crt" to the mender-connect.conf as well?

peter

7

Hi @peter

Made the changes as requested and restarted mender-client and mender-connect.
mender-connect was started using mender-connect --trace daemon.

This is the new logging output:

INFO[2021-10-01T11:49:49+02:00] Loaded configuration file: /etc/mender/mender-connect.conf
WARN[2021-10-01T11:49:49+02:00] No server URL(s) specified in mender configuration.
WARN[2021-10-01T11:49:49+02:00] ShellArguments is empty, defaulting to [--login]
WARN[2021-10-01T11:49:49+02:00] Server entry 1 has no associated server URL.
TRAC[2021-10-01T11:49:49+02:00] daemon Run starting
TRAC[2021-10-01T11:49:49+02:00] mender-connect connecting to dbus
TRAC[2021-10-01T11:49:49+02:00] GetJWTToken().len=978
TRAC[2021-10-01T11:49:49+02:00] mender-connect got len(JWT)=978
INFO[2021-10-01T11:49:49+02:00] loadServerTrust loading certificate from /etc/mender/server.crt
INFO[2021-10-01T11:49:49+02:00] API Gateway certificate (in PEM format):
-----BEGIN CERTIFICATE-----
.....
-----END CERTIFICATE-----
-----BEGIN CERTIFICATE-----
.....
-----END CERTIFICATE-----
INFO[2021-10-01T11:49:49+02:00] Issuer: [], Valid from: 202x-xx-xx 11:47:00 +0000 UTC, Valid to: 202x-xx-xx 11:47:00 +0000 UTC
ERRO[2021-10-01T11:49:49+02:00] connection manager failed to connect to https://xxxxx.com/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 1/0); len(token)=978
8

ok, so everything looks ok, besides the fact that we are getting a bad handshake on the https to backend from mender-connect. (to answer your previous questions, which I forgot: all you need is 443 port, so if mender-client works and you can see the device in the UI then mender-connect should also work)
could I ask for logs form the deviceconnect service?

peter

9

The device is still popping up in our mender dashboard:)

What do you mean with deviceconnect service? How to get the logging?

10

if you are running it under docker, then something like that should work:

docker logs `docker ps | grep deviceconnect | head -1 | awk '{print($1);}'`

(typing as we speak, should work, but in general get the id of deviceconnect container, then run docker logs on it. if you are running k8s use kubectl logs deviceconnectpod)

pg

11

Thanks for the explanation.

The log only contains messages like this:

time="2021-10-01T10:23:25Z" level=error msg="failed to upgrade the request to websocket protocol: websocket: the client is not using the websocket protocol: 'upgrade' token not found in 'Connection' header" device_id=xxxxx file=device.go func=http.DeviceController.Connect line=173 plan=enterprise request_id=fd050e96-cbed-4fec-b50b-c820dd3c729a
time="2021-10-01T10:23:25Z" level=error byteswritten=171 clientip=xx.xx.0.14 device_id=xxxxx error="websocket: the client is not using the websocket protocol: 'upgrade' token not found in 'Connection' header" file=middleware_gin.go func=accesslog.Middleware.func1 line=153 method=GET path=/api/devices/v1/deviceconnect/connect plan=enterprise qs= request_id=fd050e96-cbed-4fec-b50b-c820dd3c729a responsetime=396us status=400 ts="2021-10-01T10:23:25Z" type=HTTP/1.1 useragent=Go-http-client/1.1

I also checked the device_id and it matches the devices on which I installed mender-connect.

12

thanks for the log. now that is giving one answer and rising 2 more questions. how can it be that the client is not upgrading the connection to a websocket? is it some version mismatch, shall we move to older mender-connect or newer backend, or the vice-versa?

while I meditate over that, could you try adding:

"ServerURL": "wss://your-server-url-here"

to the mender-connect.conf?

peter

P.S.
could I get docker ps output as well? (it maybe api-gateway http configuration issue with the passing of websocket upgrade to the backend)

13

Please find below the output of docker ps command:

CONTAINER ID   IMAGE                                                COMMAND                  CREATED        STATUS                  PORTS                                           NAMES
b4484b957a7e   mendersoftware/deployments:mender-3.0.1              "/entrypoint.sh --co…"   44 hours ago   Up 44 hours             8080/tcp                                        menderproduction_mender-deployments_1
78c77a5d5fd2   traefik:v2.4                                         "/entrypoint.sh --ac…"   44 hours ago   Up 44 hours             80/tcp, 0.0.0.0:443->443/tcp, :::443->443/tcp   menderproduction_mender-api-gateway_1
fbf05d821610   mendersoftware/deviceauth:mender-3.0.1               "/usr/bin/deviceauth…"   44 hours ago   Up 44 hours             8080/tcp                                        menderproduction_mender-device-auth_1
2d7925371e74   mendersoftware/deviceconnect:mender-3.0.1            "/usr/bin/deviceconn…"   44 hours ago   Up 44 hours             8080/tcp                                        menderproduction_mender-deviceconnect_1
2913d6148e50   mendersoftware/inventory:mender-3.0.1                "/usr/bin/inventory …"   44 hours ago   Up 44 hours             8080/tcp                                        menderproduction_mender-inventory_1
f3e23f72c27c   mendersoftware/workflows:mender-3.0.1                "/usr/bin/workflows …"   44 hours ago   Up 44 hours             8080/tcp                                        menderproduction_mender-workflows-server_1
5f80761a606d   mendersoftware/workflows-worker:mender-3.0.1         "/usr/bin/workflows …"   44 hours ago   Up 44 hours                                                             menderproduction_mender-workflows-worker_1
c838c7d0e3c9   mendersoftware/useradm:mender-3.0.1                  "/usr/bin/useradm --…"   44 hours ago   Up 44 hours             8080/tcp                                        menderproduction_mender-useradm_1
a5ff761d9d0c   mendersoftware/create-artifact-worker:mender-3.0.1   "/usr/bin/workflows …"   44 hours ago   Up 44 hours             8080/tcp                                        menderproduction_mender-create-artifact-worker_1
655bb32e3b58   mendersoftware/deviceconfig:mender-3.0.1             "/usr/bin/deviceconf…"   44 hours ago   Up 44 hours             8080/tcp                                        menderproduction_mender-deviceconfig_1
0106c79bf908   mendersoftware/gui:mender-3.0.1                      "/entrypoint.sh nginx"   44 hours ago   Up 44 hours (healthy)   80/tcp, 8080/tcp                                menderproduction_mender-gui_1
a73d0323522b   nats:2.1.9-alpine3.12                                "docker-entrypoint.s…"   44 hours ago   Up 44 hours             4222/tcp, 6222/tcp, 8222/tcp                    menderproduction_mender-nats_1
494849288c1f   mongo:4.4                                            "docker-entrypoint.s…"   44 hours ago   Up 44 hours             27017/tcp                                       menderproduction_mender-mongo_1
ee3537168f64   minio/minio:RELEASE.2019-04-23T23-50-36Z             "/usr/bin/docker-ent…"   44 hours ago   Up 44 hours (healthy)   9000/tcp                                        menderproduction_minio_1

I also added the ServerURL option to the config and restarted the mender-connect service. Unfortunately it does not fix the problem but I noticed something strange. I would have expected that the logging is displaying something like connection manager failed to connect to wss://xxxxx.com/api/devices/v1/deviceconnect/connect but instead it still shows https.

14

thanks for all the information. I will now go and try to replicate the issue. my best guess at the moment is: there is something wrong with the way traefik passes HTTP upgrade. but I have no proof for that.

if you have a spare moment, could you take a look at docker logs 78c77a5d5fd2 (traefik container).

peter

15

Dave just one thing: is the certificate a self-signed one, or something else?

pg

16

Hi Peter.

It is a self-signed certificate.

17

ok thanks. I will get back to you.

pg

18

do you see anything suspicious in the docker logs 78c77a5d5fd2 (traefik container) ?

pg

19

Hi @peter

I examined the logs and saw nothing suspicious. For the particular device I found the following logging repeating.

10.65.0.122 - - [01/Oct/2021:13:08:41 +0000] "GET /api/management/v2/devauth/devices?id=xxxxx HTTP/1.1" 200 1003 "-" "-" 40557 "deviceauthMgmt@file" "http://mender-device-auth:8080" 6ms
10.65.0.122 - - [01/Oct/2021:13:08:41 +0000] "GET /api/management/v1/deviceconfig/configurations/device/xxxxx HTTP/1.1" 200 184 "-" "-" 40558 "deviceconfigMgmt@file" "http://mender-deviceconfig:8080" 6ms
10.65.0.122 - - [01/Oct/2021:13:08:41 +0000] "GET /api/management/v1/inventory/devices/xxxxx HTTP/1.1" 200 784 "-" "-" 40559 "inventoryMgmtV1@file" "http://mender-inventory:8080" 6ms
10.65.0.122 - - [01/Oct/2021:13:08:41 +0000] "GET /api/management/v1/deviceconnect/devices/xxxxx HTTP/1.1" 200 149 "-" "-" 40560 "deviceconnectMgmt@file" "http://mender-deviceconnect:8080" 5ms
10.65.0.122 - - [01/Oct/2021:13:08:44 +0000] "POST /api/management/v2/inventory/filters/search HTTP/1.1" 200 492 "-" "-" 40561 "inventoryMgmtV2@file" "http://mender-inventory:8080" 4ms
10.65.0.122 - - [01/Oct/2021:13:08:44 +0000] "POST /api/management/v2/inventory/filters/search HTTP/1.1" 200 2 "-" "-" 40562 "inventoryMgmtV2@file" "http://mender-inventory:8080" 4ms
10.65.0.122 - - [01/Oct/2021:13:08:45 +0000] "GET /api/devices/v1/deviceconnect/connect HTTP/1.1" 400 171 "-" "-" 40563 "deviceconnect@file" "http://mender-deviceconnect:8080" 3ms
10.65.0.122 - - [01/Oct/2021:13:08:49 +0000] "POST /api/management/v2/inventory/filters/search HTTP/1.1" 200 480 "-" "-" 40564 "inventoryMgmtV2@file" "http://mender-inventory:8080" 5ms
20

Hey Dave,

I started from scratch, followed the instructions, installed production server 3.0.1, self-signed the certificate, downloaded the RPi OS image with client 3.1, and configured:

root@raspberrypi:~# head -10000 /etc/mender/mender*conf
==> /etc/mender/mender.conf <==
{
    "HttpsClient": {},
    "Security": {},
    "SkipVerify": true,
    "RootfsPartA": "/dev/mmcblk0p2",
    "RootfsPartB": "/dev/mmcblk0p3",
    "DeviceTypeFile": "/var/lib/mender/device_type",
    "DBus": {
        "Enabled": true
    },
    "UpdateControlMapExpirationTimeSeconds": 90,
    "UpdateControlMapBootExpirationTimeSeconds": 45,
    "UpdatePollIntervalSeconds": 5,
    "InventoryPollIntervalSeconds": 5,
    "RetryPollIntervalSeconds": 30,
    "ServerCertificate": "/certificate.crt",
    "Servers": [
        {
            "ServerURL": "https://my-host"
        }
    ]
}

==> /etc/mender/mender-connect.conf <==
{
  "ServerCertificate": "/certificate.crt",
  "SkipVerify": true,
  "User": "pi",
  "ShellCommand": "/bin/bash"
}

(I had to add SKipVerify as I used very short and self-signed certificate).

I was unable to replicate the issue, it works. Here is the docker ps and versions output:

CONTAINER ID        IMAGE                                                COMMAND                  CREATED             STATUS                       PORTS                          NAMES
c3bcbd19d380        mendersoftware/deployments:mender-3.0.1              "/entrypoint.sh --co…"   About an hour ago   Up About an hour             8080/tcp                       menderproduction_mender-deployments_1
92678bd4db5d        traefik:v2.4                                         "/entrypoint.sh --ac…"   About an hour ago   Up About an hour             80/tcp, 0.0.0.0:443->443/tcp   menderproduction_mender-api-gateway_1
399e03cb0564        mendersoftware/deviceauth:mender-3.0.1               "/usr/bin/deviceauth…"   About an hour ago   Up About an hour             8080/tcp                       menderproduction_mender-device-auth_1
c8e7958b5dc7        mendersoftware/deviceconfig:mender-3.0.1             "/usr/bin/deviceconf…"   About an hour ago   Up About an hour             8080/tcp                       menderproduction_mender-deviceconfig_1
f45813bf60bd        mendersoftware/useradm:mender-3.0.1                  "/usr/bin/useradm --…"   About an hour ago   Up About an hour             8080/tcp                       menderproduction_mender-useradm_1
dfcc50b2f366        mendersoftware/workflows:mender-3.0.1                "/usr/bin/workflows …"   About an hour ago   Up About an hour             8080/tcp                       menderproduction_mender-workflows-server_1
58873ef6c61f        mendersoftware/inventory:mender-3.0.1                "/usr/bin/inventory …"   About an hour ago   Up About an hour             8080/tcp                       menderproduction_mender-inventory_1
5ff1a8ead75b        mendersoftware/deviceconnect:mender-3.0.1            "/usr/bin/deviceconn…"   About an hour ago   Up About an hour             8080/tcp                       menderproduction_mender-deviceconnect_1
2696e2c62494        mendersoftware/create-artifact-worker:mender-3.0.1   "/usr/bin/workflows …"   About an hour ago   Up About an hour             8080/tcp                       menderproduction_mender-create-artifact-worker_1
e7acdbd8ff3a        mendersoftware/workflows-worker:mender-3.0.1         "/usr/bin/workflows …"   About an hour ago   Up About an hour                                            menderproduction_mender-workflows-worker_1
02306295e14d        mongo:4.4                                            "docker-entrypoint.s…"   About an hour ago   Up About an hour             27017/tcp                      menderproduction_mender-mongo_1
c11b2f1016ce        mendersoftware/gui:mender-3.0.1                      "/entrypoint.sh nginx"   About an hour ago   Up About an hour (healthy)   80/tcp, 8080/tcp               menderproduction_mender-gui_1
833ccf22fd18        minio/minio:RELEASE.2019-04-23T23-50-36Z             "/usr/bin/docker-ent…"   About an hour ago   Up About an hour (healthy)   9000/tcp                       menderproduction_minio_1
636af8ec4dfb        nats:2.1.9-alpine3.12                                "docker-entrypoint.s…"   About an hour ago   Up About an hour             4222/tcp, 6222/tcp, 8222/tcp   menderproduction_mender-nats_1

client:

root@raspberrypi:~# mender-connect --version
mender-connect version 1.2.0	runtime: go1.14.7
root@raspberrypi:~# mender --version
3.1.0	runtime: go1.14.7

The question now is: what is the difference between our setups?
One request: could you disable IPv6 on all interfaces, restart the dockerd and the server composition, and send me docker ps then?

peter