Balena OS supervisor takes too much time to start

Product support balenaOS
1

Recently I have seen behavior where balena supervisor takes too much time to start

CONTAINER ID        IMAGE                               COMMAND             CREATED             STATUS                            PORTS               NAMES
629f936427ff        balena/armv7hf-supervisor:v9.15.0   "./entry.sh"        2 hours ago         Up 10 minutes (health: starting)                       resin_supervisor
r

Due to this when pushing the code locally I get this error

➜ balena push <ip-addr>
Could not communicate with local mode device at address 192.168.1.170

Additional information may be available by setting a DEBUG=1 environment
variable: "set DEBUG=1" on a Windows command prompt, or "export DEBUG=1"
on Linux or macOS.

If you need help, don't hesitate in contacting our support forums at
https://forums.balena.io

For bug reports or feature requests, have a look at the GitHub issues or
create a new one at: https://github.com/balena-io/balena-cli/issues/

After 15 mins supervisor starts and I get the following response for balena ps -a

CONTAINER ID        IMAGE                               COMMAND             CREATED             STATUS                      PORTS               NAMES
629f936427ff        balena/armv7hf-supervisor:v9.15.0   "./entry.sh"        2 hours ago         Up 15 minutes (unhealthy)                       resin_supervisor

This issue has occurred 3 - 4 times today whenever I reboot the device.

2

Hey @Sharvin26 can you post your supervisor logs, so we can see if anything untoward is happening?

To get the logs, type journalctl -f -u resin-supervisor into a host OS shell.

3

Now it’s showing Healthy next time when it show’s unhealthy I’ll add the log here

But it became healthy after 9 mins after rebooting the device =>

CONTAINER ID        IMAGE                               COMMAND             CREATED             STATUS                   PORTS               NAMES
629f936427ff        balena/armv7hf-supervisor:v9.15.0   "./entry.sh"        2 hours ago         Up 9 minutes (healthy)                       resin_supervisor
r

Right now this is the output of the journalctl -f -u resin-supervisor >

Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at IncomingMessage.emit (events.js:194:15)
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at endReadableNT (_stream_readable.js:1125:12)
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at process._tickCallback (internal/process/next_tick.js:63:19)
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:   reason: 'no such container',
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:   statusCode: 404,
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:   json:
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:    { message: 'No such image: local_image_test-subordinate:latest' } }
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]: Apply error Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 13:59:12 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v1/healthy 200 - 17.476 ms
Jun 20 14:00:32 a2ae423 resin-supervisor[4966]: Failed to get target state for device: Error: ETIMEDOUT

**Note: ** I have deleted local_image_test this image and container also.

4

If you add -n 100 to the call, we should be able to see what’s going on for more of the runtime.

5

Deleting images from the device would certainly cause the above error.

6 
-- Logs begin at Thu 2019-06-20 13:52:10 UTC. --
Jun 20 13:54:50 a2ae423 resin-supervisor[4966]:   json:
Jun 20 13:54:50 a2ae423 resin-supervisor[4966]:    { message: 'No such image: local_image_test:latest' } }
Jun 20 13:54:50 a2ae423 resin-supervisor[4966]: Apply error Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]: Applying target state
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]: Event: Service install {"service":{"appId":1,"serviceId":1,"serviceName":"test","releaseId":1}}
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]: Scheduling another update attempt due to failure:  64000 { Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:     at /usr/src/app/dist/app.js:576:112833
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:     at /usr/src/app/dist/app.js:576:112796
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:     at m.buildPayload (/usr/src/app/dist/app.js:576:112806)
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:     at IncomingMessage.<anonymous> (/usr/src/app/dist/app.js:576:112306)
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:     at IncomingMessage.emit (events.js:194:15)
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:     at endReadableNT (_stream_readable.js:1125:12)
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:     at process._tickCallback (internal/process/next_tick.js:63:19)
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:   reason: 'no such container',
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:   statusCode: 404,
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:   json:
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]:    { message: 'No such image: local_image_test:latest' } }
Jun 20 13:55:22 a2ae423 resin-supervisor[4966]: Apply error Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 13:55:32 a2ae423 resin-supervisor[4966]: Failed to get target state for device: Error: ETIMEDOUT
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]: Applying target state
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]: Event: Service install {"service":{"appId":1,"serviceId":1,"serviceName":"test","releaseId":1}}
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]: Scheduling another update attempt due to failure:  128000 { Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:     at /usr/src/app/dist/app.js:576:112833
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:     at /usr/src/app/dist/app.js:576:112796
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:     at m.buildPayload (/usr/src/app/dist/app.js:576:112806)
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:     at IncomingMessage.<anonymous> (/usr/src/app/dist/app.js:576:112306)
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:     at IncomingMessage.emit (events.js:194:15)
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:     at endReadableNT (_stream_readable.js:1125:12)
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:     at process._tickCallback (internal/process/next_tick.js:63:19)
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:   reason: 'no such container',
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:   statusCode: 404,
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:   json:
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]:    { message: 'No such image: local_image_test:latest' } }
Jun 20 13:56:26 a2ae423 resin-supervisor[4966]: Apply error Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 13:56:32 a2ae423 resin-supervisor[4966]: Failed to get target state for device: Error: ETIMEDOUT
Jun 20 13:58:02 a2ae423 resin-supervisor[4966]: Failed to get target state for device: Error: ETIMEDOUT
Jun 20 13:58:34 a2ae423 resin-supervisor[4966]: Applying target state
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]: Event: Service install {"service":{"appId":1,"serviceId":1,"serviceName":"test","releaseId":1}}
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]: Scheduling another update attempt due to failure:  256000 { Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at /usr/src/app/dist/app.js:576:112833
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at /usr/src/app/dist/app.js:576:112796
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at m.buildPayload (/usr/src/app/dist/app.js:576:112806)
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at IncomingMessage.<anonymous> (/usr/src/app/dist/app.js:576:112306)
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at IncomingMessage.emit (events.js:194:15)
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at endReadableNT (_stream_readable.js:1125:12)
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:     at process._tickCallback (internal/process/next_tick.js:63:19)
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:   reason: 'no such container',
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:   statusCode: 404,
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:   json:
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]:    { message: 'No such image: local_image_test:latest' } }
Jun 20 13:58:35 a2ae423 resin-supervisor[4966]: Apply error Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 13:59:12 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v1/healthy 200 - 17.476 ms
Jun 20 14:00:32 a2ae423 resin-supervisor[4966]: Failed to get target state for device: Error: ETIMEDOUT
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]: Applying target state
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]: Event: Service install {"service":{"appId":1,"serviceId":1,"serviceName":"test","releaseId":1}}
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]: Scheduling another update attempt due to failure:  512000 { Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:     at /usr/src/app/dist/app.js:576:112833
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:     at /usr/src/app/dist/app.js:576:112796
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:     at m.buildPayload (/usr/src/app/dist/app.js:576:112806)
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:     at IncomingMessage.<anonymous> (/usr/src/app/dist/app.js:576:112306)
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:     at IncomingMessage.emit (events.js:194:15)
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:     at endReadableNT (_stream_readable.js:1125:12)
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:     at process._tickCallback (internal/process/next_tick.js:63:19)
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:   reason: 'no such container',
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:   statusCode: 404,
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:   json:
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]:    { message: 'No such image: local_image_test:latest' } }
Jun 20 14:02:51 a2ae423 resin-supervisor[4966]: Apply error Error: (HTTP code 404) no such container - No such image: local_image_test:latest
Jun 20 14:04:13 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v1/healthy 200 - 7.011 ms
Jun 20 14:04:58 a2ae423 resin-supervisor[4966]: Supervisor API: GET /ping 200 - 15.786 ms
Jun 20 14:04:58 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/version 200 - 18.711 ms
Jun 20 14:04:59 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/local/device-info 200 - 22.379 ms
Jun 20 14:05:02 a2ae423 resin-supervisor[4966]: Failed to get target state for device: Error: ETIMEDOUT
Jun 20 14:05:51 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/local/target-state 200 - 62.193 ms
Jun 20 14:05:51 a2ae423 resin-supervisor[4966]: Supervisor API: POST /v2/local/target-state 200 - 83.294 ms
Jun 20 14:05:51 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/local/device-info 200 - 21.474 ms
Jun 20 14:05:51 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 207.461 ms
Jun 20 14:05:53 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 213.835 ms
Jun 20 14:05:54 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 220.021 ms
Jun 20 14:05:55 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 216.149 ms
Jun 20 14:05:56 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 201.403 ms
Jun 20 14:05:58 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 237.014 ms
Jun 20 14:05:59 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 205.903 ms
Jun 20 14:06:00 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 218.950 ms
Jun 20 14:06:01 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 220.588 ms
Jun 20 14:06:03 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 214.128 ms
Jun 20 14:06:04 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 205.764 ms
Jun 20 14:06:05 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 211.576 ms
Jun 20 14:06:06 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 237.123 ms
Jun 20 14:06:08 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 214.349 ms
Jun 20 14:06:09 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 231.875 ms
Jun 20 14:06:10 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 239.621 ms
Jun 20 14:06:12 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 208.640 ms
Jun 20 14:06:13 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 217.096 ms
Jun 20 14:06:14 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 228.753 ms
Jun 20 14:06:16 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 218.425 ms
Jun 20 14:06:17 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 208.279 ms
Jun 20 14:06:18 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 219.312 ms
Jun 20 14:06:19 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 228.473 ms
Jun 20 14:06:20 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 204.969 ms
Jun 20 14:06:22 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 203.996 ms
Jun 20 14:06:23 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 232.748 ms
Jun 20 14:06:24 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 200.493 ms
Jun 20 14:06:25 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 201.047 ms
Jun 20 14:06:27 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 224.044 ms
Jun 20 14:06:28 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 199.486 ms
Jun 20 14:06:29 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 211.416 ms
Jun 20 14:06:30 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 224.366 ms
Jun 20 14:06:32 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 226.516 ms
Jun 20 14:06:33 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 216.468 ms
Jun 20 14:06:34 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 206.157 ms
Jun 20 14:06:35 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 230.420 ms
Jun 20 14:06:37 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 207.109 ms
Jun 20 14:06:38 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 207.481 ms
Jun 20 14:06:39 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 236.625 ms
Jun 20 14:06:40 a2ae423 resin-supervisor[4966]: Supervisor API: GET /v2/state/status 200 - 207.614 ms
7

Yes But I have been deleting the image frequently in past few days I didn’t get this error earlier I have seen this behaviour today.

Even the logs are not streaming back to my local machine

[Live]    Watching for file changes...
[Live]    Waiting for device state to settle...
[Info]    Streaming device logs...
[Live]    Watching for file changes...



[Logs]    [6/20/2019, 7:41:25 PM] Installing service 'test sha256:bb0c6c036c166c0ce470bcff96a67b75ab9a169ad283eb17a93b819801d9bb8a'
[Logs]    [6/20/2019, 7:41:26 PM] Installed service 'test sha256:bb0c6c036c166c0ce470bcff96a67b75ab9a169ad283eb17a93b819801d9bb8a'
[Logs]    [6/20/2019, 7:41:26 PM] Starting service 'test sha256:bb0c6c036c166c0ce470bcff96a67b75ab9a169ad283eb17a93b819801d9bb8a'
[Logs]    [6/20/2019, 7:41:27 PM] Started service 'test sha256:bb0c6c036c166c0ce470bcff96a67b75ab9a169ad283eb17a93b819801d9bb8a'

But if I check the logs using balena logs -f <container-id> I am able to see them.

8

The logs you posted here show a supervisor that is working correctly. It seems strange that it took so long to start up, Perhaps this had something to do with the errors that were being reported.

As for the logs not being shown from a balena push, that’s very strange. Can you run the same command with DEBUG=1 prepended on the command line please? e.g

DEBUG=1 balena push <my-device>
9

I’ll post the log when the same situation occurs next time