golang / vscode-go

Go extension for Visual Studio Code
https://marketplace.visualstudio.com/items?itemName=golang.Go
Other
3.89k stars 751 forks source link

Debug test fails to start #1637

Closed dylankilkenny closed 3 years ago

dylankilkenny commented 3 years ago

What version of Go, VS Code & VS Code Go extension are you using?

Share the Go related settings you have added/edited

  "go.formatTool": "goimports",
  "[go]": {
    "editor.defaultFormatter": "golang.go",
    "editor.insertSpaces": false,
    "editor.formatOnSave": true,
    "editor.codeActionsOnSave": {
      "source.organizeImports": true
    },
    "editor.suggest.snippetsPreventQuickSuggestions": false
  }

Describe the bug

When clicking debug test the debug console produces the following output

API server listening at: 127.0.0.1:9352
could not launch process: stub exited while waiting for connection: exit status 0

Steps to reproduce the behavior:

  1. Click on debug test for any test
  2. View debug console
  3. See error
polinasok commented 3 years ago

Are you on MacOS? It looks like this is coming from the debugserver that dlv relies on as its backend on MacOS.

dylankilkenny commented 3 years ago

yep M1 Mac

polinasok commented 3 years ago

What's your dlv version? Since this might be an upstream error, updating dlv might do the trick if you have not done so recently. Dlv just released a new version 1.17.0.

Without a test case to reproduce, we would need some additional logging to confirm that this is an upstream error. debug test codelens doesn't use launch.json, and I don't think there is a way to enable dlv logging from settings.json via go.delveConfig. I just tried using go.alternateTools to hack dlv's settings, but it did not work for me with debug test. Would you be willing to try this with a launch.json configuration instead?

{
            "name": "Launch test function",
            "type": "go",
            "request": "launch",
            "mode": "test",
            "program": "${workspaceFolder}",
            "showLog": "true",
            "args": [
                "-test.run", "TestNameOfYourFunction",
            ]
},
polinasok commented 3 years ago

By default you will get logging from dlv's debugger layer. If instead you use"logOutput": "gdbwire" or "logOutput": "lldbout", you will get logging form the underlying layers.

dylankilkenny commented 3 years ago

The launch config you shared resulted in the same error

I have the latest delve Version: 1.7.0

polinasok commented 3 years ago

The launch config you shared resulted in the same error

I have the latest delve Version: 1.7.0

with "showLog": "true" and addittiional "logOutput" settings do you get any additional errors or related logging?

dylankilkenny commented 3 years ago

Sorry yes, here is the additional output:

API server listening at: 127.0.0.1:28918
argv[0] = 127.0.0.1:49451
argv[1] = /Users/dylankilkenny/dev/projects/bellmanford/debug.test
argv[2] = -test.run
argv[3] = TestFullSequence2
debugserver-@(#)PROGRAM:LLDB  PROJECT:lldb-1200.0.44
 for x86_64.

host = '127.0.0.1'  port = 49451
inferior_argv[0] = '/Users/dylankilkenny/dev/projects/bellmanford/debug.test'
inferior_argv[1] = '-test.run'
inferior_argv[2] = 'TestFullSequence2'
1 +0.000000 sec [11ba2/0203]: RNBRunLoopLaunchInferior Launching '/Users/dylankilkenny/dev/projects/bellmanford/debug.test'...
2 +0.000108 sec [11ba2/0203]: DNBProcessLaunch ( path='/Users/dylankilkenny/dev/projects/bellmanford/debug.test', argv = 0x7f8adac0c140, envp = 0x7f8adac0c330, working_dir=(null), stdin=/dev/stdin, stdout=/dev/stdout, stderr=/dev/stderr, no-stdio=0, launch_flavor = 1, disable_aslr = 0, err = 0x305f663d0, err_len = 1024) called...
3 +0.000111 sec [11ba2/0203]: MachProcess::MachProcess()
4 +0.000008 sec [11ba2/0203]: MachProcess::SetState(Unloaded) ignoring redundant state change...
5 +0.000006 sec [11ba2/0203]: LaunchForDebug( path = '/Users/dylankilkenny/dev/projects/bellmanford/debug.test', argv = 0x7f8adac0c140, envp = 0x7f8adac0c330, launch_flavor = 1, disable_aslr = 0 )
6 +0.000003 sec [11ba2/0203]: MachProcess::SetState(Launching) upating state (previous state was Unloaded), event_mask = 0x00000001
7 +0.000010 sec [11ba2/0203]: PosixSpawnChildForPTraceDebugging ( path='/Users/dylankilkenny/dev/projects/bellmanford/debug.test', argv=0x7f8adac0c140, envp=0x7f8adac0c330, working_dir=(null), stdin=/dev/stdin, stdout=/dev/stdout stderr=/dev/stderr, no-stdio=0)
8 +0.000008 sec [11ba2/0203]: ::posix_spawnattr_init ( &attr ) err = 0x00000000
9 +0.000016 sec [11ba2/0203]: ::posix_spawnattr_setflags ( &attr, POSIX_SPAWN_START_SUSPENDED ) err = 0x00000000
10 +0.000008 sec [11ba2/0203]: ::posix_spawn_file_actions_init ( &file_actions ) err = 0x00000000
11 +0.000008 sec [11ba2/0203]: ::posix_spawn_file_actions_addopen (&file_actions, filedes=STDIN_FILENO, path='/dev/stdin') err = 0x00000000
12 +0.000004 sec [11ba2/0203]: ::posix_spawn_file_actions_addopen (&file_actions, filedes=STDOUT_FILENO, path='/dev/stdout') err = 0x00000000
13 +0.000002 sec [11ba2/0203]: ::posix_spawn_file_actions_addopen (&file_actions, filedes=STDERR_FILENO, path='/dev/stderr') err = 0x00000000
14 +0.000450 sec [11ba2/0203]: ::posix_spawnp ( pid => 72611, path = '/Users/dylankilkenny/dev/projects/bellmanford/debug.test', file_actions = 0x305f65c30, attr = 0x305f65c40, argv = 0x7f8adac0c140, envp = 0x7f8adac0c330 ) err = 0x00000000
15 +0.000027 sec [11ba2/0203]: MachProcess::PosixSpawnChildForPTraceDebugging ( ) pid=72611, cpu_type=0x0100000c
16 +0.000003 sec [11ba2/0203]: DNBArchProtocol::SetDefaultArchitecture (cpu_type=0x0100000c) => 0
17 +0.000007 sec [11ba2/0203]: ::posix_spawn_file_actions_destroy ( &file_actions ) err = 0x00000000
18 +0.000007 sec [11ba2/0203]: MachTask::StartExceptionThread ( )
19 +0.029152 sec [11ba2/0203]: ::task_for_pid ( target_tport = 0x0103, pid = 72611, &task ) => err = 0x00000000 (success) err = 0x00000000
20 +0.000034 sec [11ba2/0203]: ::task_info ( target_task = 0x1203, flavor = TASK_BASIC_INFO, task_info_out => 0x305f65c38, task_info_outCnt => 10 ) err = 0x00000000
21 +0.000008 sec [11ba2/0203]: task_basic_info = { suspend_count = 1, virtual_size = 0x61443c8000, resident_size = 0x0000c000, user_time = 0.000000, system_time = 0.000000 }
22 +0.000017 sec [11ba2/0203]: MachException::PortInfo::Save ( task = 0x1203 )
23 +0.000012 sec [11ba2/0203]: ::task_get_exception_ports ( task = 0x1203, mask = 0x1bfe, maskCnt => 1, ports, behaviors, flavors ) err = 0x00000000
24 +0.000022 sec [11ba2/0203]: error: ::task_set_exception_ports ( task = 0x1203, exception_mask = 0x00001bfe, new_port = 0x1003, behavior = 0x80000001, new_flavor = 0x0000000d ) err = (os/kern) invalid argument (0x00000004)
Could not get inferior's Mach exception port, sending ptrace PT_KILL and exiting.
25 +0.000013 sec [11ba2/0203]: (DebugNub) new pid is 0...
26 +0.000003 sec [11ba2/0203]: MachProcess::~MachProcess()
27 +0.000002 sec [11ba2/0203]: MachProcess::SetState(Unloaded) upating state (previous state was Launching), event_mask = 0x00000002
28 +0.000020 sec [11ba2/0203]: RNBRunLoopLaunchInferior DNBProcessLaunch() returned error: '(os/kern) invalid argument'
error: failed to launch process /Library/Developer/CommandLineTools/Library/PrivateFrameworks/LLDB.framework/Versions/A/Resources/debugserver: (os/kern) invalid argument

29 +0.000004 sec [11ba2/0203]:    30255 RNBRemote::StopReadRemoteDataThread called
Exiting.

30 +0.000052 sec [11ba2/0203]: RNBRemote::~RNBRemote()
31 +0.000003 sec [11ba2/0203]:       55 RNBRemote::StopReadRemoteDataThread called
could not launch process: stub exited while waiting for connection: exit status 0
polinasok commented 3 years ago

There appears to be some kind of mismatch with your architecture and software installations: go1.16.6 darwin/arm64 vs debugserver ... for x86_64 instead of for arm64 (error is '(os/kern) invalid argument'). If go is of the right kind and working for you outside of dlv, then maybe xcode needs to be reinstalled to to get the right debugging tools?

hyangah commented 3 years ago

@dylankilkenny in addition to check the debugserver version, also check if your vscode for apple silicon or universal just in case.

Long story: I heard apple has a "defaulting to x86 if any ancestor process is x86" policy so if the vscode (or vscode-insider) is not the right arch type, all the subprocesses (including debug adapter) will use a x86 version. As seen in https://github.com/golang/vscode-go/issues/1087 and https://github.com/go-delve/delve/issues/2332, previously we suggested to use a wrapper script to sort out this because there was no arm64 native version of vscode. But now VSCode officially supports arm64, so wrapper script should be necessary any more if the right version of VSCode is used.

Thanks and let us know how it goes.

gopherbot commented 3 years ago

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

jackstine commented 3 years ago

I had to update the current version of Visual Studio Code to the new M1 Silicon version. Thanks much @hyangah!

bencom167 commented 3 years ago

I got the same issues with macbook M1. VS Code and Go are ARM64 version. The debug logs are bellow. Please help me! Many thanks!

API server listening at: 127.0.0.1:38132
argv[0] = 127.0.0.1:55199
argv[1] = /Users/bendn/code/golang/02-20210906/Test/__debug_bin
argv[2] = -test.run
argv[3] = TestNameOfYourFunction
debugserver-@(#)PROGRAM:LLDB  PROJECT:lldb-1200.0.44
 for arm64.

host = '127.0.0.1'  port = 55199
inferior_argv[0] = '/Users/bendn/code/golang/02-20210906/Test/__debug_bin'
inferior_argv[1] = '-test.run'
inferior_argv[2] = 'TestNameOfYourFunction'
1 +0.000000 sec [127de/0103]: RNBRunLoopLaunchInferior Launching '/Users/bendn/code/golang/02-20210906/Test/__debug_bin'...
2 +0.000116 sec [127de/0103]: DNBProcessLaunch ( path='/Users/bendn/code/golang/02-20210906/Test/__debug_bin', argv = 0x152e0efe0, envp = 0x152e0f2c0, working_dir=(null), stdin=/dev/stdin, stdout=/dev/stdout, stderr=/dev/stderr, no-stdio=0, launch_flavor = 1, disable_aslr = 0, err = 0x16fa55ee8, err_len = 1024) called...
3 +0.002873 sec [127de/0103]: MachProcess::MachProcess()
4 +0.000021 sec [127de/0103]: MachProcess::SetState(Unloaded) ignoring redundant state change...
5 +0.000005 sec [127de/0103]: LaunchForDebug( path = '/Users/bendn/code/golang/02-20210906/Test/__debug_bin', argv = 0x152e0efe0, envp = 0x152e0f2c0, launch_flavor = 1, disable_aslr = 0 )
6 +0.000003 sec [127de/0103]: MachProcess::SetState(Launching) upating state (previous state was Unloaded), event_mask = 0x00000001
7 +0.000003 sec [127de/0103]: PosixSpawnChildForPTraceDebugging ( path='/Users/bendn/code/golang/02-20210906/Test/__debug_bin', argv=0x152e0efe0, envp=0x152e0f2c0, working_dir=(null), stdin=/dev/stdin, stdout=/dev/stdout stderr=/dev/stderr, no-stdio=0)
8 +0.000003 sec [127de/0103]: ::posix_spawnattr_init ( &attr ) err = 0x00000000
9 +0.000002 sec [127de/0103]: ::posix_spawnattr_setflags ( &attr, POSIX_SPAWN_START_SUSPENDED ) err = 0x00000000
10 +0.000004 sec [127de/0103]: ::posix_spawn_file_actions_init ( &file_actions ) err = 0x00000000
11 +0.000003 sec [127de/0103]: ::posix_spawn_file_actions_addopen (&file_actions, filedes=STDIN_FILENO, path='/dev/stdin') err = 0x00000000
12 +0.000002 sec [127de/0103]: ::posix_spawn_file_actions_addopen (&file_actions, filedes=STDOUT_FILENO, path='/dev/stdout') err = 0x00000000
13 +0.000002 sec [127de/0103]: ::posix_spawn_file_actions_addopen (&file_actions, filedes=STDERR_FILENO, path='/dev/stderr') err = 0x00000000
14 +0.000750 sec [127de/0103]: ::posix_spawnp ( pid => 75743, path = '/Users/bendn/code/golang/02-20210906/Test/__debug_bin', file_actions = 0x16fa55a70, attr = 0x16fa55a88, argv = 0x152e0efe0, envp = 0x152e0f2c0 ) err = 0x00000000
15 +0.000010 sec [127de/0103]: MachProcess::PosixSpawnChildForPTraceDebugging ( ) pid=75743, cpu_type=0x0100000c
16 +0.000003 sec [127de/0103]: DNBArchProtocol::SetDefaultArchitecture (cpu_type=0x0100000c) => 1
17 +0.000003 sec [127de/0103]: ::posix_spawn_file_actions_destroy ( &file_actions ) err = 0x00000000
18 +0.000004 sec [127de/0103]: MachTask::StartExceptionThread ( )
19 +0.052368 sec [127de/0103]: ::task_for_pid ( target_tport = 0x0203, pid = 75743, &task ) => err = 0x00000000 (success) err = 0x00000000
20 +0.000017 sec [127de/0103]: ::task_info ( target_task = 0x0b03, flavor = TASK_BASIC_INFO, task_info_out => 0x16fa55ae8, task_info_outCnt => 10 ) err = 0x00000000
21 +0.000006 sec [127de/0103]: task_basic_info = { suspend_count = 1, virtual_size = 0x61442c4000, resident_size = 0x0000c000, user_time = 0.000000, system_time = 0.000000 }
22 +0.000003 sec [127de/0103]: MachException::PortInfo::Save ( task = 0x0b03 )
23 +0.000008 sec [127de/0103]: ::task_get_exception_ports ( task = 0x0b03, mask = 0x1bfe, maskCnt => 2, ports, behaviors, flavors ) err = 0x00000000
24 +0.000012 sec [127de/0103]: ::task_set_exception_ports ( task = 0x0b03, exception_mask = 0x00001bfe, new_port = 0x1403, behavior = 0x80000001, new_flavor = 0x00000005 ) err = 0x00000000
25 +0.000018 sec [127de/0103]: MachProcess::StartSTDIOThread ( )
26 +0.000011 sec [127de/0103]: MachProcess::SetState(Attaching) upating state (previous state was Launching), event_mask = 0x00000001
28 +0.000007 sec [127de/0c03]: MachProcess::STDIOThread ( arg = 0x15300a000 ) thread starting...
29 +0.000010 sec [127de/0c03]: MachProcess::STDIOThread (0x15300a000): thread exiting...
27 +0.000000 sec [127de/1203]: MachTask::ExceptionThread ( arg = 0x15300a068 ) starting thread...
30 +0.000014 sec [127de/0103]: successfully spawned pid 75743
31 +0.000004 sec [127de/0103]: (DebugNub) new pid is 75743...
32 +0.000007 sec [127de/1203]: ::mach_msg ( msg->{bits = 0, size = 0 remote_port = 0, local_port = 0, reserved = 0x0, id = 0x0}, option = 0x402, send_size = 0, rcv_size = 1024, rcv_name = 0x1403, timeout = 0, notify = 0)
33 +0.000009 sec [127de/0103]: RNBRunLoopLaunchInferior DNBProcessWaitForEvent (127df, eEventProcessRunningStateChanged | eEventProcessStoppedStateChanged, true, INFINITE)...
34 +0.000003 sec [127de/0103]: RNBRunLoopLaunchInferior DNBProcessWaitForEvent (127df, eEventProcessRunningStateChanged | eEventProcessStoppedStateChanged, true, INFINITE) => 0x00000001
35 +0.000002 sec [127de/0103]: RNBRunLoopLaunchInferior process 127df state changed (eEventProcessStateChanged): Attaching
36 +0.000002 sec [127de/0103]: RNBRunLoopLaunchInferior DNBProcessWaitForEvent (127df, eEventProcessRunningStateChanged | eEventProcessStoppedStateChanged, true, INFINITE)...
37 +0.277448 sec [127de/1203]: ::mach_msg ( msg->{bits = 0x80001112, size = 84 remote_port = 0xe03, local_port = 0x1403, reserved = 0x0, id = 0x965}, option = 0x402, send_size = 0, rcv_size = 1024, rcv_name = 0x1403, timeout = 0, notify = 0) err = 0x00000000
38 +0.000025 sec [127de/1203]: ::catch_mach_exception_raise ( exc_port = 0x1403, thd_port = 0x1003, tsk_port = 0x0b03, exc_type = 5 ( EXC_SOFTWARE ), exc_data[2] = { 0x10003, 0x11 })
39 +0.000018 sec [127de/1203]: ::task_suspend ( target_task = 0x0b03 ) err = 0x00000000
40 +0.000012 sec [127de/1203]: MachProcess::ExceptionMessageReceived ( )
41 +0.001612 sec [127de/1203]: error: ::mach_msg ( msg->{bits = 0, size = 0 remote_port = 0, local_port = 0, reserved = 0x0, id = 0x0}, option = 0x502, send_size = 0, rcv_size = 1024, rcv_name = 0x1403, timeout = 1, notify = 0) err = (ipc/rcv) timed out (0x10004003)
42 +0.000016 sec [127de/1203]: task_t MachProcess::ExceptionMessageBundleComplete(): 1 exception messages.
43 +0.000006 sec [127de/1203]: MachThreadList::UpdateThreadList (pid = 127df, update = 1) process stop count = 0
44 +0.000074 sec [127de/1203]: DNBArchProtocol::SetDefaultArchitecture (cpu_type=0x0100000c) => 1
45 +0.000020 sec [127de/1203]: ::task_threads ( task = 0x0b03, thread_list => 0x1008b4000, thread_list_count => 1 ) err = 0x00000000
46 +0.000077 sec [127de/1203]: MachThread::MachThread ( process = 0x153904248, tid = 0x0014991a, seq_id = 1 )
47 +0.000026 sec [127de/1203]: converted register values to debugserver's keys, return value 0, old count 68 new count 68
48 +0.000009 sec [127de/1203]: thread_get_state(0x1003, 1, &gpr, 68) => 0x00000000 (count = 68) regs
   x0=0000000000000000
   x1=0000000000000000
   x2=0000000000000000
   x3=0000000000000000
   x4=0000000000000000
   x5=0000000000000000
   x6=0000000000000000
   x7=0000000000000000
   x8=0000000000000000
   x9=0000000000000000
  x10=0000000000000000
  x11=0000000000000000
  x12=0000000000000000
  x13=0000000000000000
  x14=0000000000000000
  x15=0000000000000000
  x16=0000000000000000
  x17=0000000000000000
  x18=0000000000000000
  x19=0000000000000000
  x20=0000000000000000
  x21=0000000000000000
  x22=0000000000000000
  x23=0000000000000000
  x24=0000000000000000
  x25=0000000000000000
  x26=0000000000000000
  x27=0000000000000000
  x28=0000000000000000
   fp=0000000000000000
   lr=0000000000000000
   sp=000000016afe3550
   pc=00000001050bd000
 cpsr=00000000
49 +0.000005 sec [127de/1203]: MachThread::RestoreSuspendCountAfterStop ( )
50 +0.000007 sec [127de/1203]: MachThread::SetState ( Stopped ) for tid = 0x0014991a
51 +0.000006 sec [127de/1203]:   exc_msg { bits = 0x80001112 size = 0x00000054 remote-port = 0x00000e03 local-port = 0x00001403 reserved = 0x00000000 id = 0x00000965 } 
52 +0.000005 sec [127de/1203]: reply_msg { bits = 0x00000012 size = 0x00000024 remote-port = 0x00000e03 local-port = 0x00000000 reserved = 0x00000000 id = 0x000009c9 }
53 +0.000004 sec [127de/1203]:     state { task_port = 0x0b03, thread_port =  0x1003, exc_type = 5 (EXC_SOFTWARE) ...
54 +0.000003 sec [127de/1203]:             exc_data: EXC_SOFT_SIGNAL (17 (SIGSTOP))
55 +0.000005 sec [127de/1203]: [  0] #  1 tid: 0x0014991a, pc: 0x00000001050bd000, sp: 0x000000016afe3550, user: 0.000000, system: 0.000249, cpu:  0, policy:  1, run_state:  3 (waiting), flags:  0, suspend_count:  0 (current  0), sleep_time: 0
56 +0.000005 sec [127de/1203]: MachProcess::SetState(Stopped) upating state (previous state was Attaching), event_mask = 0x00000002
57 +0.000018 sec [127de/1203]: ::task_info ( target_task = 0x0b03, flavor = TASK_BASIC_INFO, task_info_out => 0x16fadef40, task_info_outCnt => 10 ) err = 0x00000000
58 +0.000009 sec [127de/1203]: task_basic_info = { suspend_count = 1, virtual_size = 0x61442c4000, resident_size = 0x0000c000, user_time = 0.000000, system_time = 0.000000 }
59 +0.000005 sec [127de/1203]: got a timeout, continuing...
60 +0.000002 sec [127de/0103]: RNBRunLoopLaunchInferior DNBProcessWaitForEvent (127df, eEventProcessRunningStateChanged | eEventProcessStoppedStateChanged, true, INFINITE) => 0x00000002
61 +0.000003 sec [127de/1203]: ::mach_msg ( msg->{bits = 0, size = 0 remote_port = 0, local_port = 0, reserved = 0x0, id = 0x0}, option = 0x402, send_size = 0, rcv_size = 1024, rcv_name = 0x1403, timeout = 0, notify = 0)
62 +0.000015 sec [127de/0103]: RNBRunLoopLaunchInferior process 127df state changed (eEventProcessStateChanged): Stopped
63 +0.000020 sec [127de/0103]: RNBContext::StartProcessStatusThread called
64 +0.000045 sec [127de/1503]: RNBContext::ThreadFunctionProcessStatus (arg=0x152e0d4d8, pid=127df): thread starting...
65 +0.000023 sec [127de/0103]: RNBContext::StartProcessStatusThread thread got started!
66 +0.000073 sec [127de/1503]: RNBContext::ThreadFunctionProcessStatus calling DNBProcessWaitForEvent(pid, eEventProcessRunningStateChanged | eEventProcessStoppedStateChanged | eEventStdioAvailable | eEventProfileDataAvailable, true)...
67 +0.000008 sec [127de/1503]: RNBContext::ThreadFunctionProcessStatus calling DNBProcessWaitForEvent(pid, eEventProcessRunningStateChanged | eEventProcessStoppedStateChanged | eEventStdioAvailable | eEventProfileDataAvailable, true) => 0x00000002
68 +0.000005 sec [127de/1503]: RNBContext::ThreadFunctionProcessStatus (pid=127df) got process state change: Stopped
69 +0.000004 sec [127de/1503]: RNBContext::ThreadFunctionProcessStatus calling DNBProcessWaitForEvent(pid, eEventProcessRunningStateChanged | eEventProcessStoppedStateChanged | eEventStdioAvailable | eEventProfileDataAvailable, true)...
70 +0.000807 sec [127de/0103]: Failed to reverse connect to 127.0.0.1:55199.

71 +0.000014 sec [127de/0103]:   336838 RNBRemote::StopReadRemoteDataThread called
72 +0.000004 sec [127de/0103]: RNBContext::StopProcessStatusThread called
73 +2.000669 sec [127de/0103]: RNBContext::StopProcessStatusThread thread did not stop in 2 seconds...
Exiting.

could not launch process: stub exited while waiting for connection: exit status 0
Process exiting with code: 1

`