gRPC `Upload` response stream truncated

[per1234]

Describe the problem

The cc.arduino.cli.commands.v1.ArduinoCoreService.Upload method of Arduino CLI's gRPC interface has a streaming response that contains the output from the upload process.

🐛 Under some conditions, this stream is truncated, resulting in information essential for troubleshooting upload failures not being available to the user.

To reproduce

Set up

$ arduino-cli version
arduino-cli.exe  Version: git-snapshot Commit: 5332ffda Date: 2022-07-31T06:55:13Z

$ arduino-cli sketch new /tmp/FooSketch
Sketch created in: C:\Users\per\AppData\Local\Temp\FooSketch

$ arduino-cli compile --fqbn arduino:avr:uno /tmp/FooSketch
Sketch uses 444 bytes (1%) of program storage space. Maximum is 32256 bytes.
Global variables use 9 bytes (0%) of dynamic memory, leaving 2039 bytes for local variables. Maximum is 2048 bytes.


Used platform Version Path
arduino:avr   1.8.5   C:\Users\per\AppData\Local\Arduino15\packages\arduino\hardware\avr\1.8.5

$ arduino-cli board list
Port   Protocol Type              Board Name                FQBN             Core       
COM1   serial   Serial Port       Unknown
COM15  serial   Serial Port (USB) Arduino Uno               arduino:avr:uno  arduino:avr

$ arduino-cli monitor --port COM15  # Produce conditions that will cause upload to fail
Connected to COM15! Press CTRL-C to exit.

Run the following command in another terminal:

$ arduino-cli daemon --debug

Demo

Check the command line output

Run the following command in another terminal:

$ arduino-cli upload --fqbn arduino:avr:uno --port COM15 /tmp/FooSketch
avrdude: ser_open(): can't open device "\\.\COM15": Access is denied.

Error during Upload: Failed uploading: uploading error: exit status 1

🙂 The non-verbose command line output is exactly as expected.

$ arduino-cli upload --fqbn arduino:avr:uno --port COM15 --verbose /tmp/FooSketch
"C:\Users\per\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/bin/avrdude" "-CC:\Users\per\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/etc/avrdude.conf" -v -V -patmega328p -carduino "-PCOM15" -b115200 -D "-Uflash:w:C:\Users\per\AppData\Local\Temp\arduino-sketch-2405C4C9F90028537C79B0744BCE536E/FooSketch.ino.hex:i"

avrdude: Version 6.3-20190619
         Copyright (c) 2000-2005 Brian Dean, http://www.bdmicro.com/
         Copyright (c) 2007-2014 Joerg Wunsch

         System wide configuration file is "C:\Users\per\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/etc/avrdude.conf"

         Using Port                    : COM15
         Using Programmer              : arduino
         Overriding Baud Rate          : 115200
avrdude: ser_open(): can't open device "\\.\COM15": Access is denied.


avrdude done.  Thank you.

Error during Upload: Failed uploading: uploading error: exit status 1

🙂 The verbose command line output is exactly as expected.

Check the gRPC response

Use grpcurl to run the following commands.

$ grpcurl \
  -plaintext \
  -import-path ./rpc \
  -proto cc/arduino/cli/commands/v1/commands.proto \
  127.0.0.1:50051 \
  cc.arduino.cli.commands.v1.ArduinoCoreService.Create

{
  "instance": {
    "id": 1
  }
}

$ grpcurl \
  -plaintext \
  -import-path ./rpc \
  -proto cc/arduino/cli/commands/v1/commands.proto \
  -d '{"instance": {"id": 1}}' \
  127.0.0.1:50051 \
  cc.arduino.cli.commands.v1.ArduinoCoreService.Init

Upload with verbose output disabled:

$ grpcurl \
  -plaintext \
  -import-path ./rpc \
  -proto cc/arduino/cli/commands/v1/commands.proto \
  -d '{"instance": {"id": 1}, "fqbn": "arduino:avr:uno", "sketch_path": "C:/Users/per/AppData/Local/Temp/FooSketch", "port": {"address": "COM15"}, "verbose": false}' \
  127.0.0.1:50051 \
  cc.arduino.cli.commands.v1.ArduinoCoreService.Upload

{
  "errStream": "YXZyZHVkZTogc2VyX29wZW4oKTogY2FuJ3Qgb3BlbiBkZXZpY2UgIlxcLlxDT00xNSI6IEFjY2VzcyBpcyBkZW5pZWQuDQ0KDQo="
}
ERROR:
  Code: Internal
  Message: Failed uploading: uploading error: exit status 1

🙂 The contents of the errStream field of the response is exactly as expected:

avrdude: ser_open(): can't open device "\\.\COM15": Access is denied.

Upload with verbose output enabled:

$ grpcurl \
  -plaintext \
  -import-path ./rpc \
  -proto cc/arduino/cli/commands/v1/commands.proto \
  -d '{"instance": {"id": 1}, "fqbn": "arduino:avr:uno", "sketch_path": "C:/Users/per/AppData/Local/Temp/FooSketch", "port": {"address": "COM15"}, "verbose": true}' \
  127.0.0.1:50051 \
  cc.arduino.cli.commands.v1.ArduinoCoreService.Upload

{
  "outStream": "IkM6XFVzZXJzXHBlclxBcHBEYXRhXExvY2FsXEFyZHVpbm8xNVxwYWNrYWdlc1xhcmR1aW5vXHRvb2xzXGF2cmR1ZGVcNi4zLjAtYXJkdWlubzE3L2Jpbi9hdnJkdWRlIiAiLUNDOlxVc2Vyc1xwZXJcQXBwRGF0YVxMb2NhbFxBcmR1aW5vMTVccGFja2FnZXNcYXJkdWlub1x0b29sc1xhdnJkdWRlXDYuMy4wLWFyZHVpbm8xNy9ldGMvYXZyZHVkZS5jb25mIiAtdiAtViAtcGF0bWVnYTMyOHAgLWNhcmR1aW5vICItUENPTTE1IiAtYjExNTIwMCAtRCAiLVVmbGFzaDp3OkM6XFVzZXJzXHBlclxBcHBEYXRhXExvY2FsXFRlbXBcYXJkdWluby1za2V0Y2gtMjQwNUM0QzlGOTAwMjg1MzdDNzlCMDc0NEJDRTUzNkUvRm9vU2tldGNoLmluby5oZXg6aSIK"
}
{
  "errStream": "DQo="
}
ERROR:
  Code: Internal
  Message: Failed uploading: uploading error: exit status 1

🐛 The errStream field of the response is empty.

Expected behavior

cc.arduino.cli.commands.v1.ArduinoCoreService.Upload response stream contains the full output from the upload tool.

Arduino CLI version

5332ffd

Operating system

Windows, Ubuntu

Operating system version

Windows 10, Ubuntu 20.04

Additional context

I bisected the introduction of the issue to 5332ffd

---

I encountered the issue under specific conditions, but am not certain this is the entire scope of the issue:

• Upload operation
• gRPC interface in use
• Verbose output is enabled
• Upload fails

---

I used grpcurl in the demo, but the same problem occurs when using Arduino IDE 2.x.

---

I can see the full expected output in the arduino-cli daemon --debug output (note that it is in the second segment of the stream):

CALLED: /cc.arduino.cli.commands.v1.ArduinoCoreService/Upload STREAM_RESP
5 |  REQ:  {
5 |    "instance": {
5 |      "id": 1
5 |    },
5 |    "fqbn": "arduino:avr:uno",
5 |    "sketch_path": "C:/Users/per/AppData/Local/Temp/FooSketch",
5 |    "port": {
5 |      "address": "COM15"
5 |    },
5 |    "verbose": true
5 |  }
5 |  RESP: {
5 |    "out_stream": "IkM6XFVzZXJzXHBlclxBcHBEYXRhXExvY2FsXEFyZHVpbm8xNVxwYWNrYWdlc1xhcmR1aW5vXHRvb2xzXGF2cmR1ZGVcNi4zLjAtYXJkdWlubzE3L2Jpbi9hdnJkdWRlIiAiLUNDOlxVc2Vyc1xwZXJcQXBwRGF0YVxMb2NhbFxBcmR1aW5vMTVccGFja2FnZXNcYXJkdWlub1x0b29sc1xhdnJkdWRlXDYuMy4wLWFyZHVpbm8xNy9ldGMvYXZyZHVkZS5jb25mIiAtdiAtViAtcGF0bWVnYTMyOHAgLWNhcmR1aW5vICItUENPTTE1IiAtYjExNTIwMCAtRCAiLVVmbGFzaDp3OkM6XFVzZXJzXHBlclxBcHBEYXRhXExvY2FsXFRlbXBcYXJkdWluby1za2V0Y2gtMjQwNUM0QzlGOTAwMjg1MzdDNzlCMDc0NEJDRTUzNkUvRm9vU2tldGNoLmluby5oZXg6aSIK"
5 |  }
5 |  RESP: {
5 |    "err_stream": "DQo="
5 |  }
5 |  ERROR:  rpc error: code = Internal desc = Failed uploading: uploading error: exit status 1
5 STREAM CLOSED

5 |  ERROR:  rpc error: code = Unavailable desc = transport is closing
5 |  RESP: {
5 |    "err_stream": "YXZyZHVkZTogVmVyc2lvbiA2LjMtMjAxOTA2MTkNCiAgICAgICAgIENvcHlyaWdodCAoYykgMjAwMC0yMDA1IEJyaWFuIERlYW4sIGh0dHA6Ly93d3cuYmRtaWNyby5jb20vDQogICAgICAgICBDb3B5cmlnaHQgKGMpIDIwMDctMjAxNCBKb2VyZyBXdW5zY2gNCg0KICAgICAgICAgU3lzdGVtIHdpZGUgY29uZmlndXJhdGlvbiBmaWxlIGlzICJDOlxVc2Vyc1xwZXJcQXBwRGF0YVxMb2NhbFxBcmR1aW5vMTVccGFja2FnZXNcYXJkdWlub1x0b29sc1xhdnJkdWRlXDYuMy4wLWFyZHVpbm8xNy9ldGMvYXZyZHVkZS5jb25mIg0KDQogICAgICAgICBVc2luZyBQb3J0ICAgICAgICAgICAgICAgICAgICA6IENPTTE1DQogICAgICAgICBVc2luZyBQcm9ncmFtbWVyICAgICAgICAgICAgICA6IGFyZHVpbm8NCiAgICAgICAgIE92ZXJyaWRpbmcgQmF1ZCBSYXRlICAgICAgICAgIDogMTE1MjAwDQphdnJkdWRlOiBzZXJfb3BlbigpOiBjYW4ndCBvcGVuIGRldmljZSAiXFwuXENPTTE1IjogQWNjZXNzIGlzIGRlbmllZC4NDQoNCg0KYXZyZHVkZSBkb25lLiAgVGhhbmsgeW91Lg0KDQo="
5 |  }

---

Originally reported by @sterretjeToo at https://forum.arduino.cc/t/serial-monitor-detect-interferes-with-sketch-on-promicro/1017659/5

Issue checklist

• I searched for previous reports in the issue tracker
• I verified the problem still occurs when using the nightly build
• My report contains all necessary details

[ObviousInRetrospect]

this makes SerialUPDI hard to use as a programmer and generally may degrade the quality of other bug reports

[cmaglie]

I can see the full expected output in the arduino-cli daemon --debug output (note that it is in the second segment of the stream):

Actually it is not the expected output, because the STREAM CLOSED signal happens before the last RESP

5 |  RESP: {
5 |    "err_stream": "DQo="
5 |  }
5 |  ERROR:  rpc error: code = Internal desc = Failed uploading: uploading error: exit status 1
5 STREAM CLOSED      <------ THIS SHOULD BE THE LATEST LINE

5 |  ERROR:  rpc error: code = Unavailable desc = transport is closing
5 |  RESP: {
5 |    "err_stream": "YXZyZHVkZTogVmVyc2lvbiA2LjMtMjAxOTA2MTkNCiAgICAgICAgIENvcHlyaWdodCAoYykgMjAwMC0yMDA1IEJyaWFuIERlYW4sIGh0dHA6Ly93d3cuYmRtaWNyby5jb20vDQogICAgICAgICBDb3B5cmlnaHQgKGMpIDIwMDctMjAxNCBKb2VyZyBXdW5zY2gNCg0KICAgICAgICAgU3lzdGVtIHdpZGUgY29uZmlndXJhdGlvbiBmaWxlIGlzICJDOlxVc2Vyc1xwZXJcQXBwRGF0YVxMb2NhbFxBcmR1aW5vMTVccGFja2FnZXNcYXJkdWlub1x0b29sc1xhdnJkdWRlXDYuMy4wLWFyZHVpbm8xNy9ldGMvYXZyZHVkZS5jb25mIg0KDQogICAgICAgICBVc2luZyBQb3J0ICAgICAgICAgICAgICAgICAgICA6IENPTTE1DQogICAgICAgICBVc2luZyBQcm9ncmFtbWVyICAgICAgICAgICAgICA6IGFyZHVpbm8NCiAgICAgICAgIE92ZXJyaWRpbmcgQmF1ZCBSYXRlICAgICAgICAgIDogMTE1MjAwDQphdnJkdWRlOiBzZXJfb3BlbigpOiBjYW4ndCBvcGVuIGRldmljZSAiXFwuXENPTTE1IjogQWNjZXNzIGlzIGRlbmllZC4NDQoNCg0KYXZyZHVkZSBkb25lLiAgVGhhbmsgeW91Lg0KDQo="
5 |  }

BTW I think I already fixed this problem as part of another PR:
73b3b61

@per1234 may I ask you to retest it? In case it's not fixed, may I ask you how you create the conditions for an upload failure?

[cmaglie]

I've retested with the latest version:

$ grpcurl \
  -plaintext \
  -import-path ./rpc \
  -proto cc/arduino/cli/commands/v1/commands.proto \
  -d '{"instance": {"id": 1}, "fqbn": "arduino:avr:mega:cpu=atmega1280", "sketch_path":"/home/megabug/Arduino/Blink", "port": {"address": "/dev/ttyUSB2"}, "verbose": true}' \
>   127.0.0.1:50051 \
  cc.arduino.cli.commands.v1.ArduinoCoreService.Upload
{
  "outStream": "Ii9ob21lL21lZ2FidWcvLmFyZHVpbm8xNS9wYWNrYWdlcy9hcmR1aW5vL3Rvb2xzL2F2cmR1ZGUvNi4zLjAtYXJkdWlubzE3L2Jpbi9hdnJkdWRlIiAiLUMvaG9tZS9tZWdhYnVnLy5hcmR1aW5vMTUvcGFja2FnZXMvYXJkdWluby90b29scy9hdnJkdWRlLzYuMy4wLWFyZHVpbm8xNy9ldGMvYXZyZHVkZS5jb25mIiAtdiAtViAtcGF0bWVnYTEyODAgLWNhcmR1aW5vICItUC9kZXYvdHR5VVNCMiIgLWI1NzYwMCAtRCAiLVVmbGFzaDp3Oi90bXAvYXJkdWluby9za2V0Y2hlcy8wMDIwNTBFQUE3RUZCOUE0RkM0NTFDREZCQzBGQTJEMy9CbGluay5pbm8uaGV4OmkiCg=="
}
{
  "errStream": "CmF2cmR1ZGU6IFZlcnNpb24gNi4zLTIwMTkwNjE5CiAgICAgICAgIENvcHlyaWdodCAoYykgMjAwMC0yMDA1IEJyaWFuIERlYW4sIGh0dHA6Ly93d3cuYmRtaWNyby5jb20vCiAgICAgICAgIENvcHlyaWdodCAoYykgMjAwNy0yMDE0IEpvZXJnIFd1bnNjaAoKICAgICAgICAgU3lzdGVtIHdpZGUgY29uZmlndXJhdGlvbiBmaWxlIGlzICIvaG9tZS9tZWdhYnVnLy5hcmR1aW5vMTUvcGFja2FnZXMvYXJkdWluby90b29scy9hdnJkdWRlLzYuMy4wLWFyZHVpbm8xNy9ldGMvYXZyZHVkZS5jb25mIgo="
}
{
  "errStream": "ICAgICAgICAgVXNlciBjb25maWd1cmF0aW9uIGZpbGUgaXMgIi9ob21lL21lZ2FidWcvLmF2cmR1ZGVyYyIKICAgICAgICAgVXNlciBjb25maWd1cmF0aW9uIGZpbGUgZG9lcyBub3QgZXhpc3Qgb3IgaXMgbm90IGEgcmVndWxhciBmaWxlLCBza2lwcGluZwoKICAgICAgICAgVXNpbmcgUG9ydCAgICAgICAgICAgICAgICAgICAgOiAvZGV2L3R0eVVTQjIKICAgICAgICAgVXNpbmcgUHJvZ3JhbW1lciAgICAgICAgICAgICAgOiBhcmR1aW5vCiAgICAgICAgIE92ZXJyaWRpbmcgQmF1ZCBSYXRlICAgICAgICAgIDogNTc2MDAKYXZyZHVkZTogc2VyX29wZW4oKTogY2FuJ3Qgb3BlbiBkZXZpY2UgIi9kZXYvdHR5VVNCMiI6IE5vIHN1Y2ggZmlsZSBvciBkaXJlY3RvcnkKCmF2cmR1ZGUgZG9uZS4gIFRoYW5rIHlvdS4KCg=="
}
ERROR:
  Code: Internal
  Message: Caricamento non riuscito: errore durante il caricamento: exit status 1

it seems that the avrdude stderr is streamed out, also:

3 CALLED: /cc.arduino.cli.commands.v1.ArduinoCoreService/Upload STREAM_RESP
3 |  REQ:  {
3 |    "instance": {
3 |      "id": 1
3 |    },
3 |    "fqbn": "arduino:avr:mega:cpu=atmega1280",
3 |    "sketch_path": "/home/megabug/Arduino/Blink",
3 |    "port": {
3 |      "address": "/dev/ttyUSB2"
3 |    },
3 |    "verbose": true
3 |  }
3 |  RESP: {
3 |    "out_stream": "Ii9ob21lL21lZ2FidWcvLmFyZHVpbm8xNS9wYWNrYWdlcy9hcmR1aW5vL3Rvb2xzL2F2cmR1ZGUvNi4zLjAtYXJkdWlubzE3L2Jpbi9hdnJkdWRlIiAiLUMvaG9tZS9tZWdhYnVnLy5hcmR1aW5vMTUvcGFja2FnZXMvYXJkdWluby90b29scy9hdnJkdWRlLzYuMy4wLWFyZHVpbm8xNy9ldGMvYXZyZHVkZS5jb25mIiAtdiAtViAtcGF0bWVnYTEyODAgLWNhcmR1aW5vICItUC9kZXYvdHR5VVNCMiIgLWI1NzYwMCAtRCAiLVVmbGFzaDp3Oi90bXAvYXJkdWluby9za2V0Y2hlcy8wMDIwNTBFQUE3RUZCOUE0RkM0NTFDREZCQzBGQTJEMy9CbGluay5pbm8uaGV4OmkiCg=="
3 |  }
3 |  RESP: {
3 |    "err_stream": "CmF2cmR1ZGU6IFZlcnNpb24gNi4zLTIwMTkwNjE5CiAgICAgICAgIENvcHlyaWdodCAoYykgMjAwMC0yMDA1IEJyaWFuIERlYW4sIGh0dHA6Ly93d3cuYmRtaWNyby5jb20vCiAgICAgICAgIENvcHlyaWdodCAoYykgMjAwNy0yMDE0IEpvZXJnIFd1bnNjaAoKICAgICAgICAgU3lzdGVtIHdpZGUgY29uZmlndXJhdGlvbiBmaWxlIGlzICIvaG9tZS9tZWdhYnVnLy5hcmR1aW5vMTUvcGFja2FnZXMvYXJkdWluby90b29scy9hdnJkdWRlLzYuMy4wLWFyZHVpbm8xNy9ldGMvYXZyZHVkZS5jb25mIgo="
3 |  }
3 |  RESP: {
3 |    "err_stream": "ICAgICAgICAgVXNlciBjb25maWd1cmF0aW9uIGZpbGUgaXMgIi9ob21lL21lZ2FidWcvLmF2cmR1ZGVyYyIKICAgICAgICAgVXNlciBjb25maWd1cmF0aW9uIGZpbGUgZG9lcyBub3QgZXhpc3Qgb3IgaXMgbm90IGEgcmVndWxhciBmaWxlLCBza2lwcGluZwoKICAgICAgICAgVXNpbmcgUG9ydCAgICAgICAgICAgICAgICAgICAgOiAvZGV2L3R0eVVTQjIKICAgICAgICAgVXNpbmcgUHJvZ3JhbW1lciAgICAgICAgICAgICAgOiBhcmR1aW5vCiAgICAgICAgIE92ZXJyaWRpbmcgQmF1ZCBSYXRlICAgICAgICAgIDogNTc2MDAKYXZyZHVkZTogc2VyX29wZW4oKTogY2FuJ3Qgb3BlbiBkZXZpY2UgIi9kZXYvdHR5VVNCMiI6IE5vIHN1Y2ggZmlsZSBvciBkaXJlY3RvcnkKCmF2cmR1ZGUgZG9uZS4gIFRoYW5rIHlvdS4KCg=="
3 |  }
3 |  ERROR:  rpc error: code = Internal desc = Caricamento non riuscito: errore durante il caricamento: exit status 1
3 STREAM CLOSED

the STREAM CLOSED event is generated after flushing the output.