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

nickatundo · 2022-10-13T12:45:40Z

Environment

OS and version: Ubuntu 20.04
VS Code: 1.72.0
C/C++ extension: 1.12.4
GDB version: 9.2

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;
}

Set a breakpoint at the first line on main(), ie int x = value().
Set a logpoint on the first line of value(), ie return 7;.
Start a debug session. The program stops at the breakpoint as expected.
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

The text was updated successfully, but these errors were encountered:

WardenGnaw · 2022-10-13T20:31:02Z

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 · 2022-10-13T21:47:44Z

This is a regression caused by microsoft/MIEngine#1337.

Investigating a fix.

sean-mcmanus · 2022-11-29T03:27:04Z

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

WardenGnaw added bug debugger labels Oct 13, 2022

WardenGnaw added the investigate: repro This issue's repro steps needs to be investigated/confirmed label Oct 13, 2022

WardenGnaw removed the investigate: repro This issue's repro steps needs to be investigated/confirmed label Oct 13, 2022

WardenGnaw mentioned this issue Oct 13, 2022

Fix LogPoint stepping microsoft/MIEngine#1362

Merged

sean-mcmanus added the fixed Check the Milestone for the release in which the fix is or will be available. label Nov 29, 2022

sean-mcmanus added this to the 1.13.5 milestone Nov 29, 2022

sean-mcmanus closed this as completed Dec 7, 2022

philips-software-forest-releaser bot mentioned this issue Mar 15, 2024

chore(deps): update llvm-vs-code-extensions.vscode-clangd, ms-vscode.cpptools philips-software/amp-devcontainer#364

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

nickatundo commented Oct 13, 2022

WardenGnaw commented Oct 13, 2022

WardenGnaw commented Oct 13, 2022

sean-mcmanus commented Nov 29, 2022

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

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

Comments

nickatundo commented Oct 13, 2022

Environment

Bug Summary and Steps to Reproduce

Debugger Configurations

Debugger Logs

Other Extensions

Additional Information

WardenGnaw commented Oct 13, 2022

WardenGnaw commented Oct 13, 2022

sean-mcmanus commented Nov 29, 2022