balena push / logs (local mode): multi-line prints are not shown

edorgeville · February 5, 2021, 2:32pm

Hi,
I’ve been chasing this bug for quite a while now and finally found the culprit.
It seems that, when using local mode, any multi-line prints to the console will not be sent back using either balena push or balena logs.
I put together the simplest demo I could think of in this repository: GitHub - edorgeville/balena-console-logs: balena push / logs (local mode): multi-line prints are not shown

To reproduce, set a device to local mode and balena push to it. Changing the value of the linesPerLoop variable on line #2 to 2 or more will stop any logs from getting reported back. For comparison, run node index.js or nodemon to run the app locally.
Here is a recording of the results (click on the image to go to the source, the forum system bot seems to replace the GIF with a JPG automatically):

Additional information:

balena-cli version: 12.38.7
Device type: rapsberry pi 4
balenaOS version: raspberrypi4-64-2.65.0+rev1-dev-v12.2.11

Thanks in advance for your help.
Erwan

edorgeville · February 10, 2021, 1:40pm

Bumping my own thread, can anyone on the balena team help me on this? Thanks!

sradevski · February 11, 2021, 10:30am

Hey Erwan, I’ll open an issue on your behalf and the CLI team will have a look when they have the chance. Thanks for reporting this, and apologies for not getting back to you sooner.

edorgeville · February 17, 2021, 2:05pm

Hi @sradevski, any news?

notnamed · February 17, 2021, 10:27pm

Hey, thanks for all your work with creating a replication for this issue! We have issue When using local mode, any multi-line prints to the console will not be sent back using either balena push or balena logs. · Issue #2185 · balena-io/balena-cli · GitHub opened against this, but we’re still working on a fix. We’ve got your thread and this issue linked, so once we have an update, someone will come back and let you know.

edorgeville · April 7, 2021, 12:48pm

Hey @notnamed , any updates on this?

pipex · April 7, 2021, 10:34pm

Hi @edorgeville,

Thanks again for your replication!

I spent some time testing your code on one of my devices, but the same conditions (same device, os, cli and supervisor versions) but could not get the same results you did.

Is there anything else you can tell us about your setup? Are you using windows/linux/mac? What versions of the OS and of node? If using windows, how did you install? Are you using WSL?

Have you tried the same with another os or supervisor versions?

Thank you. Any further information you can provide may help us get to a resolution of this ticket.

edorgeville · April 8, 2021, 3:56pm

Hi @pipex,

OS: Windows 10 20H2 (build 19042.867)
The balena CLI was installed using the Windows installer from those instructions
Node: v15.8.0

The shell I am using is Git bash. I tried running the same command in cmd, same bug happens.
I updated the CLI to 12.44.6, issue still happens. Adding the --debug flag gives a bit more info about what is happening. The logs are received, but a parsing error occurs.

$ balena push <redacted>.local --debug
[debug] new argv=[C:\Program Files\balena-cli\client\bin\node.exe,C:\Program Files\balena-cli\client\bin\run,push,b1409e4.local] length=4
[Debug]   Using build source directory: . 
[Debug]   Pushing to local device: <redacted>.local
[Debug]   Checking we can access device
[Debug]   Sending request to http://<redacted>:48484/ping
[Debug]   Checking device supervisor version: 12.3.5
[Info]    Starting build on device <redacted>
[Debug]   Loading project...
[Debug]   Resolving project...
[Info]    No "docker-compose.yml" file found at "."
[Info]    Creating default composition with source: "."
[Debug]   Creating project...
[Debug]   Tarring all non-ignored files...
[Debug]   Sending request to http://<redacted>:48484/v2/local/device-info
[Debug]   Found build tasks:
[Debug]       main: build [.]
[Debug]   Resolving services with [raspberrypi4-64|aarch64]
[Debug]   Found project types:
[Debug]       main: Dockerfile.template
[Debug]   Probing remote daemon for cache images
[Debug]   Using 25 on-device images for cache...
[Debug]   Starting builds...
[Build]   [main] Step 1/6 : FROM balenalib/raspberrypi4-64-node:12-run
[Build]   [main]  ---> 284c124f41f8
[Build]   [main] Step 2/6 : WORKDIR /usr/src/app
[Build]   [main]  ---> Using cache
[Build]   [main]  ---> f2a0078917f4
[Build]   [main] Step 3/6 : COPY index.js .
[Build]   [main]  ---> Using cache
[Build]   [main]  ---> 197678dad1b4
[Build]   [main] Step 4/6 : CMD node index.js
[Build]   [main]  ---> Using cache
[Build]   [main]  ---> 37041df8de8c
[Build]   [main] Step 5/6 : LABEL io.resin.local.image=1
[Build]   [main]  ---> Using cache
[Build]   [main]  ---> dcd3ba124f1e
[Build]   [main] Step 6/6 : LABEL io.resin.local.service=main
[Build]   [main]  ---> Using cache
[Build]   [main]  ---> 2132a2fe7269
[Build]   [main] Successfully built 2132a2fe7269
[Build]   [main] Successfully tagged local_image_main:latest

[Debug]   Setting device state...
[Debug]   Sending request to http://<redacted>:48484/v2/local/target-state
[Debug]   Sending target state: {"local":{"name":"<redacted>","config":{"HOST_CONFIG_disable_overscan":"1","HOST_CONFIG_gpu_mem":"128","HOST_CONFIG_hdmi_cvt":"1920 1080 60 1 0 0 0","HOST_CONFIG_hdmi_force_hotplug":"1","HOST_CONFIG_hdmi_group":"2","HOST_CONFIG_hdmi_mode":"87","HOST_CONFIG_dtoverlay":"\"vc4-fkms-v3d\"","HOST_CONFIG_dtparam":"\"i2c_arm=on\",\"spi=on\",\"audio=on\"","SUPERVISOR_DELTA_VERSION":"3","HOST_CONFIG_disable_splash":"1","HOST_CONFIG_enable_uart":"1","SUPERVISOR_DELTA":"1","SUPERVISOR_LOCAL_MODE":"1","SUPERVISOR_POLL_INTERVAL":"900000","SUPERVISOR_VPN_CONTROL":"true","SUPERVISOR_INSTANT_UPDATE_TRIGGER":"true","SUPERVISOR_CONNECTIVITY_CHECK":"true","SUPERVISOR_LOG_CONTROL":"true","SUPERVISOR_DELTA_REQUEST_TIMEOUT":"30000","SUPERVISOR_DELTA_APPLY_TIMEOUT":"0","SUPERVISOR_DELTA_RETRY_COUNT":"30","SUPERVISOR_DELTA_RETRY_INTERVAL":"10000","SUPERVISOR_OVERRIDE_LOCK":"false","SUPERVISOR_PERSISTENT_LOGGING":"false","HOST_FIREWALL_MODE":"off","HOST_DISCOVERABILITY":"true"},"apps":{"1":{"name":"localapp","commit":"localrelease","releaseId":"1","services":{"1":{"environment":{},"labels":{"io.resin.features.kernel-modules":"1","io.resin.features.firmware":"1","io.resin.features.dbus":"1","io.resin.features.supervisor-api":"1","io.resin.features.resin-api":"1"},"privileged":true,"tty":true,"restart":"always","network_mode":"host","volumes":["resin-data:/data"],"imageId":1,"serviceName":"main","serviceId":1,"image":"local_image_main:latest","running":true}},"volumes":{"resin-data":{}},"networks":{}}}},"dependent":{"apps":[],"devices":[]}}
[Debug]   Sending request to http://<redacted>:48484/v2/local/target-state
[Info]    Streaming device logs...
[Debug]   Sending request to http://<redacted>:48484/v2/local/device-info
[Live]    Watching for file changes...
[Live]    Waiting for device state to settle...
[Debug]   Device state not settled, retrying in 1000ms
[Debug]   Dropping device log due to failed parsing: SyntaxError: Unexpected token { in JSON at position 184
[Debug]   Dropping device log due to failed parsing: SyntaxError: Unexpected token { in JSON at position 184
[Live]    Device state settled
[Debug]   Dropping device log due to failed parsing: SyntaxError: Unexpected token { in JSON at position 184
[Debug]   Dropping device log due to failed parsing: SyntaxError: Unexpected token { in JSON at position 184
[Debug]   Dropping device log due to failed parsing: SyntaxError: Unexpected token { in JSON at position 184
[Debug]   Dropping device log due to failed parsing: SyntaxError: Unexpected token { in JSON at position 184

edorgeville · April 8, 2021, 5:58pm

I investiguated some more.
I don’t know the implementation of the logs parsing in the CLI, but I would guess it uses the supervisor API logs endpoint (http://uuid.local:48484/v2/local/logs), then JSON.parse() any new chunk of data that comes through. I made the following proof-of-concept to illustrate the issue:

# parseLogs.js
var http = require('http');
var body = '';

http.get('http://uuid.local:48484/v2/local/logs', (res) => {
  res.on('data', (chunk) => {
    try {
      JSON.parse(chunk)
    } catch (error) {
      console.error(String(chunk), error)
    }
    
  })
  res.on('end', () => {
    console.log('Done')
  })
})

Run node parseLogs.js, then increase the value of linesPerLoop (e.g. 100) on the device until it makes parseLog output errors:

$ node stream.js 
{"serviceName":"main","serviceId":1,"imageId":1,"message":"Counter \u001b[33m275\u001b[39m :  SyntaxError: Unexpected end of JSON input
    at JSON.parse (<anonymous>)
    at IncomingMessage.<anonymous> (<redacted>\stream.js:7:12)
    at IncomingMessage.emit (node:events:378:20)
    at addChunk (node:internal/streams/readable:313:12)
    at readableAddChunk (node:internal/streams/readable:288:9)
    at IncomingMessage.Readable.push (node:internal/streams/readable:227:10)
    at HTTPParser.parserOnBody (node:_http_common:142:24)
    at Socket.socketOnData (node:_http_client:502:22)
    at Socket.emit (node:events:378:20)
    at addChunk (node:internal/streams/readable:313:12)
\u001b[33m25\u001b[39m / \u001b[33m100\u001b[39m\r","isStdErr":false,"timestamp":1617904499312}
 SyntaxError: Unexpected token \ in JSON at position 0
    at JSON.parse (<anonymous>)
    at IncomingMessage.<anonymous> (<redacted>\stream.js:7:12)
    at IncomingMessage.emit (node:events:378:20)
    at addChunk (node:internal/streams/readable:313:12)
    at readableAddChunk (node:internal/streams/readable:288:9)
    at IncomingMessage.Readable.push (node:internal/streams/readable:227:10)
    at HTTPParser.parserOnBody (node:_http_common:142:24)
    at Socket.socketOnData (node:_http_client:502:22)
    at Socket.emit (node:events:378:20)
    at addChunk (node:internal/streams/readable:313:12)
{"serviceName":"main","serviceId":1,"imageId":1,"message":"Counter \u001b[33m275\u001b[39m : \u001b[33m74\u001b[39m / \u001b[33m100\u001b[39m\r","isStdErr":false,"timestamp":16 SyntaxError: Unexpected end of JSON input
    at JSON.parse (<anonymous>)
    at IncomingMessage.<anonymous> (<redacted>\stream.js:7:12)
    at IncomingMessage.emit (node:events:378:20)
    at addChunk (node:internal/streams/readable:313:12)
    at readableAddChunk (node:internal/streams/readable:288:9)
    at IncomingMessage.Readable.push (node:internal/streams/readable:227:10)
    at HTTPParser.parserOnBody (node:_http_common:142:24)
    at Socket.socketOnData (node:_http_client:502:22)
    at Socket.emit (node:events:378:20)
    at addChunk (node:internal/streams/readable:313:12)
17904499320}
 SyntaxError: Unexpected token } in JSON at position 11
    at JSON.parse (<anonymous>)
    at IncomingMessage.<anonymous> (<redacted>\stream.js:7:12)
    at IncomingMessage.emit (node:events:378:20)
    at addChunk (node:internal/streams/readable:313:12)
    at readableAddChunk (node:internal/streams/readable:288:9)
    at IncomingMessage.Readable.push (node:internal/streams/readable:227:10)
    at HTTPParser.parserOnBody (node:_http_common:142:24)
    at Socket.socketOnData (node:_http_client:502:22)
    at Socket.emit (node:events:378:20)
    at addChunk (node:internal/streams/readable:313:12)

Taking a quick look at those logs, it seems to me that the more logs there is, the higher the chances are that JSON objects will arrive chunked in random places.

phil-d-wilson · April 9, 2021, 7:53am

Hi there Erwan,

Thank you for continuing to try and debug this. I’ve pinged the CLI team to have a read of your PoC and the results, as it may help with the issue linked above.

Phil

pdcastro · April 9, 2021, 11:42pm

Erwan, thanks again for investigating this issue. It should be fixed in balena CLI v12.44.8 or later – let us know if it now works for you. The CLI was doing more or less the same as the client example that you kindly shared:

http.get('http://uuid.local:48484/v2/local/logs', (res) => {
  res.on('data', (chunk) => {
      JSON.parse(chunk)

However, that supervisor endpoint provides a stream of NDJSON objects over HTTP. As such, in the code above, chunk is a Buffer or “raw string” that may contain multiple NDJSON objects, or even an incomplete object that needs to be concatenated with subsequent chunks (or parts of subsequent chunks) before JSON.parse() can be called on each individual object. A relatively easy way to achieve this in Javascript is to pipe the stream to the ndjson transform stream, as done in PR 2248 for the balena CLI.

edorgeville · April 14, 2021, 12:43pm

Thank you! I can confirm that the logs are not being dropped anymore. Thank you for taking the time to fix this and sharing the details with me.

Topic		Replies	Views
Can't see logs in `balena logs` unless not using `.local` balenaOS support , raspberrypi3 , balena-cli	6	937	September 2, 2020
No logging output in local mode Product support	19	1362	March 10, 2020
How to log from client.js balenaOS local-mode , raspberrypizero	1	484	October 20, 2020
streaming logs to linux problem General	4	397	November 2, 2021
How to get logs in local mode balenaOS raspberrypi3 , local-mode	2	604	October 7, 2019

balena push / logs (local mode): multi-line prints are not shown

Related topics