openBalena VPN and API fail

openBalena
#1

Hi all,

I’ve created an openBalena server, but after a few days, I got some errors.
First, I’ve added a new device, but it couldn’t connect to the VPN for some reason (state stayed inactive).
After that, I tried to download the balenaOS image again for the Raspberry Pi 4, and tried the command:

balena os configure <image-location> --app <app>

But I got the following error:

ECONNRESET: request to https://api.<balena-server>/download-config failed, reason: socket hang up

FetchError: request to https://api.<balena-server>/download-config failed, reason: socket hang up
    at ClientRequest.<anonymous> (/usr/local/lib/node_modules/balena-cli/node_modules/node-fetch/index.js:133:11)
    at ClientRequest.emit (events.js:327:22)
    at ClientRequest.EventEmitter.emit (domain.js:485:12)
    at TLSSocket.socketOnEnd (_http_client.js:463:9)
    at TLSSocket.emit (events.js:327:22)
    at TLSSocket.EventEmitter.emit (domain.js:485:12)
    at endReadableNT (_stream_readable.js:1201:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:21)
From previous event:
    at new Fetch (/usr/local/lib/node_modules/balena-cli/node_modules/node-fetch/index.js:49:9)
    at Fetch (/usr/local/lib/node_modules/balena-cli/node_modules/node-fetch/index.js:37:10)
    at /usr/local/lib/node_modules/balena-cli/node_modules/fetch-ponyfill/fetch-node.js:15:12
    at requestAsync (/usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/utils.js:327:7)
From previous event:
    at requestAsync (/usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/utils.js:346:22)
    at /usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/utils.js:396:12
    at /usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/request.js:176:14
From previous event:
    at Object.exports.send (/usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/request.js:175:89)
    at /usr/local/lib/node_modules/balena-cli/node_modules/balena-sdk/build/models/os.js:430:32
    at processImmediate (internal/timers.js:456:21)
    at process.topLevelDomainCallback (domain.js:137:15)
From previous event:
    at /usr/local/lib/node_modules/balena-cli/node_modules/balena-sdk/build/models/os.js:429:18
From previous event:
    at Object.getConfig (/usr/local/lib/node_modules/balena-cli/node_modules/balena-sdk/build/models/os.js:421:27)
    at generateBaseConfig (/usr/local/lib/node_modules/balena-cli/build/utils/config.js:8:53)
    at generateApplicationConfig (/usr/local/lib/node_modules/balena-cli/build/utils/config.js:21:12)
    at OsConfigureCmd.run (/usr/local/lib/node_modules/balena-cli/build/actions-oclif/os/configure.js:60:36)
    at async OsConfigureCmd._run (/usr/local/lib/node_modules/balena-cli/node_modules/@oclif/command/lib/command.js:44:20)
    at async Config.runCommand (/usr/local/lib/node_modules/balena-cli/node_modules/@oclif/config/lib/config.js:160:9)
    at async CustomMain.run (/usr/local/lib/node_modules/balena-cli/node_modules/@oclif/command/lib/main.js:21:9)
    at async CustomMain._run (/usr/local/lib/node_modules/balena-cli/node_modules/@oclif/command/lib/command.js:44:20)
    at async Promise.all (index 1)
    at async Object.run (/usr/local/lib/node_modules/balena-cli/build/app-oclif.js:30:9)
    at async routeCliFramework (/usr/local/lib/node_modules/balena-cli/build/preparser.js:41:9)
    at async Object.run (/usr/local/lib/node_modules/balena-cli/build/app.js:14:5)

I don’t know how to get more logs from the openBalena server, because the container only says it’s initialized.

Does anybody have any clue about what’s going on here? Because we’d love to use openBalena

#2

The only other logs I could find was from the openbalena_db_1

2020-05-12 10:07:18.540 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2020-05-12 10:07:18.540 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2020-05-12 10:07:18.542 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-05-12 10:07:18.613 UTC [23] LOG:  database system was shut down at 2020-05-12 09:54:40 UTC
2020-05-12 10:07:18.657 UTC [1] LOG:  database system is ready to accept connections
2020-05-12 10:07:30.258 UTC [30] ERROR:  relation "uniq_model_model_type_vocab" already exists
2020-05-12 10:07:30.258 UTC [30] STATEMENT:  CREATE UNIQUE INDEX "uniq_model_model_type_vocab" ON "model" ("is of-vocabulary", "model type");
#3

When creating an app, I also get about the same error:

DEBUG=1 balena app create test-app
[debug] original argv0="node" argv=[/usr/local/bin/node,/usr/local/bin/balena,app,create,test-app] length=5
[debug] new argv=[/usr/local/bin/node,/usr/local/bin/balena,app:create,test-app] length=4
ECONNRESET: request to https://api.<balena-server>/device-types/v1 failed, reason: socket hang up

FetchError: request to https://api.<balena-server>/device-types/v1 failed, reason: socket hang up
    at ClientRequest.<anonymous> (/usr/local/lib/node_modules/balena-cli/node_modules/node-fetch/index.js:133:11)
    at ClientRequest.emit (events.js:327:22)
    at ClientRequest.EventEmitter.emit (domain.js:485:12)
    at TLSSocket.socketOnEnd (_http_client.js:463:9)
    at TLSSocket.emit (events.js:327:22)
    at TLSSocket.EventEmitter.emit (domain.js:485:12)
    at endReadableNT (_stream_readable.js:1201:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:21)
From previous event:
    at new Fetch (/usr/local/lib/node_modules/balena-cli/node_modules/node-fetch/index.js:49:9)
    at Fetch (/usr/local/lib/node_modules/balena-cli/node_modules/node-fetch/index.js:37:10)
    at /usr/local/lib/node_modules/balena-cli/node_modules/fetch-ponyfill/fetch-node.js:15:12
    at requestAsync (/usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/utils.js:327:7)
From previous event:
    at requestAsync (/usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/utils.js:346:22)
    at /usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/utils.js:396:12
    at /usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/request.js:176:14
    at processImmediate (internal/timers.js:456:21)
From previous event:
    at Object.exports.send (/usr/local/lib/node_modules/balena-cli/node_modules/balena-request/build/request.js:175:89)
    at Object.getDeviceTypes (/usr/local/lib/node_modules/balena-cli/node_modules/balena-sdk/build/models/config.js:106:18)
    at Object.selectDeviceType (/usr/local/lib/node_modules/balena-cli/build/utils/patterns.js:90:24)
    at AppCreateCmd.run (/usr/local/lib/node_modules/balena-cli/build/actions-oclif/app/create.js:17:60)
    at runNextTicks (internal/process/task_queues.js:62:5)
    at processImmediate (internal/timers.js:429:9)
    at process.topLevelDomainCallback (domain.js:137:15)
    at async AppCreateCmd._run (/usr/local/lib/node_modules/balena-cli/node_modules/@oclif/command/lib/command.js:44:20)
    at async Config.runCommand (/usr/local/lib/node_modules/balena-cli/node_modules/@oclif/config/lib/config.js:160:9)
    at async CustomMain.run (/usr/local/lib/node_modules/balena-cli/node_modules/@oclif/command/lib/main.js:21:9)
    at async CustomMain._run (/usr/local/lib/node_modules/balena-cli/node_modules/@oclif/command/lib/command.js:44:20)
    at async Promise.all (index 1)
    at async Object.run (/usr/local/lib/node_modules/balena-cli/build/app-oclif.js:30:9)
    at async routeCliFramework (/usr/local/lib/node_modules/balena-cli/build/preparser.js:41:9)
    at async Object.run (/usr/local/lib/node_modules/balena-cli/build/app.js:14:5)

For help, visit our support forums: https://forums.balena.io
For bug reports or feature requests, see: https://github.com/balena-io/balena-cli/issues/
#4

Hi, it looks like the database is shutdown, can you restart the DB and share detailed logs on why it fails.

#5

Hi,

I’ve restarted the container with:

$ docker restart openbalena_db_1

And this is the output of:

$ docker logs openbalena_db_1

2020-05-12 10:07:18.540 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2020-05-12 10:07:18.540 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2020-05-12 10:07:18.542 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-05-12 10:07:18.613 UTC [23] LOG:  database system was shut down at 2020-05-12 09:54:40 UTC
2020-05-12 10:07:18.657 UTC [1] LOG:  database system is ready to accept connections
2020-05-12 10:07:30.258 UTC [30] ERROR:  relation "uniq_model_model_type_vocab" already exists
2020-05-12 10:07:30.258 UTC [30] STATEMENT:  CREATE UNIQUE INDEX "uniq_model_model_type_vocab" ON "model" ("is of-vocabulary", "model type");
2020-05-12 10:24:56.443 UTC [1] LOG:  received smart shutdown request
2020-05-12 10:24:56.447 UTC [1] LOG:  worker process: logical replication launcher (PID 29) exited with exit code 1
2020-05-12 10:25:07.209 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2020-05-12 10:25:07.209 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2020-05-12 10:25:07.211 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-05-12 10:25:07.227 UTC [22] LOG:  database system was interrupted; last known up at 2020-05-12 10:22:19 UTC
2020-05-12 10:25:07.263 UTC [22] LOG:  database system was not properly shut down; automatic recovery in progress
2020-05-12 10:25:07.265 UTC [22] LOG:  redo starts at 0/293E788
2020-05-12 10:25:07.266 UTC [22] LOG:  invalid record length at 0/293FAA8: wanted 24, got 0
2020-05-12 10:25:07.266 UTC [22] LOG:  redo done at 0/293FA80
2020-05-12 10:25:07.266 UTC [22] LOG:  last completed transaction was at log time 2020-05-12 10:25:00.040657+00
2020-05-12 10:25:07.277 UTC [1] LOG:  database system is ready to accept connections

But it still doesn’t work…

#7

Can you get the logs from the API server when making the CLI request please? This should tell use why the connection is being dropped prematurely.

#8

Hi,

I’d love to give you the logs from the API server, but when I execute:

$ docker logs openbalena_api_1

This is the response:

Systemd init system enabled.
#9

That’s strange, there should be a lot more logs than that. Perhaps try to restart and get the logs from then:

docker restart openbalena_api_1 && docker logs openbalena_api_1
#10

I’ve executed it, but same response

$ docker restart openbalena_api_1 && docker logs openbalena_api_1
openbalena_api_1
Systemd init system enabled.
Systemd init system enabled.
#11

FYI, this is the output of docker ps:

CONTAINER ID        IMAGE                                 COMMAND                  CREATED             STATUS              PORTS                                                                                           NAMES
b648518774aa        openbalena_haproxy                    "/docker-entrypoint.…"   About an hour ago   Up About an hour    0.0.0.0:80->80/tcp, 0.0.0.0:443->443/tcp, 222/tcp, 5432/tcp, 0.0.0.0:3128->3128/tcp, 6379/tcp   openbalena_haproxy_1
5c011b079cb4        balena/open-balena-vpn:v8.10.0        "/usr/bin/entry.sh"      About an hour ago   Up About an hour    80/tcp, 443/tcp, 3128/tcp                                                                       openbalena_vpn_1
95a06bd6b275        balena/open-balena-api:v0.19.5        "/usr/bin/entry.sh"      About an hour ago   Up 2 minutes        80/tcp                                                                                          openbalena_api_1
1370b81b25ce        balena/open-balena-registry:v2.11.1   "/usr/bin/entry.sh"      About an hour ago   Up About an hour    80/tcp                                                                                          openbalena_registry_1
953c21fb6ad9        balena/open-balena-s3:v2.8.5          "/usr/bin/entry.sh"      About an hour ago   Up About an hour    80/tcp                                                                                          openbalena_s3_1
a0abe2d66674        balena/open-balena-db:v2.0.3          "docker-entrypoint.s…"   About an hour ago   Up 56 minutes       5432/tcp                                                                                        openbalena_db_1
496b4ce9be62        redis:alpine                          "docker-entrypoint.s…"   About an hour ago   Up About an hour    6379/tcp                                                                                        openbalena_redis_1
a0ce9a2a0f41        openbalena_cert-provider              "/entry.sh /usr/src/…"   About an hour ago   Up About an hour    80/tcp                                                                                          openbalena_cert-provider_1

Just so you know all container versions etc

#13

Apologies, I had forgotten that the api logs to journald from within the container. To check these, do:

docker exec -it openbalena_api_1 bash
journalctl -f
#14

Tried that, at that shows a lot more logs. Here is the result after trying to create an app again openbalena.api.log (58.0 KB)

One of the interesting logs is probably:

May 12 11:43:32 95a06bd6b275 api[859]: Failed to get device types Inaccessible host: `resin-production-img-cloudformation.s3.amazonaws.com'. This service may not be available in the `us-east-1' region. UnknownEndpoint: Inaccessible host: `resin-production-img-cloudformation.s3.amazonaws.com'. This service may not be available in the `us-east-1' region.
May 12 11:43:32 95a06bd6b275 api[859]:     at Request.ENOTFOUND_ERROR (/usr/src/app/node_modules/aws-sdk/lib/event_listeners.js:494:46)
May 12 11:43:32 95a06bd6b275 api[859]:     at Request.callListeners (/usr/src/app/node_modules/aws-sdk/lib/sequential_executor.js:106:20)
May 12 11:43:32 95a06bd6b275 api[859]:     at Request.emit (/usr/src/app/node_modules/aws-sdk/lib/sequential_executor.js:78:10)
May 12 11:43:32 95a06bd6b275 api[859]:     at Request.emit (/usr/src/app/node_modules/aws-sdk/lib/request.js:683:14)
May 12 11:43:32 95a06bd6b275 api[859]:     at ClientRequest.error (/usr/src/app/node_modules/aws-sdk/lib/event_listeners.js:333:22)
May 12 11:43:32 95a06bd6b275 api[859]:     at ClientRequest.<anonymous> (/usr/src/app/node_modules/aws-sdk/lib/http/node.js:93:19)
May 12 11:43:32 95a06bd6b275 api[859]:     at ClientRequest.emit (events.js:189:13)
May 12 11:43:32 95a06bd6b275 api[859]:     at ClientRequest.EventEmitter.emit (domain.js:441:20)
May 12 11:43:32 95a06bd6b275 api[859]:     at TLSSocket.socketErrorListener (_http_client.js:392:9)
May 12 11:43:32 95a06bd6b275 api[859]:     at TLSSocket.emit (events.js:189:13)
May 12 11:43:32 95a06bd6b275 api[859]:     at TLSSocket.EventEmitter.emit (domain.js:441:20)
May 12 11:43:32 95a06bd6b275 api[859]:     at emitErrorNT (internal/streams/destroy.js:82:8)
May 12 11:43:32 95a06bd6b275 api[859]:     at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
May 12 11:43:32 95a06bd6b275 api[859]:     at process._tickCallback (internal/process/next_tick.js:63:19)
May 12 11:43:32 95a06bd6b275 api[859]: From previous event:
May 12 11:43:32 95a06bd6b275 api[859]:     at Object.listFolders (/usr/src/app/src/lib/device-types/storage/s3.ts:67:20)
May 12 11:43:32 95a06bd6b275 api[859]:     at fetchDeviceTypes (/usr/src/app/src/lib/device-types/index.ts:69:22)
May 12 11:43:32 95a06bd6b275 api[859]:     at ontimeout (timers.js:436:11)
May 12 11:43:32 95a06bd6b275 api[859]:     at tryOnTimeout (timers.js:300:5)
May 12 11:43:32 95a06bd6b275 api[859]:     at listOnTimeout (timers.js:263:5)
May 12 11:43:32 95a06bd6b275 api[859]:     at Timer.processTimers (timers.js:223:10)
May 12 11:43:32 95a06bd6b275 api[859]: From previous event:
May 12 11:43:32 95a06bd6b275 api[859]:     at fetchDeviceTypes (/usr/src/app/src/lib/device-types/index.ts:101:15)
May 12 11:43:32 95a06bd6b275 api[859]:     at fetchDeviceTypesAndReschedule (/usr/src/app/src/lib/device-types/index.ts:126:21)
May 12 11:43:32 95a06bd6b275 api[859]:     at getDeviceTypes (/usr/src/app/src/lib/device-types/index.ts:150:12)
May 12 11:43:32 95a06bd6b275 api[859]:     at Object.exports.deviceTypes (/usr/src/app/src/lib/device-types/index.ts:166:12)
May 12 11:43:32 95a06bd6b275 api[859]:     at exports.getDeviceTypes (/usr/src/app/src/routes/device-types.ts:8:6)
May 12 11:43:32 95a06bd6b275 api[859]:     at Layer.handle [as handle_request] (/usr/src/app/node_modules/express/lib/router/layer.js:95:5)
May 12 11:43:32 95a06bd6b275 api[859]:     at next (/usr/src/app/node_modules/express/lib/router/route.js:137:13)
May 12 11:43:32 95a06bd6b275 api[859]:     at Route.dispatch (/usr/src/app/node_modules/express/lib/router/route.js:112:3)
May 12 11:43:32 95a06bd6b275 api[859]:     at Layer.handle [as handle_request] (/usr/src/app/node_modules/express/lib/router/layer.js:95:5)
May 12 11:43:32 95a06bd6b275 api[859]:     at /usr/src/app/node_modules/express/lib/router/index.js:281:22
May 12 11:43:32 95a06bd6b275 api[859]:     at Function.process_params (/usr/src/app/node_modules/express/lib/router/index.js:335:12)
May 12 11:43:32 95a06bd6b275 api[859]:     at next (/usr/src/app/node_modules/express/lib/router/index.js:275:10)
May 12 11:43:32 95a06bd6b275 api[859]:     at passport.authenticate (/usr/src/app/src/platform/jwt.ts:104:9)
May 12 11:43:32 95a06bd6b275 api[859]:     at JwtStrategy.strategy.success (/usr/src/app/node_modules/passport/lib/middleware/authenticate.js:214:18)
May 12 11:43:32 95a06bd6b275 api[859]:     at verified (/usr/src/app/node_modules/passport-jwt/lib/strategy.js:115:41)
May 12 11:43:32 95a06bd6b275 api[859]:     at runCallback (timers.js:705:18)
May 12 11:43:32 95a06bd6b275 api[859]:     at tryOnImmediate (timers.js:676:5)
May 12 11:43:32 95a06bd6b275 api[859]:     at processImmediate (timers.js:658:5)
May 12 11:43:32 95a06bd6b275 api[859]:     at process.topLevelDomainCallback (domain.js:120:23)
#16

Seems to me like a network issue with the server. Can you try running curl -iI https://resin-production-img-cloudformation.s3.amazonaws.com/ from inside the server?

#18

Hi,

Thanks for your reply. After some hours yesterday, the openBalena server seems to work again.
I’ve ran your command and got the following output:

HTTP/1.1 200 OK
x-amz-id-2: ujTacmZ9ok3Vh9PXXev6p7mf86dInlO/hE9FZd1rAwBKjznI+zH1svJlKPitFhykj9YPLjb7Zjk=
x-amz-request-id: BE91C7D193F40F9F
Date: Wed, 13 May 2020 10:27:00 GMT
x-amz-bucket-region: us-east-1
Content-Type: application/xml
Transfer-Encoding: chunked
Server: AmazonS3

My server was connected to the internet (of course) and I didn’t change anything about the firewall and/or network settings. Server is running Debian 10.

On one hand, I’m happy it’s working now. But on the other hand, I’m not satisfied because I could not determine what the issue was…

#19

Hey there, great that the issue got resolved! As dfunckt mentioned, it sounds like there were some networking issues and it doesn’t sound like an issue with openBalena itself. Please let us know if you experience the same thing again, and we can investigate further. Have a nice day!