Openbalena crash logs


#1

I have noted a couple of times that my openbalena backend instance gives http error 503 Service Unavailable when trying to execute commands using balena-cli.
Is there any logs in the openbalena backend side that I can check to see what is causing this?

So far the only workaround I found is to restart openbalena app.

Any help is appreciated.


#6

Sure thing @rlev

So if you’re getting a 503 error then it means that one of the backend services, probably the API, has crashed out and isn’t responding. You can check this by finding the container name/ID of the API container, then running the command below:

$ docker exec -it <name or ID> journalctl -u open-balena-api -fn100

This should show some logs and possibly an exception. Screenshot attached for an example.


#9

Thank you for getting back @richbayliss.

Question :

What would be a good way to monitor that the openbalena api service is running OK and in case is not do a service restart automatically?

Thanks


#10

It shouldn’t be getting into a state which caused it to crash; so I would be very interested to see your logs.


#11

Hi @richbayliss,

Sorry for the delay. I was waiting for the issue to happens again.

Below you will see the logs when I intent to login into my backend instance of openbalena and I get 503 error :

Logging in to mydomain.com
BalenaRequestError: Request error:

503 Service Unavailable


No server is available to handle this request.

If you need help, don’t hesitate in contacting us at:

** GitHub: https://github.com/balena-io/balena-cli/issues/new**
** Forums: https://forums.balena.io**

– Logs begin at Tue 2019-02-12 20:48:27 UTC. –
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at runPut (/usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1357:23)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at /usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1145:18
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at runRequest (/usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1136:51)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at /usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1043:22
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Promise.try (/usr/src/app/node_modules/@resin/pinejs/out/database-layer/db.js:182:55)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at promise.tap (/usr/src/app/node_modules/@resin/pinejs/out/database-layer/db.js:182:48)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Promise (/usr/src/app/node_modules/@resin/pinejs/out/database-layer/db.js:182:25)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Object.transaction (/usr/src/app/node_modules/@resin/pinejs/out/database-layer/db.js:174:16)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at runTransaction (/usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1233:17)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at /usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1032:18
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at /usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1030:13
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Promise.each (/usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/control-flow.js:32:16)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at mapTill (/usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/control-flow.js:31:20)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at /usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1015:14
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at handleODataRequest (/usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:1003:8)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at /usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:912:14
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at runURI (/usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:861:12)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at PinejsClient._request (/usr/src/app/node_modules/@resin/pinejs/out/sbvr-api/sbvr-utils.js:814:14)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at PinejsClientCoreFactory.PinejsClientCore.request (/usr/src/app/node_modules/pinejs-client-core/core.js:841:29)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at PinejsClientCoreFactory.PinejsClientCore.patch (/usr/src/app/node_modules/pinejs-client-core/core.js:777:25)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at auth_1.comparePassword.then.res (/usr/src/app/src/routes/session.ts:32:40)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at auth_1.findUser.then.user (/usr/src/app/src/routes/session.ts:28:14)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at runCallback (timers.js:705:18)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at tryOnImmediate (timers.js:676:5)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at processImmediate (timers.js:658:5)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at process.topLevelDomainCallback (domain.js:121:23)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: From previous event:
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at exports.login (/usr/src/app/src/routes/session.ts:23:10)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Layer.handle [as handle_request] (/usr/src/app/node_modules/express/lib/router/layer.js:95:5)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at next (/usr/src/app/node_modules/express/lib/router/route.js:137:13)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at module.exports. (/usr/src/app/node_modules/express-brute/index.js:142:36)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Multi.callback (/usr/src/app/node_modules/express-brute-redis/index.js:35:45)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at multi_callback (/usr/src/app/node_modules/redis/lib/multi.js:89:14)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Command.callback (/usr/src/app/node_modules/redis/lib/multi.js:116:9)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at normal_reply (/usr/src/app/node_modules/redis/index.js:726:21)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at RedisClient.return_reply (/usr/src/app/node_modules/redis/index.js:824:9)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at JavascriptRedisParser.returnReply (/usr/src/app/node_modules/redis/index.js:192:18)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at JavascriptRedisParser.execute (/usr/src/app/node_modules/redis-parser/lib/parser.js:574:12)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Socket. (/usr/src/app/node_modules/redis/index.js:274:27)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Socket.emit (events.js:182:13)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Socket.EventEmitter.emit (domain.js:442:20)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at addChunk (_stream_readable.js:283:12)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at readableAddChunk (_stream_readable.js:264:11)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at Socket.Readable.push (_stream_readable.js:219:10)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17) message: ‘Connection terminated’, name: ‘DatabaseError’ }
Feb 12 21:17:58 7c19ee2bf1aa api[906]: resin: Running GET /resin/user(2)
Feb 12 21:17:58 7c19ee2bf1aa api[906]: Auth: Running GET /Auth/permission?$select=name&$filter=(is_of__user/any(uhp:(uhp/user eq 2) and ((uhp/expiry_date eq null) or (uhp/expiry_date gt now())))) or (is_of__role/any(rhp:rhp/role/any(r:r/is_of__user/any(uhr:(uhr/user eq 2) and ((uhr/expiry_date eq null) or (uhr/expiry_date gt now()))))))&$orderby=name asc
Feb 12 21:17:58 7c19ee2bf1aa api[906]: resin: SELECT “user”.“created at” AS “created_at”, “user”.“id”, “user”.“actor”, “user”.“username”, “user”.“password”, “user”.“jwt secret” AS “jwt_secret”, “user”.“email”
Feb 12 21:17:58 7c19ee2bf1aa api[906]: FROM “user”
Feb 12 21:17:58 7c19ee2bf1aa api[906]: WHERE “user”.“id” = $1 [ 2 ]
Feb 12 21:18:00 7c19ee2bf1aa api[906]: Auth: SELECT “permission”.“name”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: FROM “permission”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: WHERE (EXISTS (
Feb 12 21:18:00 7c19ee2bf1aa api[906]: SELECT 1
Feb 12 21:18:00 7c19ee2bf1aa api[906]: FROM “user-has-permission” AS “permission.user-has-permission”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: WHERE “permission”.“id” = “permission.user-has-permission”.“permission”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: AND “permission.user-has-permission”.“user” = $1
Feb 12 21:18:00 7c19ee2bf1aa api[906]: AND (“permission.user-has-permission”.“expiry date” IS NULL
Feb 12 21:18:00 7c19ee2bf1aa api[906]: OR “permission.user-has-permission”.“expiry date” > CURRENT_TIMESTAMP)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: )
Feb 12 21:18:00 7c19ee2bf1aa api[906]: OR EXISTS (
Feb 12 21:18:00 7c19ee2bf1aa api[906]: SELECT 1
Feb 12 21:18:00 7c19ee2bf1aa api[906]: FROM “role-has-permission” AS “permission.role-has-permission”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: WHERE “permission”.“id” = “permission.role-has-permission”.“permission”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: AND EXISTS (
Feb 12 21:18:00 7c19ee2bf1aa api[906]: SELECT 1
Feb 12 21:18:00 7c19ee2bf1aa api[906]: FROM “role” AS “permission.role-has-permission.role”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: WHERE “permission.role-has-permission”.“role” = “permission.role-has-permission.role”.“id”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: AND EXISTS (
Feb 12 21:18:00 7c19ee2bf1aa api[906]: SELECT 1
Feb 12 21:18:00 7c19ee2bf1aa api[906]: FROM “user-has-role” AS “permission.role-has-permission.role.user-has-role”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: WHERE “permission.role-has-permission.role”.“id” = “permission.role-has-permission.role.user-has-role”.“role”
Feb 12 21:18:00 7c19ee2bf1aa api[906]: AND “permission.role-has-permission.role.user-has-role”.“user” = $2
Feb 12 21:18:00 7c19ee2bf1aa api[906]: AND (“permission.role-has-permission.role.user-has-role”.“expiry date” IS NULL
Feb 12 21:18:00 7c19ee2bf1aa api[906]: OR “permission.role-has-permission.role.user-has-role”.“expiry date” > CURRENT_TIMESTAMP)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: )
Feb 12 21:18:00 7c19ee2bf1aa api[906]: )
Feb 12 21:18:00 7c19ee2bf1aa api[906]: ))
Feb 12 21:18:00 7c19ee2bf1aa api[906]: ORDER BY “permission”.“name” ASC [ 2, 2 ]
Feb 12 21:18:00 7c19ee2bf1aa api[906]: Error: Connection terminated unexpectedly
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at Client. (/usr/src/app/node_modules/pg/lib/client.js:226:28)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at Object.onceWrapper (events.js:273:13)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at Connection.emit (events.js:182:13)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at Connection.EventEmitter.emit (domain.js:442:20)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at Socket. (/usr/src/app/node_modules/pg/lib/connection.js:138:10)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at Socket.emit (events.js:187:15)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at Socket.EventEmitter.emit (domain.js:442:20)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at endReadableNT (_stream_readable.js:1094:12)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: at process._tickCallback (internal/process/next_tick.js:63:19)
Feb 12 21:18:00 7c19ee2bf1aa api[906]: Program node index.js exited with code 1


#12

OK so the API died because it lost connection with the Redis & DB services (looking at the errors in the logs) which I have seen in the past if the HAproxy container restarts. The services talk to each other through this service, so that could be the cause.

I will take a look at what you could do to have it restart in the event of an error like this :ok_hand:


#13

@rlev so if you set the environment variable PRODUCTION_MODE: "true" in the docker-compose.yml for the stack, then you will loose some verbosity on the logs, but you should find that in the event of the API crashing it will be restarted by systemd.


#14

@richbayliss

In the file /open-balena/config/docker-compose.yml
I find only :

 # Project-specific config.
 #
 # All paths must be defined relative to `compose/services.yml` regardless of
 # the location of this file, i.e. refer to `my-open-balena-checkout/somedir`
 # as `../somedir`. This is because of the way docker-compose handles paths
 # when specifying multiple configs and open-balena always specifying
 # `compose/services.yml` as the "base" config.
 #
 # You may view the effective config with `scripts/compose config`.
 version: '2.1'

But in the /open-balena/compose/services.yml

I see :

services:
  api:
    extends:
      file: ./common.yml
      service: component
    image: balena/open-balena-api:${OPENBALENA_API_VERSION_TAG:-master}
    depends_on:
      - db
      - s3
      - redis
    environment:
      API_VPN_SERVICE_API_KEY: ${OPENBALENA_API_VPN_SERVICE_API_KEY}
      BALENA_ROOT_CA: ${OPENBALENA_ROOT_CA}
      COOKIE_SESSION_SECRET: ${OPENBALENA_COOKIE_SESSION_SECRET}
      DB_HOST: db.${OPENBALENA_HOST_NAME}
      DB_PASSWORD: docker
      DB_PORT: 5432
      DB_USER: docker
      .....
      .....
      MIXPANEL_TOKEN: __unused__

PRODUCTION_MODE: '{OPENBALENA_PRODUCTION_MODE}' PUBNUB_PUBLISH_KEY: __unused__ PUBNUB_SUBSCRIBE_KEY: __unused__ REDIS_HOST: redis.{OPENBALENA_HOST_NAME}

vpn:
    extends:
      file: ./common.yml
      service: component
    image: balena/open-balena-vpn:${OPENBALENA_VPN_VERSION_TAG:-master}
    depends_on:
      - api
    cap_add:
      - NET_ADMIN
    environment:
      API_SERVICE_API_KEY: ${OPENBALENA_API_VPN_SERVICE_API_KEY}
      BALENA_API_HOST: api.${OPENBALENA_HOST_NAME}
      BALENA_ROOT_CA: ${OPENBALENA_ROOT_CA}
      BALENA_VPN_PORT: 443

PRODUCTION_MODE: '{OPENBALENA_PRODUCTION_MODE}' RESIN_VPN_GATEWAY: 10.2.0.1 SENTRY_DSN: VPN_HAPROXY_USEPROXYPROTOCOL: 'true' VPN_OPENVPN_CA_CRT: {OPENBALENA_VPN_CA}
VPN_OPENVPN_SERVER_CRT: {OPENBALENA_VPN_SERVER_CRT} VPN_OPENVPN_SERVER_DH: {OPENBALENA_VPN_SERVER_DH}
VPN_OPENVPN_SERVER_KEY: {OPENBALENA_VPN_SERVER_KEY} VPN_SERVICE_API_KEY: {OPENBALENA_VPN_SERVICE_API_KEY}

Is this the file you are refering to?


#15

Yes, sorry, just replace the ${OPENBALENA_PRODUCTION_MODE} for the API service and it should do the trick once you update the running services :ok_hand:


#16

Will do.

Thanks @richbayliss