xdebug / vscode-php-debug

PHP Debug Adapter for Visual Studio Code 🐞⛔
MIT License
784 stars 178 forks source link

XDebugError: command is not available #482

Closed MarceloLuis1997 closed 3 years ago

MarceloLuis1997 commented 3 years ago

Hi,

I'm using this awesome extension for a while and sometimes in the Debug Console it shows the error XDebugError: command is not available. The debug still works fine after that, but the Debug Console often shows that error.

PHP version: 7.4.3 XDebug version: 2.9.6-7.4 Adapter version: v1.14.5

launch.json:

{
    "version": "0.2.0",
    "configurations": [
        {
            "name": "Listen for XDebug",
            "type": "php",
            "request": "launch",
            "port": 9000
        },
        {
            "name": "Launch currently open script",
            "type": "php",
            "request": "launch",
            "program": "${file}",
            "cwd": "${fileDirname}",
            "port": 9000
        }
    ]
}

XDebug php.ini config:

zend_extension = C:\xampp\php\ext\php_xdebug-2.9.6-7.4-vc15-x86_64.dll
xdebug.remote_enable = 1
xdebug.remote_autostart = 1
xdebug.remote_host = localhost
xdebug.remote_handler=dbgp
xdebug.remote_port = 9000

Error log:

connection 342: read ECONNRESET
XDebugError: command is not available
    at new Response (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.14.5\out\xdebugConnection.js:58:19)
    at Connection.<anonymous> (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.14.5\out\xdebugConnection.js:613:20)
    at Generator.next (<anonymous>)
    at fulfilled (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.14.5\out\xdebugConnection.js:5:58)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:94:5) {
  code: 5,
  name: 'XDebugError'
}
connection 363: read ECONNRESET

Code snippet to reproduce: It just randomly shows the error in any endpoint of my laravel application.

allanwolski commented 3 years ago

Same problem here with my Zend application.

PHP version: 7.1.24 XDebug version: 2.9.8-7.1 Adapter version: v1.14.5

XDebugError: command is not available
    at new Response (c:\Users\Allan\.vscode\extensions\felixfbecker.php-debug-1.14.5\out\xdebugConnection.js:58:19)
    at Connection.<anonymous> (c:\Users\Allan\.vscode\extensions\felixfbecker.php-debug-1.14.5\out\xdebugConnection.js:613:20)
    at Generator.next (<anonymous>)
    at fulfilled (c:\Users\Allan\.vscode\extensions\felixfbecker.php-debug-1.14.5\out\xdebugConnection.js:5:58)
    at processTicksAndRejections (internal/process/task_queues.js:94:5) {
  code: 5,
  name: 'XDebugError'
}
wellu commented 3 years ago

Happens here also. Sometimes I need to restart debugging session to get over it. Sometimes I restart whole Visual Studio too. Dunno what causes this.

zobo commented 3 years ago

If I could see the dbgp log (xdebug3 https://xdebug.org/docs/all_settings#log xdebug2 https://2.xdebug.org/docs/all_settings#remote_log) it would help. The error here comes from Xdebug. The trace shows it happens in response to sendBreakpointRemoveCommand that only happens when VSC is setting breakpoints.

The dbgp error is described here: https://xdebug.org/docs/dbgp#error-codes and the code (Xdebug branch 2.9) gets created here https://github.com/xdebug/xdebug/blob/12ffd358e6c566788b84c409bd77584a67ad8755/src/debugger/handler_dbgp.c

This tells me, that VSC + adapter are sending breakpoint_remove command when the script is in stopping state.

R0Wi commented 3 years ago

Hi all, i'm using a docker image to run apache with xdebug 3 (https://github.com/thecodingmachine/docker-images-php). In general my setup seems to work since some breakpoints work correctly. Although others do not. I tested the setup by trying to debug Nextcloud so i set one breakpoint here which works and another one here which does not seem to work since the debugger doesn't break and instead prints the following error messages onto the console:

XDebugError: no such breakpoint
    at new Response (/home/robin/.vscode/extensions/felixfbecker.php-debug-1.14.5/out/xdebugConnection.js:58:19)
    at Connection.<anonymous> (/home/robin/.vscode/extensions/felixfbecker.php-debug-1.14.5/out/xdebugConnection.js:613:20)
    at Generator.next (<anonymous>)
    at fulfilled (/home/robin/.vscode/extensions/felixfbecker.php-debug-1.14.5/out/xdebugConnection.js:5:58)
    at processTicksAndRejections (internal/process/task_queues.js:94:5) {
  code: 205,
  name: 'XDebugError'
}
XDebugError: command is not available
    at new Response (/home/robin/.vscode/extensions/felixfbecker.php-debug-1.14.5/out/xdebugConnection.js:58:19)
    at Connection.<anonymous> (/home/robin/.vscode/extensions/felixfbecker.php-debug-1.14.5/out/xdebugConnection.js:613:20)
    at Generator.next (<anonymous>)
    at fulfilled (/home/robin/.vscode/extensions/felixfbecker.php-debug-1.14.5/out/xdebugConnection.js:5:58)
    at processTicksAndRejections (internal/process/task_queues.js:94:5) {
  code: 5,
  name: 'XDebugError'
}

@zobo i set the xdebug log level to 7 and attached the log file here, hope this helps somehow. xdebug.log

My setup (inside the docker container):

Thanks for your effort and let me know if i can provide any additional information.

zobo commented 3 years ago

Great, thanks for he dump @R0Wi . I'll inspect it and get back to you with conclusions.

R0Wi commented 3 years ago

@zobo btw: i have to correct my statement from above: even if there are some errors in the console, all breakpoints seem to be hit correctly. But of course it would be interesting what causes the errors :-) Thanks for investigation 👍

zobo commented 3 years ago

Hello @R0Wi . I have researched the issue and came to the following conclusion; It's a design issue.

The issue happens when there are concurrent scripts being debugged. There is an already related PR #366, but I'll need to check this specific behavior anyway.

The debug adapter (this extension) gets calls from vscode (setBreakPointsRequest, setExceptionBreakPointsRequest, setFunctionBreakPointsRequest). This happens when the user changes any breakpoint or on the start of the debugging session. So if concurrent debug sessions exist (like in your log) VSCode will call those at the beginning of every session.

In each of those calls, for each connection a list of existing breakpoints is fetched from Xdebug, then the list is updated by removing current breakpoints and adding them again.

The limitation of Xdebug is that the DBGp connection is blocking, and nothing is processed on it, as long as the php process is executing code. Only after a break is hit, there can be any communication on it.

Because I see a <response ... command="run" transaction_id="6" status="break"... just before the issue, and a bunch of duplicate breakpoint_list and breakpoint_remove my conclusion is that at least two setBreakPointsRequest calls are running in parallel, because while one connection is in running state, at least two more got initiated and each of them caused a setBreakPointsRequest from VSCode.

The proper way to solve this is to delegate the breakpoint management code down from the adapter to the connection level. And research how to properly handle multiple concurrent connections - be it "threads" or some other way.

@R0Wi next time I'll also ask for the VSCode debug log (enabled in launch.json).

I'll try to make a PR when time permits and have a look at it with @felixfbecker and @derickr - whenever they have time.

R0Wi commented 3 years ago

Great analysis, thanks @zobo. I think i also noticed the described "parallel behaviour" in the VSCode debuggers bottom left corner where the request threads of apache are shown. I noticed multiple entries while debugging and refreshing the Nextcloud webapplication. So this would fit to your suspicion of parallel things going on here.

If you need further information or log dumps just let me know, glad to help 👍

L3P3 commented 3 years ago

So what does this mean guys? I want to debug a Magento 2 application and just use vs code for years now. There seems to be a connection since in the debug view, it lists active requests appearing and disappearing. When I set a breakpoint thou, it says "command not supported" and "no such breakpoint". Is the bottom line for me now just "nope, cannot do it"? Or what? Thanks

zobo commented 3 years ago

Hi @L3P3. I was looking for the right solution and came up with this https://github.com/xdebug/vscode-php-debug/pull/517. It's taking a lot longer to implement as the changes are quite dramatic.

I'll try to provide a quick patch for the issue within the current plugin framework.

Once I have the other branch ready, would you be willing to test a prerelease?

Best!

L3P3 commented 3 years ago

Actually, I noticed that setting breakpoints and all that works. I still get the error messages above but for most requests, it works, just about 5% fail.

zobo commented 3 years ago

This should be solved with the new breakpoint management subsystem. Let me know if there are more problems.

nickjanssen commented 3 years ago

Still getting this on v1.15.1. Debugging works about half of the time. In my case I'm debugging code that listens for a webhook. This webhook is executed many times in succession from an external service and is thus out of my control. The app itself (and xdebug) runs in a k8s pod locally.

Here's a video of the problem. You can see that the debugger works for a few seconds, then command is not available shows.

https://user-images.githubusercontent.com/2780160/118937547-f04b0200-b94d-11eb-80a9-2ae8ea885db5.mp4

zobo commented 3 years ago

Hi @nickjanssen ! Thanks for getting back. Can you please provide all the relevant logs? To debug this I need the log from DEBUG CONSOLE (but don't forget to turn on "log": "true" in launch.json under "Listen for Xdebug") and then xdebug.log from all PHP instances - but I think in your case it's just one. Set xdebug.log to a location accessible and writable outside of the POD (or fetch it later).

There are a few things I'm thinking about:

  1. Even while debugging, you are getting a lot of requests. The current way these parallel requests are presented isn't the best and has issues. See #558 . If you can build a version of that branch (see #517) and try that I'd love to hear your feedback. This is something I will be releasing in a while. If you can't let me know and I'll provide a VSIX.
  2. One other solution, but probably not reliable, could be to limit max parallel connections. See #571
  3. Another solution for you could be to switch xdebug.start_upon_request to trigger and insert a xdebug_break(); call where you want to debug. This way, PHP/Xdebug will only connect to the debugger right there.

But please send me the logs, I would really like to figure out what the issue is.

PS: All INI variables are Xdebug 3 specific. If you are still using Xdebug 2 let me know.

wellu commented 3 years ago

It seems to me that 'command not available' leading to non-functioning breakpoints and debugging in overall most likely occurs when there are multiple asynchronous requests coming.

zobo commented 3 years ago

Yes, that was the case observed before. The old implementation just reacted to DAP setBreakPointsRequest by fetching the current list of breakpoints, removing all related to a file and the adding the received ones. The issue happened when a Xdebug connection was busy (executing a run operation) and multiple such setBreakPointsRequest happened. Then all this chain of commands (list, remove, add) happened in an overlapping order (list, list, remove, remove, add, add) that caused removal of now un-existing breakpoints. The reason why this happens is that parallel connections live in the same debug session, presented as threads, and when a new one is connected it triggers the InitializedEvent. This causes the IDE to send another setBreakPointsRequest resetting breakpoints on all existing connections.

The new implementation however keeps an internal state of breakpoints and stacks changes and sends them later to Xdebug connection when it is available.

This is why I am so curious why this would happen, because this means there's an edge case I was not able to find/test for.

wellu commented 3 years ago

Hmmm.. I have PHP Debug 1.15.1 and now that I remember I haven't seen the problem anymore. So please ignore my previous comment.

nickjanssen commented 3 years ago

@zobo here's the vscode logs of one session while the debugger crashed. I am using Xdebug 3. https://gist.github.com/nickjanssen/11b56ae62e35a35b8fb3c38dd3182133 I tried to get xdebug logs but could not get them to work, despite seemingly valid configuration settings:

Directive   Local Value Master Value
xdebug.auto_trace   (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.cli_color    0   0
xdebug.client_discovery_header  no value    no value
xdebug.client_host  host.docker.internal    localhost
xdebug.client_port  9000    9000
xdebug.cloud_id no value    no value
xdebug.collect_assignments  Off Off
xdebug.collect_includes (setting removed in Xdebug 3)   (setting removed in Xdebug 3)
xdebug.collect_params   (setting removed in Xdebug 3)   (setting removed in Xdebug 3)
xdebug.collect_return   Off Off
xdebug.collect_vars (setting removed in Xdebug 3)   (setting removed in Xdebug 3)
xdebug.connect_timeout_ms   200 200
xdebug.coverage_enable  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.default_enable   (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.discover_client_host Off Off
xdebug.dump.COOKIE  no value    no value
xdebug.dump.ENV no value    no value
xdebug.dump.FILES   no value    no value
xdebug.dump.GET no value    no value
xdebug.dump.POST    no value    no value
xdebug.dump.REQUEST no value    no value
xdebug.dump.SERVER  no value    no value
xdebug.dump.SESSION no value    no value
xdebug.dump_globals On  On
xdebug.dump_once    On  On
xdebug.dump_undefined   Off Off
xdebug.file_link_format no value    no value
xdebug.filename_format  no value    no value
xdebug.force_display_errors Off Off
xdebug.force_error_reporting    0   0
xdebug.gc_stats_enable  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.gc_stats_output_dir  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.gc_stats_output_name gcstats.%p  gcstats.%p
xdebug.halt_level   0   0
xdebug.idekey   docker  docker
xdebug.log  /tmp/xdebug.log no value
xdebug.log_level    10  7
xdebug.max_nesting_level    256 256
xdebug.max_stack_frames -1  -1
xdebug.mode debug   debug
xdebug.output_dir   /tmp    /tmp
xdebug.overload_var_dump    (setting removed in Xdebug 3)   (setting removed in Xdebug 3)
xdebug.profiler_append  Off Off
xdebug.profiler_enable  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.profiler_enable_trigger  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.profiler_enable_trigger_value    (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.profiler_output_dir  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.profiler_output_name cachegrind.out.%p   cachegrind.out.%p
xdebug.remote_autostart (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.remote_connect_back  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.remote_enable    (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.remote_host  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.remote_log   (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.remote_log_level (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.remote_mode  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.remote_port  (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.remote_timeout   (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.scream   Off Off
xdebug.show_error_trace Off Off
xdebug.show_exception_trace Off Off
xdebug.show_local_vars  Off Off
xdebug.show_mem_delta   (setting removed in Xdebug 3)   (setting removed in Xdebug 3)
xdebug.start_upon_error default default
xdebug.start_with_request   yes yes
xdebug.trace_enable_trigger (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.trace_enable_trigger_value   (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.trace_format 0   0
xdebug.trace_options    0   0
xdebug.trace_output_dir (setting renamed in Xdebug 3)   (setting renamed in Xdebug 3)
xdebug.trace_output_name    trace.%c    trace.%c
xdebug.trigger_value    no value    no value
xdebug.var_display_max_children 128 128
xdebug.var_display_max_data 512 512
xdebug.var_display_max_depth    3   3

Attempting to cat the file simply says it doesn't exist.

root@wordpress-visuade-deployment-666fdcdb56-tc8ps:/var/www/html# cat /tmp/xdebug.log
cat: /tmp/xdebug.log: No such file or directory
zobo commented 3 years ago

Maybe it's in a private tmp? See https://xdebug.org/docs/step_debug#troubleshoot

MarceloLuis1997 commented 3 years ago

I have updated my PHP DEBUG extension to v.1.15.1 and I didn't noticed the error anymore.. until now:

XdebugError: command is not available
    at new Response (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.15.1\out\xdebugConnection.js:77:19)
    at Connection.<anonymous> (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.15.1\out\xdebugConnection.js:709:20)
    at Generator.next (<anonymous>)
    at fulfilled (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.15.1\out\xdebugConnection.js:24:58)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:93:5) {
  code: 5
}
tvvocold commented 3 years ago

I have updated my PHP DEBUG extension to v.1.15.1 and I didn't noticed the error anymore.. until now:

XdebugError: command is not available
    at new Response (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.15.1\out\xdebugConnection.js:77:19)
    at Connection.<anonymous> (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.15.1\out\xdebugConnection.js:709:20)
    at Generator.next (<anonymous>)
    at fulfilled (c:\Users\Marcelo\.vscode\extensions\felixfbecker.php-debug-1.15.1\out\xdebugConnection.js:24:58)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:93:5) {
  code: 5
}

Hi, if you are using Laravel then maybe you can try to run this command : php artisan optimize && php artisan cache:clear && composer dump-autoload it works for me.

zobo commented 3 years ago

Hi @tvvocold . I'll try, but might not be able to reproduce. A new release is imminent that will also have extended logging. The extension will also log all Xdebug traffic and that should then make it trivial for me to analyze such errors. Should be out in a day or so. I'll let you know and will ask you to try to reproduce the error again with logging on.

Thanks!

zobo commented 3 years ago

@tvvocold Just a bump. The new release is out and has improved logging. All Xdebug packets should be logged in VSCode and that would help me a lot to debug your issue. If you still see it, drop me a log from VSCode and I'll analyze it. Thanks.

tvvocold commented 3 years ago

@tvvocold Just a bump. The new release is out and has improved logging. All Xdebug packets should be logged in VSCode and that would help me a lot to debug your issue. If you still see it, drop me a log from VSCode and I'll analyze it. Thanks.

@zobo Thx but I'm OK. You can ping @MarceloLuis1997 to confirm it.