debug server startup fails due to stdout buffering

[tlyu]

Issue Type: Bug

This is probably actually a problem in MIEngine.

I'm using the Arduino extension on macOS, and debugging with avarice and avr-gdb, but this problem also occurs if I configure a plain cppdbg instance in launch.json instead of using the Arduino extension's debugger.

If specifying a debug server to start, it apparently gets launched with pipes, not a pseudo-terminal. If it doesn't flush its stdout, then VS Code will probably never see its startup message, and therefore time out on starting it.

This category of bug seems to have been reported multiple times, usually without resolution, and usually by people working with gdb debug servers.

On macOS, there is a workaround of using /usr/bin/env as debugServerPath, and specifying STDBUF1=L with the rest of the debug server path and arguments.

Arguably, authors of debug servers should line-buffer or explicitly flush their status messages sent to stdout, but this is a subtle interaction that is unlikely to be reported or well-troubleshooted.

Extension version: 1.9.8
VS Code version: Code 1.67.2 (Universal) (c3511e6c69bb39013c4a4b7b9566ec1ca73fc4d5, 2022-05-17T18:20:57.384Z)
OS version: Darwin x64 19.6.0
Restricted Mode: No

System Info

Item	Value
CPUs	Intel(R) Core(TM) i7-7920HQ CPU @ 3.10GHz (8 x 3100)
GPU Status	2d_canvas: enabled canvas_oop_rasterization: disabled_off direct_rendering_display_compositor: disabled_off_ok gpu_compositing: enabled metal: disabled_off multiple_raster_threads: enabled_on oop_rasterization: enabled opengl: enabled_on rasterization: enabled raw_draw: disabled_off_ok skia_renderer: enabled_on video_decode: enabled video_encode: enabled webgl: enabled webgl2: enabled
Load (avg)	2, 2, 2
Memory (System)	16.00GB (0.08GB free)
Process Argv	--crash-reporter-id 8c334355-bde7-413a-8609-0fd7d4a582f2
Screen Reader	no
VM	22%

[tlyu]

I confirmed that avarice doesn't flush its stdout, both by inspecting recent source code and by observing its behavior when piped to cat.

launch.json, broken cppdbg config

        {
            "name": "broken cppdbg Arduino",
            "type": "cppdbg",
            "request": "launch",
            "program": "${workspaceFolder}/.build/${relativeFile}.elf",
            "cwd": "${workspaceFolder}/.build",
            "MIMode": "gdb",
            "miDebuggerPath": "/usr/local/bin/avr-gdb",
            "debugServerPath": "/usr/local/bin/avarice",
            "debugServerArgs": "--dragon --capture -B 1 localhost:6423",
            "serverStarted": "Waiting for connection on port \\d+\\.",
            "setupCommands": [],
            "customLaunchSetupCommands": [
                {
                    "text": "-target-select extended-remote localhost:6423"
                },
                {
                    "text": "file \"${workspaceFolder}/.build/${relativeFile}.elf\"",
                }
            ],
            "stopAtEntry": false,
            "launchCompleteCommand": "exec-continue",
            "filterStdout": true,
            "targetArchitecture": "x64",
            "args": [],
            "logging": {
                "engineLogging": true
            }
        },

debug console output, broken cppdbg config

1: (133) LaunchOptions{"name":"broken cppdbg Arduino","type":"cppdbg","request":"launch","program":"/Users/tlyu/Documents/Arduino/Blink32u4/.build/Blink32u4.ino.elf","cwd":"/Users/tlyu/Documents/Arduino/Blink32u4/.build","MIMode":"gdb","miDebuggerPath":"/usr/local/bin/avr-gdb","debugServerPath":"/usr/local/bin/avarice","debugServerArgs":"--dragon --capture -B 1 localhost:6423","serverStarted":"Waiting for connection on port \\d+\\.","setupCommands":[],"customLaunchSetupCommands":[{"text":"-target-select extended-remote localhost:6423"},{"text":"file \"/Users/tlyu/Documents/Arduino/Blink32u4/.build/Blink32u4.ino.elf\""}],"stopAtEntry":false,"launchCompleteCommand":"exec-continue","filterStdout":true,"targetArchitecture":"x64","args":[],"logging":{"engineLogging":true},"__configurationTarget":5,"__sessionId":"b7049928-7e62-4453-bf54-4cb60e0f5c16"}
1: (274) codeSign-stderr: /usr/local/bin/avr-gdb: code object is not signed at all
1: (276) Send Event AD7MessageEvent
1: (281) Starting: "/usr/local/bin/avarice" --dragon --capture -B 1 localhost:6423
1: (10290) <-logout
1: (10333) Send Event AD7MessageEvent
ERROR: Unable to start debugging. Debug server process failed to initialize.

launch.json, working cppdbg config

        {
            "name": "working cppdbg Arduino",
            "type": "cppdbg",
            "request": "launch",
            "program": "${workspaceFolder}/.build/${relativeFile}.elf",
            "cwd": "${workspaceFolder}/.build",
            "MIMode": "gdb",
            "miDebuggerPath": "/usr/local/bin/avr-gdb",
            "debugServerPath": "/usr/bin/env",
            "debugServerArgs": "STDBUF1=L /usr/local/bin/avarice --dragon --capture -B 1 localhost:6423",
            "serverStarted": "Waiting for connection on port \\d+\\.",
            "setupCommands": [],
            "customLaunchSetupCommands": [
                {
                    "text": "-target-select extended-remote localhost:6423"
                },
                {
                    "text": "file \"${workspaceFolder}/.build/${relativeFile}.elf\"",
                }
            ],
            "stopAtEntry": false,
            "launchCompleteCommand": "exec-continue",
            "filterStdout": true,
            "targetArchitecture": "x64",
            "args": [],
            "logging": {
                "engineLogging": true
            }
        }

debug console, working cppdbg config

1: (120) LaunchOptions{"name":"working cppdbg Arduino","type":"cppdbg","request":"launch","program":"/Users/tlyu/Documents/Arduino/Blink32u4/.build/Blink32u4.ino.elf","cwd":"/Users/tlyu/Documents/Arduino/Blink32u4/.build","MIMode":"gdb","miDebuggerPath":"/usr/local/bin/avr-gdb","debugServerPath":"/usr/bin/env","debugServerArgs":"STDBUF1=L /usr/local/bin/avarice --dragon --capture -B 1 localhost:6423","serverStarted":"Waiting for connection on port \\d+\\.","setupCommands":[],"customLaunchSetupCommands":[{"text":"-target-select extended-remote localhost:6423"},{"text":"file \"/Users/tlyu/Documents/Arduino/Blink32u4/.build/Blink32u4.ino.elf\""}],"stopAtEntry":false,"launchCompleteCommand":"exec-continue","filterStdout":true,"targetArchitecture":"x64","args":[],"logging":{"engineLogging":true},"__configurationTarget":5,"__sessionId":"9906602a-9dd2-4e8e-bff4-6a68eedb7729"}
1: (204) codeSign-stderr: /usr/local/bin/avr-gdb: code object is not signed at all
1: (206) Send Event AD7MessageEvent
1: (210) Starting: "/usr/bin/env" STDBUF1=L /usr/local/bin/avarice --dragon --capture -B 1 localhost:6423
1: (220) ->AVaRICE version 2.13, May 31 2022 01:49:42
1: (226) ->
1: (231) ->JTAG config starting.
1: (231) ->Found a device: AVRDRAGON
1: (231) ->Serial number:  00:a2:00:02:80:0d
1: (287) ->Reported JTAG device ID: 0x9587
1: (287) ->Configured for device ID: 0x9587 atmega32u4
1: (404) ->JTAG config complete.
1: (408) ->Waiting for connection on port 6423.
1: (415) Starting: "/usr/local/bin/avr-gdb" --interpreter=mi
1: (420) DebuggerPid=36463
1: (544) ->=thread-group-added,id="i1"
1: (545) ->~"GNU gdb (GDB) 10.1\n"
1: (545) ->~"Copyright (C) 2020 Free Software Foundation, Inc.\n"
1: (546) ->~"License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>\nThis is free software: you are free to change and redistribute it.\nThere is NO WARRANTY, to the extent permitted by law."
1: (546) ->~"\nType \"show copying\" and \"show warranty\" for details.\n"
1: (546) ->~"This GDB was configured as \"--host=x86_64-apple-darwin19.6.0 --target=avr\".\n"
1: (546) ->~"Type \"show configuration\" for configuration details.\n"
1: (546) ->~"For bug reporting instructions, please see:\n"
1: (546) ->~"<https://www.gnu.org/software/gdb/bugs/>.\n"
1: (546) ->~"Find the GDB manual and other documentation resources online at:\n    <http://www.gnu.org/software/gdb/documentation/>."
1: (546) ->~"\n\n"
1: (546) ->~"For help, type \"help\".\n"
1: (546) ->~"Type \"apropos word\" to search for commands related to \"word\".\n"
1: (546) ->(gdb)
1: (554) <-1001-gdb-set mi-async on
1: (555) ->1001^done
1: (555) ->(gdb)
1: (558) 1001: elapsed time 5
1: (572) <-1002-interpreter-exec console "set pagination off"
1: (572) ->=cmd-param-changed,param="pagination",value="off"
1: (572) ->1002^done
1: (572) ->(gdb)
1: (572) 1002: elapsed time 0
1: (572) <-1003-gdb-set auto-solib-add on
1: (572) ->1003^done
1: (572) ->(gdb)
1: (573) 1003: elapsed time 0
1: (573) <-1004-gdb-set solib-search-path /Users/tlyu/Documents/Arduino/Blink32u4/.build:
1: (573) ->1004^done
1: (574) ->(gdb)
1: (574) 1004: elapsed time 0
1: (574) <-1005-target-select extended-remote localhost:6423
1: (576) ->Connection opened by host 127.0.0.1, port 53725.
1: (578) ->=thread-group-started,id="i1",pid="42000"
1: (578) ->&"warning: No executable has been specified and target does not support\ndetermining executable automatically.  Try using the \"file\" command."
1: (578) ->&"\n"
1: (578) ->=thread-created,id="1",group-id="i1"
1: (586) <-1006-thread-info 1
1: (796) ->~"0x00000640 in ?? ()\n"
1: (796) ->*stopped,frame={addr="0x00000640",func="??",args=[],arch="avr"},thread-id="1",stopped-threads="all"
1: (796) ->1005^connected
1: (796) ->(gdb)
1: (796) ->1006^done,threads=[{id="1",target-id="Thread <main>",frame={level="0",addr="0x00000640",func="??",args=[],arch="avr"},state="stopped"}]
1: (796) ->(gdb)
1: (803) 1005: elapsed time 229
1: (807) 1006: elapsed time 220
1: (808) <-1007-interpreter-exec console "file \"/Users/tlyu/Documents/Arduino/Blink32u4/.build/Blink32u4.ino.elf\""
1: (808) ->~"A program is being debugged already.\nAre you sure you want to change the file? "
1: (809) ->~"(y or n) [answered Y; input not from terminal]\n"
1: (817) ->~"Reading symbols from /Users/tlyu/Documents/Arduino/Blink32u4/.build/Blink32u4.ino.elf...\n"
1: (824) ->1007^done
1: (824) 1007: elapsed time 15
1: (824) ->(gdb)
1: (830) Send Event AD7EngineCreateEvent
1: (831) Send Event AD7ProgramCreateEvent
WARNING: Debugger executable '/usr/local/bin/avr-gdb' is not signed. As a result, debugging may not work properly.
1: (961) Send Event AD7LoadCompleteEvent
env: AVaRICE version 2.13, May 31 2022 01:49:42
env: 
env: JTAG config starting.
env: Found a device: AVRDRAGON
env: Serial number:  00:a2:00:02:80:0d
env: Reported JTAG device ID: 0x9587
env: Configured for device ID: 0x9587 atmega32u4
env: JTAG config complete.
env: Waiting for connection on port 6423.
=thread-group-added,id="i1"
GNU gdb (GDB) 10.1
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "--host=x86_64-apple-darwin19.6.0 --target=avr".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word".
=cmd-param-changed,param="pagination",value="off"
env: Connection opened by host 127.0.0.1, port 53725.
0x00000640 in ?? ()
1: (1003) <-1008-thread-info
1: (1061) ->1008^done,threads=[{id="1",target-id="Thread <main>",frame={level="0",addr="0x00000640",func="micros",args=[],file="/Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/wiring.c",fullname="/Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/wiring.c",line="103",arch="avr:5"},state="stopped"}],current-thread-id="1"
1: (1061) ->(gdb)
1: (1061) 1008: elapsed time 58
1: (1075) <-1009-stack-list-frames 0 1000
1: (1139) ->1009^done,stack=[frame={level="0",addr="0x00000640",func="micros",file="/Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/wiring.c",fullname="/Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/wiring.c",line="103",arch="avr:5"},frame={level="1",addr="0x00000664",func="delay",file="/Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/wiring.c",fullname="/Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/wiring.c",line="112",arch="avr:5"},frame={level="2",addr="0x00000f44",func="loop",file="/Users/tlyu/Documents/Arduino/Blink32u4/Blink32u4.ino",fullname="/Users/tlyu/Documents/Arduino/Blink32u4/Blink32u4.ino",line="23",arch="avr:5"},frame={level="3",addr="0x00000f44",func="main",file="/Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/main.cpp",fullname="/Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/main.cpp",line="46",arch="avr:5"}]
1: (1139) ->(gdb)
1: (1140) 1009: elapsed time 65
1: (1144) Send Event AD7ProcessInfoUpdatedEvent
1: (1155) Send Event AD7ThreadCreateEvent
1: (1183) <--exec-continue
1: (1184) ->^running
1: (1184) ->*running,thread-id="all"
1: (1184) ->(gdb)
1: (8092) <-1010-exec-interrupt
1: (8093) ->1010^done
1: (8093) ->(gdb)
1: (8094) 1010: elapsed time 1
1: (8575) ->~"\nProgram"
1: (8575) ->~" received signal SIGINT, Interrupt.\n"

Program received signal SIGINT, Interrupt.
1: (8583) ->~"0x0000060a in micros () at /Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/wiring.c:84\n"
0x0000060a in micros () at /Users/tlyu/Library/Arduino15/packages/arduino/hardware/avr/1.8.5/cores/arduino/wiring.c:84

[tlyu]

Examples of other possible instances of this bug, or similar bugs:

https://forums.mbed.com/t/visual-studio-code-unable-to-start-debugging-debug-server-process-failed-to-initialize/8104

https://stackoverflow.com/questions/49342654/how-to-run-openocd-gdb-server-from-visual-studio-code

microsoft/vscode#69405