Vscode-cpptools: Debug: Stepping multi-threaded application doesn't follow thread

[Anketell]

VSCode Version: 1.13.1
cpptools Version: 0.12.0
OS Version: Fedora 21

Steps to Reproduce:

1. Place a breakpoint to interrupt execution.
2. Once the breakpoint is hit, step over (F10).

The focus in the call stack window will change from the current thread's call stack to the first call stack in the list. To continue stepping, the correct call stack (thread) must first be selected.

This make stepping through threaded code quite tedious.

The expected behaviour is that the focus in the call stack window remains at the top of the call stack for the current thread and doesn't change.

[pieandcakes]

@anketell can you enable "logging": { "engineLogging": true, "trace": true, "traceResponse": true } and retry your scenario and share the log with me? I'd like to know if the request for -thread-info is being requested on the wrong thread or if the actual issue is that the VSCode UI is changing the thread.

[Anketell]

@pieandcakes Where should this logging configuration go?

[Anketell]

@pieandcakes Ok, got it. I have some more information also. This only seems to happen if the main thread call stack is expanded. If not, when stepping, it seems to track the thread correctly.

I've cut out the bits that look interesting (hopefully the right ones)

Break point hit

------8<-----------
E stopped: {"threadId":6123,"reason":"breakpoint","source":{"name":"result_store_impl.cpp","path":"/home/vagrant/avatar/src/lib/storage/result_store_impl.cpp","sourceReference":0},"line":346,"column":1,"text":null,"allThreadsStopped":true,"type":"stopped"}
C threads: null
R: {"success":true,"message":null,"request_seq":9,"command":"threads","body":{"threads":[{"id":6118,"name":"webapp"},{"id":6123,"name":"webapp"}]},"running":false,"refs":null,"seq":0,"type":"response"}
C stackTrace: {"threadId":6123,"startFrame":0,"levels":20}
1: (12441) <-1024-stack-list-arguments 2 0 20
--------8<-----------
1: (14903) <-1036-thread-select 1
1: (14905) ->1036^done,new-thread-id="1",frame={level="0",addr="0x00007ffff5885283",func="epoll_wait",args=[],file="../sysdeps/unix/syscall-template.S",fullname="/build/eglibc-MjiXCM/eglibc-2.19/misc/../sysdeps/unix/syscall-template.S",line="81"}
1: (14905) ->(gdb)
-----------8<--------------
1: (19691) <-1039-thread-select 2
-----8<---------------

At this point we are stopped at the break point, the source code is correctly highlighted and the focus is correctly on the top the top the second thread.

Step over

1: (19693) <-1040-exec-next
1: (19694) ->1040^running
1: (19694) ->running,thread-id="2"
1: (19694) 1040: elapsed time 1
1: (19694) ->(gdb)
1: (19694) ->running,thread-id="all"
R: {"success":true,"message":null,"request_seq":14,"command":"next","body":null,"running":false,"refs":null,"seq":0,"type":"response"}
1: (19700) ->*stopped,reason="end-stepping-range",frame={addr="0x00007ffff6c7abf5",func="persistance::Result_store_impl::zip_all_transients",args=[{name="this",value="0x7fffffffe0a0"},{name="zip_filename",value="\"/tmp/test_transients.zip\""}],file="/home/vagrant/avatar/src/lib/storage/result_store_impl.cpp",fullname="/home/vagrant/avatar/src/lib/storage/result_store_impl.cpp",line="348"},thread-id="2",stopped-threads="all",core="2"
1: (19701) <-1041-stack-list-frames 0 1000
--------8<------------
1: (20169) <-1053-thread-select 1
1: (20169) ->1053^done,new-thread-id="1",frame={level="0",addr="0x00007ffff5885283",func="epoll_wait",args=[],file="../sysdeps/unix/syscall-template.S",fullname="/build/eglibc-MjiXCM/eglibc-2.19/misc/../sysdeps/unix/syscall-template.S",line="81"}
1: (20169) ->(gdb)
1: (20169) 1053: elapsed time 0
1: (20170) <-1054-stack-list-frames 0 1000
--------8<------------

So now, after the step it's collected stack information for thread 2 (the current thread) and thread 1 (the main thread) The focus is now, incorrectly, on top of the main thread.

Conversely, when I don't expand the main thread call stack, it all works as expected and I don't see that last section above where it selects thread 1 and collects it's call stack.

Presumably, the first case just needs to select the current thread after collecting the main thread's call stack - just a guess.

[pieandcakes]

@Anketell I think I need a bit more of the log. I need to know the order of thread-select going on and tie it to what VS Code is sending us. The E/R/C messages are the trace components from VSCode to our code, and the items with the -> or <- are messages from us to gdb. I'm trying to establish a timeline as to what is causing it to select the top frame versus the frame where the stopping event has occurred. If you don't feel comfortable posting it, can you send it to me in email? My email address is on my profile page.

[Anketell]

@pieandcakes I can't really share that with you as that would breach CIC. I can however distill a test case. Stay tuned...

_Sent from my HTC 0PJA10 using FastHub_

[Anketell]

@pieandcakes Ok - here 'tis.

step_test.zip - source code.
gdb_expected.txt - log of sequence that follows thread.
gdb_unexpected.txt - log of sequence that doesn't follow thread.

Expected Steps

1. Set break-point on line 14 of step_test.cpp
2. Launch debugger
3. GDB stops at break-point
4. Step over
5. Continue

Unexpected Steps

1. Set break-point on line 14 of step_test.cpp
2. Launch debugger
3. GDB stops at break-point
4. Expand main thread call stack
5. Select top of second thread (leaving main thread call stack expanded)
6. Step over
7. Continue

Outcome

As described previously, the expected sequence maintains focus on the stepped thread whereas the unexpected sequence doesn't maintain focus on the stepped thread.

gdb_expected.txt
gdb_unexpected.txt
step_test.zip

[Anketell]

@pieandcakes apologies, the logs above don't include what you want. Try these...

gdb_expected.txt
gdb_unexpected.txt

[Anketell]

@pieandcakes This behaviour has now deteriorated with cpptools v0.12.2

It is no longer possible to collapse the main thread and step through a different one. At each step, the debugger reopens the main thread and focuses it.

[Anketell]

@pieandcakes This is still the behaviour observed with cpptools v0.12.4

Again, once the main thread has been expanded, closing it again does not help. Stepping another thread will expend and refocus the main thread.

You're clearly a busy man - I'm more than happy to debug this if you make the repository available.

[pieandcakes]

@Anketell Sorry about the delay. The source for our debugging translator is located at https://github.com/Microsoft/MIEngine if you want to look. After debugging this, I think it looks like a VS Code issue.

I took your example provided and I see this:

C stackTrace: {"threadId":1,"startFrame":0,"levels":20}
 R: {"success":true,"message":null,"request_seq":16,"command":"stackTrace","body":{"stackFrames":[{"id":1008,"source":null,"line":0,"column":0,"name":"ntdll.dll!ntdll!ZwWaitForSingleObject"},{"id":1009,"source":null,"line":0,"column":0,"name":"KernelBase.dll!WaitForSingleObjectEx"},{"id":1010,"source":null,"line":0,"column":0,"name":"libwinpthread-1.dll!pthread_join"},{"id":1011,"source":{"name":"thread.h","path":"z:\\Testing\\issues\\864\\step_test\\thread.h","sourceReference":0},"line":36,"column":1,"name":"Thread::wait(Thread * const this)"},{"id":1012,"source":{"name":"step_test.cpp","path":"z:\\Testing\\issues\\864\\step_test\\step_test.cpp","sourceReference":0},"line":25,"column":1,"name":"main()"}],"totalFrames":5},"running":false,"refs":null,"seq":0,"type":"response"}
C next: {"threadId":5}
 R: {"success":true,"message":null,"request_seq":17,"command":"next","body":null,"running":false,"refs":null,"seq":0,"type":"response"}
E stopped: {"threadId":5,"reason":"step","source":{"name":"step_test.cpp","path":"z:\\Testing\\issues\\864\\step_test\\step_test.cpp","sourceReference":0},"line":15,"column":1,"text":null,"allThreadsStopped":true,"type":"stopped"}
C threads: null
 R: {"success":true,"message":null,"request_seq":18,"command":"threads","body":{"threads":[{"id":1,"name":"Thread #1"},{"id":2,"name":"Thread #2"},{"id":3,"name":"Thread #3"},{"id":4,"name":"Thread #4"},{"id":5,"name":"Thread #5"}]},"running":false,"refs":null,"seq":0,"type":"response"}
C stackTrace: {"threadId":5,"startFrame":0,"levels":20}
 R: {"success":true,"message":null,"request_seq":19,"command":"stackTrace","body":{"stackFrames":[{"id":1000,"source":{"name":"step_test.cpp","path":"z:\\Testing\\issues\\864\\step_test\\step_test.cpp","sourceReference":0},"line":15,"column":1,"name":"Step_thread::main(Step_thread * const this)"},{"id":1001,"source":{"name":"thread.h","path":"z:\\Testing\\issues\\864\\step_test\\thread.h","sourceReference":0},"line":16,"column":1,"name":"Thread::run_main(void * thread)"},{"id":1002,"source":null,"line":0,"column":0,"name":"libwinpthread-1.dll!pthread_create_wrapper"},{"id":1003,"source":null,"line":0,"column":0,"name":"msvcrt.dll!msvcrt!_beginthreadex"},{"id":1004,"source":null,"line":0,"column":0,"name":"msvcrt.dll!msvcrt!_endthreadex"},{"id":1005,"source":null,"line":0,"column":0,"name":"kernel32.dll!KERNEL32!BaseThreadInitThunk"},{"id":1006,"source":null,"line":0,"column":0,"name":"ntdll.dll!ntdll!RtlUserThreadStart"},{"id":1007,"source":null,"line":0,"column":0,"name":"[Unknown/Just-In-Time compiled code]"}],"totalFrames":8},"running":false,"refs":null,"seq":0,"type":"response"}
C stackTrace: {"threadId":1,"startFrame":0,"levels":20}
 R: {"success":true,"message":null,"request_seq":20,"command":"stackTrace","body":{"stackFrames":[{"id":1008,"source":null,"line":0,"column":0,"name":"ntdll.dll!ntdll!ZwWaitForSingleObject"},{"id":1009,"source":null,"line":0,"column":0,"name":"KernelBase.dll!WaitForSingleObjectEx"},{"id":1010,"source":null,"line":0,"column":0,"name":"libwinpthread-1.dll!pthread_join"},{"id":1011,"source":{"name":"thread.h","path":"z:\\Testing\\issues\\864\\step_test\\thread.h","sourceReference":0},"line":36,"column":1,"name":"Thread::wait(Thread * const this)"},{"id":1012,"source":{"name":"step_test.cpp","path":"z:\\Testing\\issues\\864\\step_test\\step_test.cpp","sourceReference":0},"line":25,"column":1,"name":"main()"}],"totalFrames":5},"running":false,"refs":null,"seq":0,"type":"response"}
C scopes: {"frameId":1008}
 R: {"success":true,"message":null,"request_seq":21,"command":"scopes","body":{"scopes":[]},"running":false,"refs":null,"seq":0,"type":"response"}

The interesting code is that we have stopped on thread 5 but it is requesting scopes for frame 1008 which is thread 1. I've filed issue: https://github.com/Microsoft/vscode/issues/34604

[Anketell]

Good work @pieandcakes - I'll stay tuned.

[pieandcakes]

@Anketell Looks like VSCode fixed it and it should be released in their next update (October). it is also available in VS Code Insiders build.