search

microsoft / vscode-cpptools

Official repository for the Microsoft C/C++ extension for VS Code.
Other
5.46k stars 1.53k forks source link

Step Over past a logpoint stops at the wrong place #9995

Closed nickatundo closed 1 year ago

nickatundo commented 1 year ago

Environment

Bug Summary and Steps to Reproduce

[This is my first bug report here, apologies if I've misunderstood or provided the wrong info]

If a logpoint is hit during a stepping operation (Step Into or Step Over), the program is restarted after the logpoint and simply continues until a breakpoint hits or the program exits. As I understand it, the intention wrt logpoints in C/C++ is to treat them as breakpoints, in which case the program should not be restarted at all.

To reproduce, with this program:

#include <stdio.h>

int value(void)
{
    return 7;
}

int
main(void)
{
    int x = value();
    printf("Hello, %d!\n", x);
    return 0;
}
  1. Set a breakpoint at the first line on main(), ie int x = value().
  2. Set a logpoint on the first line of value(), ie return 7;.
  3. Start a debug session. The program stops at the breakpoint as expected.
  4. Hit Step Over or press F10.
    • Ideal: the logpoint message is printed and the program stops at the second line of main(), ie printf....
    • Expected: the logpoint is treated as a breakpoint so the program stops at the return 7 line.
    • Actual: the program runs to completion.

In the debug console log it can be seen that a -exec-continue MI command is issued to restart the program.

Debugger Configurations

tasks.json:
{
    "version": "2.0.0",
    "tasks": [
        {
            "type": "cppbuild",
            "label": "C/C++: gcc-9 build active file",
            "command": "/usr/bin/gcc-9",
            "args": [
                "-fdiagnostics-color=always",
                "-g",
                "${file}",
                "-o",
                "${fileDirname}/${fileBasenameNoExtension}"
            ],
            "options": {
                "cwd": "${fileDirname}"
            },
            "problemMatcher": [
                "$gcc"
            ],
            "group": {
                "kind": "build",
                "isDefault": true
            },
            "detail": "Task generated by Debugger."
        }
    ]
}

launch.json:
        {
            "name": "gcc-9 - Build and debug active file",
            "type": "cppdbg",
            "request": "launch",
            "program": "${fileDirname}/${fileBasenameNoExtension}",
            "args": [],
            "stopAtEntry": false,
            "cwd": "${workspaceFolder}",
            "environment": [],
            "externalConsole": false,
            "MIMode": "gdb",
            "setupCommands": [
                {
                    "description": "Enable pretty-printing for gdb",
                    "text": "-enable-pretty-printing",
                    "ignoreFailures": true
                }
            ],
            "preLaunchTask": "C/C++: gcc-9 build active file",
            "logging": {
                "trace": true,
                "traceResponse": true,
                "engineLogging": true
            },
            "miDebuggerPath": "/usr/bin/gdb"
        }

Debugger Logs

<--   C (next-18): {"command":"next","arguments":{"threadId":163595},"type":"request","seq":18}
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15133) <-1036-exec-next\n"},"seq":532}
1: (15133) <-1036-exec-next
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15134) ->1036^running\n"},"seq":534}
1: (15134) ->1036^running
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15134) ->*running,thread-id=\"all\"\n"},"seq":536}
1: (15134) ->*running,thread-id="all"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15135) ->(gdb)\n"},"seq":538}
1: (15135) ->(gdb)
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15136) ->=breakpoint-modified,bkpt={number=\"2\",type=\"breakpoint\",disp=\"keep\",enabled=\"y\",addr=\"0x0000555555555151\",func=\"value\",file=\"/home/nbull/undo-1/examples/hello-world.c\",fullname=\"/home/nbull/undo-1/examples/hello-world.c\",line=\"5\",thread-groups=[\"i1\"],times=\"1\",original-location=\"hello-world.c:5\"}\n"},"seq":540}
1: (15136) ->=breakpoint-modified,bkpt={number="2",type="breakpoint",disp="keep",enabled="y",addr="0x0000555555555151",func="value",file="/home/nbull/undo-1/examples/hello-world.c",fullname="/home/nbull/undo-1/examples/hello-world.c",line="5",thread-groups=["i1"],times="1",original-location="hello-world.c:5"}
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15137) ->~\"\\n\"\n"},"seq":542}
1: (15137) ->~"\n"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15137) ->~\"Breakpoint 2, value () at /home/nbull/undo-1/examples/hello-world.c:5\\n\"\n"},"seq":544}
1: (15137) ->~"Breakpoint 2, value () at /home/nbull/undo-1/examples/hello-world.c:5\n"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15137) ->~\"5\\t    return 7;\\n\"\n"},"seq":546}
1: (15137) ->~"5\t    return 7;\n"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15137) ->*stopped,reason=\"breakpoint-hit\",disp=\"keep\",bkptno=\"2\",frame={addr=\"0x0000555555555151\",func=\"value\",args=[],file=\"/home/nbull/undo-1/examples/hello-world.c\",fullname=\"/home/nbull/undo-1/examples/hello-world.c\",line=\"5\",arch=\"i386:x86-64\"},thread-id=\"1\",stopped-threads=\"all\",core=\"7\"\n"},"seq":548}
1: (15137) ->*stopped,reason="breakpoint-hit",disp="keep",bkptno="2",frame={addr="0x0000555555555151",func="value",args=[],file="/home/nbull/undo-1/examples/hello-world.c",fullname="/home/nbull/undo-1/examples/hello-world.c",line="5",arch="i386:x86-64"},thread-id="1",stopped-threads="all",core="7"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15139) 1036: elapsed time 5\n"},"seq":550}
1: (15139) 1036: elapsed time 5
--> E (output): {"type":"event","event":"output","body":{"category":"stdout","output":"\n"},"seq":553}

--> E (output): {"type":"event","event":"output","body":{"category":"stdout","output":"Breakpoint 2, value () at /home/nbull/undo-1/examples/hello-world.c:5\n"},"seq":555}
Breakpoint 2, value () at /home/nbull/undo-1/examples/hello-world.c:5
--> E (output): {"type":"event","event":"output","body":{"category":"stdout","output":"5\t    return 7;\n"},"seq":557}
5       return 7;
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15144) <-1037-stack-list-frames 0 1000\n"},"seq":559}
1: (15144) <-1037-stack-list-frames 0 1000
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15145) ->1037^done,stack=[frame={level=\"0\",addr=\"0x0000555555555151\",func=\"value\",file=\"/home/nbull/undo-1/examples/hello-world.c\",fullname=\"/home/nbull/undo-1/examples/hello-world.c\",line=\"5\",arch=\"i386:x86-64\"},frame={level=\"1\",addr=\"0x0000555555555169\",func=\"main\",file=\"/home/nbull/undo-1/examples/hello-world.c\",fullname=\"/home/nbull/undo-1/examples/hello-world.c\",line=\"11\",arch=\"i386:x86-64\"}]\n"},"seq":561}
1: (15145) ->1037^done,stack=[frame={level="0",addr="0x0000555555555151",func="value",file="/home/nbull/undo-1/examples/hello-world.c",fullname="/home/nbull/undo-1/examples/hello-world.c",line="5",arch="i386:x86-64"},frame={level="1",addr="0x0000555555555169",func="main",file="/home/nbull/undo-1/examples/hello-world.c",fullname="/home/nbull/undo-1/examples/hello-world.c",line="11",arch="i386:x86-64"}]
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15146) ->(gdb)\n"},"seq":563}
1: (15146) ->(gdb)
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15146) 1037: elapsed time 1\n"},"seq":565}
1: (15146) 1037: elapsed time 1
--> R (next-18): {"type":"response","request_seq":18,"success":true,"command":"next","body":{},"seq":552}
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15148) <-1038-var-delete var1\n"},"seq":568}
1: (15148) <-1038-var-delete var1
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15149) ->1038^done,ndeleted=\"1\"\n"},"seq":570}
1: (15149) ->1038^done,ndeleted="1"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15149) ->(gdb)\n"},"seq":572}
1: (15149) ->(gdb)
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15150) 1038: elapsed time 1\n"},"seq":574}
1: (15150) 1038: elapsed time 1
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15152) Send Event AD7BreakpointEvent\n"},"seq":576}
1: (15152) Send Event AD7BreakpointEvent
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"SEVEN!\n"},"seq":578}
SEVEN!
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15157) <--exec-continue\n"},"seq":580}
1: (15157) <--exec-continue
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15157) ->^running\n"},"seq":582}
1: (15157) ->^running
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15157) ->*running,thread-id=\"all\"\n"},"seq":584}
1: (15157) ->*running,thread-id="all"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15157) ->(gdb)\n"},"seq":586}
1: (15157) ->(gdb)
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15158) ->~\"[Inferior 1 (process 163595) exited normally]\\n\"\n"},"seq":588}
1: (15158) ->~"[Inferior 1 (process 163595) exited normally]\n"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15158) ->=thread-exited,id=\"1\",group-id=\"i1\"\n"},"seq":590}
1: (15158) ->=thread-exited,id="1",group-id="i1"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15158) ->=thread-group-exited,id=\"i1\",exit-code=\"0\"\n"},"seq":593}
1: (15158) ->=thread-group-exited,id="i1",exit-code="0"
--> E (output): {"type":"event","event":"output","body":{"category":"stdout","output":"[Inferior 1 (process 163595) exited normally]\n"},"seq":592}
[Inferior 1 (process 163595) exited normally]
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15158) ->*stopped,reason=\"exited-normally\"\n"},"seq":595}
1: (15158) ->*stopped,reason="exited-normally"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15161) Send Event AD7ThreadDestroyEvent\n"},"seq":598}
1: (15161) Send Event AD7ThreadDestroyEvent
--> E (thread): {"type":"event","event":"thread","body":{"reason":"exited","threadId":163595},"seq":600}
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15162) <--gdb-exit\n"},"seq":602}
1: (15162) <--gdb-exit
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15163) ->^exit\n"},"seq":604}
1: (15163) ->^exit
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (15168) Send Event AD7ProgramDestroyEvent\n"},"seq":606}
1: (15168) Send Event AD7ProgramDestroyEvent
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"The program '/home/nbull/undo-1/examples/hello-world' has exited with code 0 (0x00000000).\r\n\n"},"seq":608}
The program '/home/nbull/undo-1/examples/hello-world' has exited with code 0 (0x00000000).
--> E (exited): {"type":"event","event":"exited","body":{"exitCode":0},"seq":610}
--> E (terminated): {"type":"event","event":"terminated","body":{},"seq":612}
--> E (output): {"type":"event","event":"output","body":{"category":"telemetry","output":"VS/Diagnostics/Debugger/DebugCompleted","data":{"VS.Diagnostics.Debugger.ImplementationName":"Microsoft.MIDebugEngine","VS.Diagnostics.Debugger.EngineVersion":"17.4.20818.1","VS.Diagnostics.Debugger.HostVersion":"17.4.20818.1","VS.Diagnostics.Debugger.AdapterId":"cppdbg","VS.Diagnostics.Debugger.DebugCompleted.BreakCounter":1}},"seq":614}
<--   C (disconnect-19): {"command":"disconnect","arguments":{"restart":false},"type":"request","seq":19}
--> R (disconnect-19): {"type":"response","request_seq":19,"success":true,"command":"disconnect","body":{},"seq":617}

Other Extensions

No response

Additional Information

No response

WardenGnaw commented 1 year ago

Thanks for reporting this. I will have to investigate.

We handle that case where if you are stepping into a LogPoint, it should stop. See https://github.com/microsoft/MIEngine/blob/b20b747a715a6b07aafc3a2429609d5e7449b3f1/src/OpenDebugAD7/AD7DebugSession.cs#L3461-L3474

WardenGnaw commented 1 year ago

This is a regression caused by https://github.com/microsoft/MIEngine/pull/1337.

Investigating a fix.

sean-mcmanus commented 1 year ago

Fixed with 1.13.5 (pre-release, release candidate): https://github.com/microsoft/vscode-cpptools/releases/tag/v1.13.5