Raspberry pi 3 not able to join openbalena server

Hello,

I am currently trying to set up my first system with openbalena and balenaOS. I have the following configuration:

Openbalena server 3.2.1
BalenaOS 12.3.0 on Raspberry Pi 3
Balena-cli 12.40.0

The server is running and I am able to curl to the server:
% curl api.openbalena.local/ping
OK%

However, after booting up the Pi is not joining my server and is showing following log:

Feb 17 18:20:53 85d0c4a resin-supervisor[2366]: resin_supervisor
Feb 17 18:20:53 85d0c4a resin-supervisor[2376]: active
Feb 17 18:20:56 85d0c4a resin-supervisor[2377]: Container config has not changed
Feb 17 18:21:00 85d0c4a resin-supervisor[2439]: [info]    Supervisor v12.3.0 starting up...
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Setting host to discoverable
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [warn]    Invalid firewall mode: . Reverting to state: off
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    🔥 Applying firewall mode: off
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [debug]   Starting logging infrastructure
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [debug]   Performing database cleanup for container log timestamps
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Starting firewall
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [success] 🔥 Firewall mode applied
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [debug]   Starting api binder
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Previous engine snapshot was not stored. Skipping cleanup.
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [debug]   Handling of local mode switch is completed
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: (node:1) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    API Binder bound to: https://api.openbalena.local/v6/
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [event]   Event: Supervisor start {}
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [debug]   Connectivity check enabled: true
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [debug]   Starting periodic check for IP addresses
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Reporting initial state, supervisor version and API info
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Attempting to load any preloaded applications
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [debug]   VPN status path exists.
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    VPN connection is not active.
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Waiting for connectivity...
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Starting API server
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Supervisor API successfully started on port 48484
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    Applying target state
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [debug]   Ensuring device is provisioned
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [event]   Event: Device bootstrap {}
Feb 17 18:21:01 85d0c4a resin-supervisor[2439]: [info]    New device detected. Provisioning...
Feb 17 18:21:02 85d0c4a resin-supervisor[2439]: [debug]   Finished applying target state
Feb 17 18:21:02 85d0c4a resin-supervisor[2439]: [success] Device state apply success
Feb 17 18:21:04 85d0c4a resin-supervisor[2439]: [error]   LogBackend: unexpected error: Error
Feb 17 18:21:04 85d0c4a resin-supervisor[2439]: [error]         at /usr/src/app/dist/app.js:10:917150
Feb 17 18:21:04 85d0c4a resin-supervisor[2439]: [error]       at processTicksAndRejections (internal/process/task_queues.js:97:5)
Feb 17 18:21:04 85d0c4a resin-supervisor[2439]: [event]   Event: Device bootstrap failed, retrying {"delay":30000,"error":{"message":"","stack":"Error\n    at /usr/src/app/dist/app.js:10:917150\n    at processTicksAndRejections (internal/process/task_queues.js:97:5)"}}
Feb 17 18:21:34 85d0c4a resin-supervisor[2439]: [event]   Event: Device bootstrap {}
Feb 17 18:21:34 85d0c4a resin-supervisor[2439]: [info]    New device detected. Provisioning...
Feb 17 18:21:37 85d0c4a resin-supervisor[2439]: [event]   Event: Device bootstrap failed, retrying {"delay":30000,"error":{"message":"","stack":"Error\n    at /usr/src/app/dist/app.js:10:917150\n    at processTicksAndRejections (internal/process/task_queues.js:97:5)"}}

Even when forcing the device to join my server with balena join 192.168.1.118, the list from balena devices stays empty.

What do I miss in the process?

Best regards,

Maikel Coenen

Hi there, welcome to the openBalena forums! Great to hear you’re getting set up for the first time. We’re happy to help.

I’ve pinged one of the openBalena maintainers to take a closer look at the issue you’re facing, but in the meantime, can you please confirm the balenaOS version you’re running? I assume you mean you’re running supervisor version 12.3.0. Did you download the OS from balenaOS - Run Docker containers on embedded IoT devices?

Ah yes, sorry for the confusion. I’ve downloaded the OS yesterday from the webpage indeed. It is balenaOS 2.67.3 rev 4 with supervisor 12.3.0.

I also tried to build it myself with Yocto which resulted in the same problem.

There seems to be an issue with the device communicating with the backend – the logs show that both the logging backend and device registration failed, with no actual error message unfortunately.

To debug this, can you please try running the same curl command from inside the device? This will rule out any network issues. Also, what do backend API logs show from around the time the device tries to communicate? You can extract service logs with ./scripts/compose exec api journalctl --no-pager. It may also be useful to reboot the device before looking at API logs, so it begins the cycle again and you can get fresh ones.

curl from rpi results in the same:
root@85d0c4a:~# curl api.openbalena.local/ping
OK

Hereby the log but cannot see much about a communication between the device and the backend

Feb 18 13:06:21 89bafd000208 api[986]: ORDER BY "permission"."name" ASC [ 'On57mMigOImDJqttiLQHU02I225V2vD4' ]
Feb 18 13:06:21 89bafd000208 api[986]: Parsing GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='On57mMigOImDJqttiLQHU02I225V2vD4'
Feb 18 13:06:21 89bafd000208 api[986]: Running GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='On57mMigOImDJqttiLQHU02I225V2vD4'
Feb 18 13:06:21 89bafd000208 api[986]: SELECT "api key"."is of-actor" AS "is_of__actor"
Feb 18 13:06:21 89bafd000208 api[986]: FROM "api key"
Feb 18 13:06:21 89bafd000208 api[986]: WHERE ("api key"."key") IS NOT NULL AND ("api key"."key") = ($1) [ 'On57mMigOImDJqttiLQHU02I225V2vD4' ]
Feb 18 13:06:21 89bafd000208 api[986]: Parsing GET /resin/device(uuid=@uuid)?$select=id&@uuid='85d0c4a33a5b40fcef8b65acfc4cfc43'
Feb 18 13:06:21 89bafd000208 api[986]: 2021-02-18T13:06:21.445Z 172.20.0.8 a/4 GET /services/vpn/auth/85d0c4a33a5b40fcef8b65acfc4cfc43 401 9.540ms -
Feb 18 13:06:25 89bafd000208 api[986]: Parsing GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:25 89bafd000208 api[986]: Running GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:25 89bafd000208 api[986]: SELECT "permission"."name"
Feb 18 13:06:25 89bafd000208 api[986]: FROM "permission"
Feb 18 13:06:25 89bafd000208 api[986]: WHERE (EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:         FROM "api key-has-permission" AS "permission.api key-has-permission"
Feb 18 13:06:25 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.api key-has-permission"."permission"
Feb 18 13:06:25 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:                 FROM "api key" AS "permission.api key-has-permission.api key"
Feb 18 13:06:25 89bafd000208 api[986]:                 WHERE "permission.api key-has-permission"."api key" = "permission.api key-has-permission.api key"."id"
Feb 18 13:06:25 89bafd000208 api[986]:                 AND ("permission.api key-has-permission.api key"."key") IS NOT NULL AND ("permission.api key-has-permission.api key"."key") = ($1)
Feb 18 13:06:25 89bafd000208 api[986]:         )
Feb 18 13:06:25 89bafd000208 api[986]: )
Feb 18 13:06:25 89bafd000208 api[986]: OR EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:         FROM "role-has-permission" AS "permission.role-has-permission"
Feb 18 13:06:25 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.role-has-permission"."permission"
Feb 18 13:06:25 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:                 FROM "role" AS "permission.role-has-permission.role"
Feb 18 13:06:25 89bafd000208 api[986]:                 WHERE "permission.role-has-permission"."role" = "permission.role-has-permission.role"."id"
Feb 18 13:06:25 89bafd000208 api[986]:                 AND EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:                         SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:                         FROM "api key-has-role" AS "permission.role-has-permission.role.api key-has-role"
Feb 18 13:06:25 89bafd000208 api[986]:                         WHERE "permission.role-has-permission.role"."id" = "permission.role-has-permission.role.api key-has-role"."role"
Feb 18 13:06:25 89bafd000208 api[986]:                         AND EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:                                 SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:                                 FROM "api key" AS "permission.role-has-permission.role.api key-has-role.api key"
Feb 18 13:06:25 89bafd000208 api[986]:                                 WHERE "permission.role-has-permission.role.api key-has-role"."api key" = "permission.role-has-permission.role.api key-has-role.api key"."id"
Feb 18 13:06:25 89bafd000208 api[986]:                                 AND ("permission.role-has-permission.role.api key-has-role.api key"."key") IS NOT NULL AND ("permission.role-has-permission.role.api key-has-role.api key"."key") = ($1)
Feb 18 13:06:25 89bafd000208 api[986]:                         )
Feb 18 13:06:25 89bafd000208 api[986]:                 )
Feb 18 13:06:25 89bafd000208 api[986]:         )
Feb 18 13:06:25 89bafd000208 api[986]: ))
Feb 18 13:06:25 89bafd000208 api[986]: ORDER BY "permission"."name" ASC [ 'IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7' ]
Feb 18 13:06:25 89bafd000208 api[986]: Parsing GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:25 89bafd000208 api[986]: Running GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:25 89bafd000208 api[986]: SELECT "api key"."is of-actor" AS "is_of__actor"
Feb 18 13:06:25 89bafd000208 api[986]: FROM "api key"
Feb 18 13:06:25 89bafd000208 api[986]: WHERE ("api key"."key") IS NOT NULL AND ("api key"."key") = ($1) [ 'IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7' ]
Feb 18 13:06:25 89bafd000208 api[986]: Parsing PATCH /resin/service_instance(7)
Feb 18 13:06:25 89bafd000208 api[986]: Parsing GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:25 89bafd000208 api[986]: Running GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:25 89bafd000208 api[986]: SELECT "permission"."name"
Feb 18 13:06:25 89bafd000208 api[986]: FROM "permission"
Feb 18 13:06:25 89bafd000208 api[986]: WHERE (EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:         FROM "api key-has-permission" AS "permission.api key-has-permission"
Feb 18 13:06:25 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.api key-has-permission"."permission"
Feb 18 13:06:25 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:                 FROM "api key" AS "permission.api key-has-permission.api key"
Feb 18 13:06:25 89bafd000208 api[986]:                 WHERE "permission.api key-has-permission"."api key" = "permission.api key-has-permission.api key"."id"
Feb 18 13:06:25 89bafd000208 api[986]:                 AND ("permission.api key-has-permission.api key"."key") IS NOT NULL AND ("permission.api key-has-permission.api key"."key") = ($1)
Feb 18 13:06:25 89bafd000208 api[986]:         )
Feb 18 13:06:25 89bafd000208 api[986]: )
Feb 18 13:06:25 89bafd000208 api[986]: OR EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:         FROM "role-has-permission" AS "permission.role-has-permission"
Feb 18 13:06:25 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.role-has-permission"."permission"
Feb 18 13:06:25 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:                 FROM "role" AS "permission.role-has-permission.role"
Feb 18 13:06:25 89bafd000208 api[986]:                 WHERE "permission.role-has-permission"."role" = "permission.role-has-permission.role"."id"
Feb 18 13:06:25 89bafd000208 api[986]:                 AND EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:                         SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:                         FROM "api key-has-role" AS "permission.role-has-permission.role.api key-has-role"
Feb 18 13:06:25 89bafd000208 api[986]:                         WHERE "permission.role-has-permission.role"."id" = "permission.role-has-permission.role.api key-has-role"."role"
Feb 18 13:06:25 89bafd000208 api[986]:                         AND EXISTS (
Feb 18 13:06:25 89bafd000208 api[986]:                                 SELECT 1
Feb 18 13:06:25 89bafd000208 api[986]:                                 FROM "api key" AS "permission.role-has-permission.role.api key-has-role.api key"
Feb 18 13:06:25 89bafd000208 api[986]:                                 WHERE "permission.role-has-permission.role.api key-has-role"."api key" = "permission.role-has-permission.role.api key-has-role.api key"."id"
Feb 18 13:06:25 89bafd000208 api[986]:                                 AND ("permission.role-has-permission.role.api key-has-role.api key"."key") IS NOT NULL AND ("permission.role-has-permission.role.api key-has-role.api key"."key") = ($1)
Feb 18 13:06:25 89bafd000208 api[986]:                         )
Feb 18 13:06:25 89bafd000208 api[986]:                 )
Feb 18 13:06:25 89bafd000208 api[986]:         )
Feb 18 13:06:25 89bafd000208 api[986]: ))
Feb 18 13:06:25 89bafd000208 api[986]: ORDER BY "permission"."name" ASC [ 'IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7' ]
Feb 18 13:06:25 89bafd000208 api[986]: Parsing GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:25 89bafd000208 api[986]: Running GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:25 89bafd000208 api[986]: SELECT "api key"."is of-actor" AS "is_of__actor"
Feb 18 13:06:25 89bafd000208 api[986]: FROM "api key"
Feb 18 13:06:25 89bafd000208 api[986]: WHERE ("api key"."key") IS NOT NULL AND ("api key"."key") = ($1) [ 'IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7' ]
Feb 18 13:06:25 89bafd000208 api[986]: Running PATCH /resin/service_instance(7)
Feb 18 13:06:25 89bafd000208 api[986]: UPDATE "service instance"
Feb 18 13:06:25 89bafd000208 api[986]: SET "last heartbeat" = $1
Feb 18 13:06:25 89bafd000208 api[986]: WHERE ("service instance"."id") IS NOT NULL AND ("service instance"."id") = ($2)
Feb 18 13:06:25 89bafd000208 api[986]: AND "service instance"."id" IN ((
Feb 18 13:06:25 89bafd000208 api[986]:         SELECT "service instance"."id"
Feb 18 13:06:25 89bafd000208 api[986]:         FROM (
Feb 18 13:06:25 89bafd000208 api[986]:                 SELECT "service instance"."created at", "service instance"."modified at", "service instance"."id", "service instance"."service type", "service instance"."ip address", "service instance"."last heartbeat"
Feb 18 13:06:25 89bafd000208 api[986]:                 FROM "service instance"
Feb 18 13:06:25 89bafd000208 api[986]:         ) AS "service instance"
Feb 18 13:06:25 89bafd000208 api[986]: )) [ 2021-02-18T13:06:25.565Z, 7 ]
Feb 18 13:06:25 89bafd000208 api[986]: 2021-02-18T13:06:25.569Z 172.20.0.8 s/vpn PATCH /resin/service_instance(7) 200 23.459ms -
Feb 18 13:06:34 89bafd000208 api[986]: Parsing GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='On57mMigOImDJqttiLQHU02I225V2vD4'
Feb 18 13:06:34 89bafd000208 api[986]: Running GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='On57mMigOImDJqttiLQHU02I225V2vD4'
Feb 18 13:06:34 89bafd000208 api[986]: SELECT "permission"."name"
Feb 18 13:06:34 89bafd000208 api[986]: FROM "permission"
Feb 18 13:06:34 89bafd000208 api[986]: WHERE (EXISTS (
Feb 18 13:06:34 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:34 89bafd000208 api[986]:         FROM "api key-has-permission" AS "permission.api key-has-permission"
Feb 18 13:06:34 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.api key-has-permission"."permission"
Feb 18 13:06:34 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:34 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:34 89bafd000208 api[986]:                 FROM "api key" AS "permission.api key-has-permission.api key"
Feb 18 13:06:34 89bafd000208 api[986]:                 WHERE "permission.api key-has-permission"."api key" = "permission.api key-has-permission.api key"."id"
Feb 18 13:06:34 89bafd000208 api[986]:                 AND ("permission.api key-has-permission.api key"."key") IS NOT NULL AND ("permission.api key-has-permission.api key"."key") = ($1)
Feb 18 13:06:34 89bafd000208 api[986]:         )
Feb 18 13:06:34 89bafd000208 api[986]: )
Feb 18 13:06:34 89bafd000208 api[986]: OR EXISTS (
Feb 18 13:06:34 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:34 89bafd000208 api[986]:         FROM "role-has-permission" AS "permission.role-has-permission"
Feb 18 13:06:34 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.role-has-permission"."permission"
Feb 18 13:06:34 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:34 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:34 89bafd000208 api[986]:                 FROM "role" AS "permission.role-has-permission.role"
Feb 18 13:06:34 89bafd000208 api[986]:                 WHERE "permission.role-has-permission"."role" = "permission.role-has-permission.role"."id"
Feb 18 13:06:34 89bafd000208 api[986]:                 AND EXISTS (
Feb 18 13:06:34 89bafd000208 api[986]:                         SELECT 1
Feb 18 13:06:34 89bafd000208 api[986]:                         FROM "api key-has-role" AS "permission.role-has-permission.role.api key-has-role"
Feb 18 13:06:34 89bafd000208 api[986]:                         WHERE "permission.role-has-permission.role"."id" = "permission.role-has-permission.role.api key-has-role"."role"
Feb 18 13:06:34 89bafd000208 api[986]:                         AND EXISTS (
Feb 18 13:06:34 89bafd000208 api[986]:                                 SELECT 1
Feb 18 13:06:34 89bafd000208 api[986]:                                 FROM "api key" AS "permission.role-has-permission.role.api key-has-role.api key"
Feb 18 13:06:34 89bafd000208 api[986]:                                 WHERE "permission.role-has-permission.role.api key-has-role"."api key" = "permission.role-has-permission.role.api key-has-role.api key"."id"
Feb 18 13:06:34 89bafd000208 api[986]:                                 AND ("permission.role-has-permission.role.api key-has-role.api key"."key") IS NOT NULL AND ("permission.role-has-permission.role.api key-has-role.api key"."key") = ($1)
Feb 18 13:06:34 89bafd000208 api[986]:                         )
Feb 18 13:06:34 89bafd000208 api[986]:                 )
Feb 18 13:06:34 89bafd000208 api[986]:         )
Feb 18 13:06:34 89bafd000208 api[986]: ))
Feb 18 13:06:34 89bafd000208 api[986]: ORDER BY "permission"."name" ASC [ 'On57mMigOImDJqttiLQHU02I225V2vD4' ]
Feb 18 13:06:34 89bafd000208 api[986]: Parsing GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='On57mMigOImDJqttiLQHU02I225V2vD4'
Feb 18 13:06:34 89bafd000208 api[986]: Running GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='On57mMigOImDJqttiLQHU02I225V2vD4'
Feb 18 13:06:34 89bafd000208 api[986]: SELECT "api key"."is of-actor" AS "is_of__actor"
Feb 18 13:06:34 89bafd000208 api[986]: FROM "api key"
Feb 18 13:06:34 89bafd000208 api[986]: WHERE ("api key"."key") IS NOT NULL AND ("api key"."key") = ($1) [ 'On57mMigOImDJqttiLQHU02I225V2vD4' ]
Feb 18 13:06:34 89bafd000208 api[986]: Parsing GET /resin/device(uuid=@uuid)?$select=id&@uuid='85d0c4a33a5b40fcef8b65acfc4cfc43'
Feb 18 13:06:34 89bafd000208 api[986]: 2021-02-18T13:06:34.181Z 172.20.0.8 a/4 GET /services/vpn/auth/85d0c4a33a5b40fcef8b65acfc4cfc43 401 6.784ms -
Feb 18 13:06:35 89bafd000208 api[986]: Parsing GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:35 89bafd000208 api[986]: Running GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:35 89bafd000208 api[986]: SELECT "permission"."name"
Feb 18 13:06:35 89bafd000208 api[986]: FROM "permission"
Feb 18 13:06:35 89bafd000208 api[986]: WHERE (EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:         FROM "api key-has-permission" AS "permission.api key-has-permission"
Feb 18 13:06:35 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.api key-has-permission"."permission"
Feb 18 13:06:35 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:                 FROM "api key" AS "permission.api key-has-permission.api key"
Feb 18 13:06:35 89bafd000208 api[986]:                 WHERE "permission.api key-has-permission"."api key" = "permission.api key-has-permission.api key"."id"
Feb 18 13:06:35 89bafd000208 api[986]:                 AND ("permission.api key-has-permission.api key"."key") IS NOT NULL AND ("permission.api key-has-permission.api key"."key") = ($1)
Feb 18 13:06:35 89bafd000208 api[986]:         )
Feb 18 13:06:35 89bafd000208 api[986]: )
Feb 18 13:06:35 89bafd000208 api[986]: OR EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:         FROM "role-has-permission" AS "permission.role-has-permission"
Feb 18 13:06:35 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.role-has-permission"."permission"
Feb 18 13:06:35 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:                 FROM "role" AS "permission.role-has-permission.role"
Feb 18 13:06:35 89bafd000208 api[986]:                 WHERE "permission.role-has-permission"."role" = "permission.role-has-permission.role"."id"
Feb 18 13:06:35 89bafd000208 api[986]:                 AND EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:                         SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:                         FROM "api key-has-role" AS "permission.role-has-permission.role.api key-has-role"
Feb 18 13:06:35 89bafd000208 api[986]:                         WHERE "permission.role-has-permission.role"."id" = "permission.role-has-permission.role.api key-has-role"."role"
Feb 18 13:06:35 89bafd000208 api[986]:                         AND EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:                                 SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:                                 FROM "api key" AS "permission.role-has-permission.role.api key-has-role.api key"
Feb 18 13:06:35 89bafd000208 api[986]:                                 WHERE "permission.role-has-permission.role.api key-has-role"."api key" = "permission.role-has-permission.role.api key-has-role.api key"."id"
Feb 18 13:06:35 89bafd000208 api[986]:                                 AND ("permission.role-has-permission.role.api key-has-role.api key"."key") IS NOT NULL AND ("permission.role-has-permission.role.api key-has-role.api key"."key") = ($1)
Feb 18 13:06:35 89bafd000208 api[986]:                         )
Feb 18 13:06:35 89bafd000208 api[986]:                 )
Feb 18 13:06:35 89bafd000208 api[986]:         )
Feb 18 13:06:35 89bafd000208 api[986]: ))
Feb 18 13:06:35 89bafd000208 api[986]: ORDER BY "permission"."name" ASC [ 'IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7' ]
Feb 18 13:06:35 89bafd000208 api[986]: Parsing GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:35 89bafd000208 api[986]: Running GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:35 89bafd000208 api[986]: SELECT "api key"."is of-actor" AS "is_of__actor"
Feb 18 13:06:35 89bafd000208 api[986]: FROM "api key"
Feb 18 13:06:35 89bafd000208 api[986]: WHERE ("api key"."key") IS NOT NULL AND ("api key"."key") = ($1) [ 'IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7' ]
Feb 18 13:06:35 89bafd000208 api[986]: Parsing PATCH /resin/service_instance(7)
Feb 18 13:06:35 89bafd000208 api[986]: Parsing GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:35 89bafd000208 api[986]: Running GET /Auth/permission?$select=name&$filter=(is_of__api_key/any(khp:khp/api_key/any(k:k/key eq @apiKey))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__api_key/any(khr:khr/api_key/any(k:k/key eq @apiKey)))))&$orderby=name asc&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:35 89bafd000208 api[986]: SELECT "permission"."name"
Feb 18 13:06:35 89bafd000208 api[986]: FROM "permission"
Feb 18 13:06:35 89bafd000208 api[986]: WHERE (EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:         FROM "api key-has-permission" AS "permission.api key-has-permission"
Feb 18 13:06:35 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.api key-has-permission"."permission"
Feb 18 13:06:35 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:                 FROM "api key" AS "permission.api key-has-permission.api key"
Feb 18 13:06:35 89bafd000208 api[986]:                 WHERE "permission.api key-has-permission"."api key" = "permission.api key-has-permission.api key"."id"
Feb 18 13:06:35 89bafd000208 api[986]:                 AND ("permission.api key-has-permission.api key"."key") IS NOT NULL AND ("permission.api key-has-permission.api key"."key") = ($1)
Feb 18 13:06:35 89bafd000208 api[986]:         )
Feb 18 13:06:35 89bafd000208 api[986]: )
Feb 18 13:06:35 89bafd000208 api[986]: OR EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:         SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:         FROM "role-has-permission" AS "permission.role-has-permission"
Feb 18 13:06:35 89bafd000208 api[986]:         WHERE "permission"."id" = "permission.role-has-permission"."permission"
Feb 18 13:06:35 89bafd000208 api[986]:         AND EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:                 SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:                 FROM "role" AS "permission.role-has-permission.role"
Feb 18 13:06:35 89bafd000208 api[986]:                 WHERE "permission.role-has-permission"."role" = "permission.role-has-permission.role"."id"
Feb 18 13:06:35 89bafd000208 api[986]:                 AND EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:                         SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:                         FROM "api key-has-role" AS "permission.role-has-permission.role.api key-has-role"
Feb 18 13:06:35 89bafd000208 api[986]:                         WHERE "permission.role-has-permission.role"."id" = "permission.role-has-permission.role.api key-has-role"."role"
Feb 18 13:06:35 89bafd000208 api[986]:                         AND EXISTS (
Feb 18 13:06:35 89bafd000208 api[986]:                                 SELECT 1
Feb 18 13:06:35 89bafd000208 api[986]:                                 FROM "api key" AS "permission.role-has-permission.role.api key-has-role.api key"
Feb 18 13:06:35 89bafd000208 api[986]:                                 WHERE "permission.role-has-permission.role.api key-has-role"."api key" = "permission.role-has-permission.role.api key-has-role.api key"."id"
Feb 18 13:06:35 89bafd000208 api[986]:                                 AND ("permission.role-has-permission.role.api key-has-role.api key"."key") IS NOT NULL AND ("permission.role-has-permission.role.api key-has-role.api key"."key") = ($1)
Feb 18 13:06:35 89bafd000208 api[986]:                         )
Feb 18 13:06:35 89bafd000208 api[986]:                 )
Feb 18 13:06:35 89bafd000208 api[986]:         )
Feb 18 13:06:35 89bafd000208 api[986]: ))
Feb 18 13:06:35 89bafd000208 api[986]: ORDER BY "permission"."name" ASC [ 'IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7' ]
Feb 18 13:06:35 89bafd000208 api[986]: Parsing GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:35 89bafd000208 api[986]: Running GET /Auth/api_key(key=@apiKey)?$select=is_of__actor&@apiKey='IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7'
Feb 18 13:06:35 89bafd000208 api[986]: SELECT "api key"."is of-actor" AS "is_of__actor"
Feb 18 13:06:35 89bafd000208 api[986]: FROM "api key"
Feb 18 13:06:35 89bafd000208 api[986]: WHERE ("api key"."key") IS NOT NULL AND ("api key"."key") = ($1) [ 'IljtyPCHHqXkeD4GwBz2TZwmw8Ca8TB7' ]
Feb 18 13:06:35 89bafd000208 api[986]: Running PATCH /resin/service_instance(7)
Feb 18 13:06:35 89bafd000208 api[986]: UPDATE "service instance"
Feb 18 13:06:35 89bafd000208 api[986]: SET "last heartbeat" = $1
Feb 18 13:06:35 89bafd000208 api[986]: WHERE ("service instance"."id") IS NOT NULL AND ("service instance"."id") = ($2)
Feb 18 13:06:35 89bafd000208 api[986]: AND "service instance"."id" IN ((
Feb 18 13:06:35 89bafd000208 api[986]:         SELECT "service instance"."id"
Feb 18 13:06:35 89bafd000208 api[986]:         FROM (
Feb 18 13:06:35 89bafd000208 api[986]:                 SELECT "service instance"."created at", "service instance"."modified at", "service instance"."id", "service instance"."service type", "service instance"."ip address", "service instance"."last heartbeat"
Feb 18 13:06:35 89bafd000208 api[986]:                 FROM "service instance"
Feb 18 13:06:35 89bafd000208 api[986]:         ) AS "service instance"
Feb 18 13:06:35 89bafd000208 api[986]: )) [ 2021-02-18T13:06:35.600Z, 7 ]
Feb 18 13:06:35 89bafd000208 api[986]: 2021-02-18T13:06:35.606Z 172.20.0.8 s/vpn PATCH /resin/service_instance(7) 200 26.367ms -

Full log:
api.log (7.1 MB)

Possibly found a problem after looking at this post: Device registration fails with open balena

The balenaRootCA stored in config.json is not the same as the certificate I receive with openssl s_client -connect api.openbalena.local:443. Maybe that could also clarify the errors in the vpn container?

Feb 18 15:09:33 5310aba944d1 haproxy[174]: Routing 172.21.0.1:56614@tcp-443 to vpn-workers/vpn1:41298 [C:1/1 Q:0/0 T:1/0]

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] TCP connection established with [AF_INET]127.0.0.1:41298

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] Socket flags: TCP_NODELAY=1 succeeded

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 TLS: Initial packet from [AF_INET]127.0.0.1:41298, sid=6b7a6e95 8c678615

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_VER=2.4.7

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_PLAT=linux

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_PROTO=2

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_NCP=2

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_LZ4=1

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_LZ4v2=1

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_LZO=1

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_COMP_STUB=1

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_COMP_STUBv2=1

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 peer info: IV_TCPNL=1

Feb 18 15:09:33 5310aba944d1 vpn[1011]: info: [vpn-8] AUTH FAIL: API Authentication failed for 85d0c4a33a5b40fcef8b65acfc4cfc43

Feb 18 15:09:33 5310aba944d1 vpn[1011]: ::ffff:127.0.0.1 - - [18/Feb/2021:15:09:33 +0000] "POST /api/v1/auth/ HTTP/1.1" 401 12 "-" "curl/7.64.0"

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 WARNING: Failed running command (--auth-user-pass-verify): external program exited with error status: 1

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 TLS Auth Error: Auth Username/Password verification failed for peer

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384

Feb 18 15:09:33 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 Peer Connection Initiated with [AF_INET]127.0.0.1:41298

Feb 18 15:09:35 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 PUSH: Received control message: 'PUSH_REQUEST'

Feb 18 15:09:35 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 Delayed exit in 5 seconds

Feb 18 15:09:35 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 SENT CONTROL [UNDEF]: 'AUTH_FAILED' (status=1)

Feb 18 15:09:35 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 Connection reset, restarting [0]

Feb 18 15:09:35 5310aba944d1 vpn[1011]: notice: [vpn-8.1] 127.0.0.1:41298 SIGUSR1[soft,connection-reset] received, client-instance restarting

Hey Maikel-coenen, indeed both the certificate on config.json and balenaRootCa value have to be the same.
Try getting the certificate running openssl s_client -connect api.openbalena.local:443 and include it in the config.json file.
That will make the server to recognise the device and authorize it.
Give it a try and let us know!

Included the certificate in config.json but no difference, same error message as above.

Found some more errors but not sure if it is related. It is from the registry container of open-balena:

Feb 19 08:42:58 ffa60f1fb87c configure-balena-root-ca.sh[58]: 1 added, 0 removed; done.

Feb 19 08:42:58 ffa60f1fb87c configure-balena-root-ca.sh[58]: Running hooks in /etc/ca-certificates/update.d...

Feb 19 08:42:58 ffa60f1fb87c configure-balena-root-ca.sh[58]: done.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: Started balena-root-ca.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: Started balena-registry.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: Startup finished in 1.872s.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Service RestartSec=100ms expired, scheduling restart.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Scheduled restart job, restart counter is at 5.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: Stopped System Logging Service.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Start request repeated too quickly.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Failed with result 'exit-code'.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: Failed to start System Logging Service.

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: syslog.socket: Failed with result 'service-start-limit-hit'.

Feb 19 08:58:34 ffa60f1fb87c systemd[1]: Starting Cleanup of Temporary Directories...

Feb 19 08:58:34 ffa60f1fb87c systemd[1]: systemd-tmpfiles-clean.service: Succeeded.

Feb 19 08:58:34 ffa60f1fb87c systemd[1]: Started Cleanup of Temporary Directories.

And the status of rsyslog:

● rsyslog.service - System Logging Service
   Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Fri 2021-02-19 08:42:58 UTC; 37min ago
     Docs: man:rsyslogd(8)
           https://www.rsyslog.com/doc/
  Process: 908 ExecStart=/usr/sbin/rsyslogd -n -iNONE (code=exited, status=1/FAILURE)
 Main PID: 908 (code=exited, status=1/FAILURE)

Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Failed to kill control group /system.slice/rsyslog.service, ignoring: Input/output error
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Failed to kill control group /system.slice/rsyslog.service, ignoring: Input/output error
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Failed with result 'exit-code'.
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: Failed to start System Logging Service.
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Service RestartSec=100ms expired, scheduling restart.
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Scheduled restart job, restart counter is at 5.
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: Stopped System Logging Service.
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Start request repeated too quickly.
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: rsyslog.service: Failed with result 'exit-code'.
Feb 19 08:42:58 ffa60f1fb87c systemd[1]: Failed to start System Logging Service.

Hi there, rsyslog might be a different, unrelated problem. It shouldn’t cause openBalena components to fail. Does openssl s_client -connect api.openbalena.local:443 on the openBalena server result in a correct TLS handshake or an error? How about curl https://api.openbalena.local/ping?