Possibly broken responses from `evaluate` #751

przepompownia · 2022-02-21T21:22:09Z

PHP version: 8.1.2
Xdebug version: 3.1.2
VS Code extension version: 1.24.0

Given a PHP code

<?php

$obj = new class extends stdClass {
    public $z = 1;
};

xdebug_break();
echo '';

try to evaluate $obj after stopping at the breakpoint. The context does not matter: I tested both on eval and repl`.

From XDebug I get

 [231043] [Step Debug] <- property_get -i 17 -d 0 -c 0 -n "$obj"                                                                                                                                                                             
 [231043] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="property_get" transaction_id="17"><property type="object" children="1" numchildren="1" page="0" pagesize="512"><n    ame encoding="base64"><![CDATA[JG9iag==]]></name><fullname encoding="base64"><![CDATA[JG9iag==]]></fullname><classname encoding="base64"><![CDATA[c3RkQ2xhc3NAYW5vbnltb3VzAC9ob21lL2FyY3RneC9kZXYvYXJjdGd4L3ZpbS10ZXN0LWVudnMvZGFwLXVpLXRlc3    QvdGVzdC8wNi1hbm9ueW1vdXMtY2xhc3MvaW5kLnBocDozJDA=]]></classname><property name="z" fullname="$obj-&gt;z" facet="public" type="int"><![CDATA[1]]></property></property></response>

nvim-dap logs the following response from the adapter:

 DEBUG ] 2022-02-21T19:50:34Z+0100 ] ...dap-ui-test/pack/bundle/opt/nvim-dap/lua/dap/session.lua:851 ] "request"  {
  arguments = {
    variablesReference = 4
  },
  command = "variables",
  seq = 14,
  type = "request"
}
[ DEBUG ] 2022-02-21T19:50:34Z+0100 ] ...dap-ui-test/pack/bundle/opt/nvim-dap/lua/dap/session.lua:561 ] {
  body = {
    variables = { {
        presentationHint = vim.empty_dict(),
        type = "",
        value = "$obj",
        variablesReference = 0
      }, {
        presentationHint = vim.empty_dict(),
        type = "",
        value = "$obj",
        variablesReference = 0
      }, {
        presentationHint = vim.empty_dict(),
        type = "",
        value = "stdClass@anonymous\0/home/test/nvim-test/dap-ui-test/test/06-anonymous-class/ind.php:3$0",
        variablesReference = 0
      }, {
        evaluateName = "$obj->z",
        name = "z",
        presentationHint = {
          visibility = "public"
        },
        type = "int",
        value = "1",
        variablesReference = 0
      } }
  },
  command = "variables",
  request_seq = 14,
  seq = 18,
  success = true,
  type = "response"
}

Please note that some variables does not have name field.

If you want to see the working example, in https://github.com/przepompownia/dap-ui-test please run make start to install dependencies and make anonymous-class to reproduce the example.

There seems to be also a problem with evaluation by dbgpClient CLI. I reported it on https://bugs.xdebug.org/view.php?id=2066

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

zobo · 2022-02-22T05:55:50Z

I can confirm the issue and am working on a fix.

zobo · 2022-02-22T06:44:06Z

The problem was in the traversing logic, see the PR. It assumed all chile nodes of the XML elements would be property nodes, but due to extended format, they were not.

przepompownia · 2022-02-22T10:28:47Z

Hi @zobo
thanks for quick fixing. I see no errors after the example evaluation although I still have similar error using dap-ui and created example to it (make anonymous-class-1.24.1).

Is it correct that there is no name in some elements?

[ DEBUG ] 2022-02-22T11:18:23Z+0100 ] ...dap-ui-test/pack/bundle/opt/nvim-dap/lua/dap/session.lua:851 ] "request"  {
  arguments = {
    variablesReference = 20
  },
  command = "variables",
  seq = 15,
  type = "request"
}
[ DEBUG ] 2022-02-22T11:18:23Z+0100 ] ...dap-ui-test/pack/bundle/opt/nvim-dap/lua/dap/session.lua:561 ] {
  body = {
    variables = { {
        presentationHint = vim.empty_dict(),
        type = "",
        value = "stdClass@anonymous\0/home/arctgx/dev/arctgx/vim-test-envs/dap-ui-test/test/07-anonymous-class-w-ada
pter-1.24/ind.php:3$0",
        variablesReference = 0
      }, {
        evaluateName = "z",
        name = "z",
        presentationHint = {
          visibility = "public"
        },
        type = "int",
        value = "1",
        variablesReference = 0
      } }
  },
  command = "variables",
  request_seq = 15,
  seq = 19,
  success = true,
  type = "response"
}

zobo · 2022-02-22T11:07:04Z

The output is a bit strange. I am testing in VSC, but that should not matter: I used this code:

$obj = new class extends stdClass {
    public $z = 1;
};

xdebug_break();
echo '';

And here is the relevant log:

-> variablesRequest
{
  command: 'variables',
  arguments: { variablesReference: 1 },
  type: 'request',
  seq: 16
}
xd(1) <- context_get -i 14 -d 0 -c 0
xd(1) -> <?xml version="1.0" encoding="iso-8859-1"?><response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="14" context="0"><property type="object" children="1" numchildren="1" page="0" pagesize="32"><name encoding="base64"><![CDATA[JG9iag==]]></name><fullname encoding="base64"><![CDATA[JG9iag==]]></fullname><classname encoding="base64"><![CDATA[c3RkQ2xhc3NAYW5vbnltb3VzAEM6XHRlbXBcdGVzdDEucGhwOjI2JDA=]]></classname><property name="z" fullname="$obj-&gt;z" facet="public" type="int"><![CDATA[1]]></property></property></response>
<- variablesResponse
Response {
  seq: 0,
  type: 'response',
  request_seq: 16,
  command: 'variables',
  success: true,
  body: {
    variables: [
      {
        name: '$obj',
        value: 'stdClass@anonymous\x00C:\\temp\\test1.php:26$0',
        type: 'object',
        variablesReference: 4,
        presentationHint: {},
        evaluateName: '$obj'
      }
    ]
  }
}

And when I expand the variable tree

-> variablesRequest
{
  command: 'variables',
  arguments: { variablesReference: 4 },
  type: 'request',
  seq: 17
}
<- variablesResponse
Response {
  seq: 0,
  type: 'response',
  request_seq: 17,
  command: 'variables',
  success: true,
  body: {
    variables: [
      {
        name: 'z',
        value: '1',
        type: 'int',
        variablesReference: 0,
        presentationHint: { visibility: 'public' },
        evaluateName: '$obj->z'
      }
    ]
  }
}

Notice there is no DBGP request, as the structure of all nested elements of $obj was already loaded.

I know you provided a good test case, I just cant setup things right now. If you can, please retry the test and also try to include the various logs sent by the debug adapter (OutputEvent). Don't forget to add log = true to you configuration. If you can't, I'll try to look at it later.

przepompownia · 2022-02-22T11:10:18Z

I'll try to make some more expressive example in free time.

przepompownia · 2022-02-22T23:50:34Z

I still did not found where I can find log entries from the adapter after setting log = true in the fresh master version of the example. After explanation from Derick I looked into /tmp/xdebug.log and see that extended_properties are set to 1 without my manual setting (after adding it was set again):

 [347899] [Step Debug] <- feature_set -i 3 -n extended_properties -v 1                                                                                                                                                                       
 [347899] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="3" feature="extended_properties" success="1"></response>

With this feature I get proper XML XDebug response without NULL characters

<?xml version="1.0"?>                                                                                                                                                                                                                           
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="18">                                                                                                                    
  <property type="object" children="1" numchildren="1" page="0" pagesize="512">                                                                                                                                                                 
    <classname encoding="base64"><![CDATA[c3RkQ2xhc3NAYW5vbnltb3VzAC9ob21lL2FyY3RneC9kZXYvYXJjdGd4L3ZpbS10ZXN0LWVudnMvZGFwLXVpLXRlc3QvdGVzdC8wNy1hbm9ueW1vdXMtY2xhc3Mtdy1hZGFwdGVyLTEuMjQvaW5kLnBocDozJDA=]]></classname>                       
    <property name="z" facet="public" type="int"><![CDATA[1]]></property>                                                                                                                                                                       
  </property>                                                                                                                                                                                                                                   
</response>

but I still get no name in one item:

{
arguments = {
    context = "repl",
    expression = "$obj",
    frameId = 1
  },
  command = "evaluate",
  seq = 14,
  type = "request"
}

{
  body = {
    result = "stdClass@anonymous\0/home/test/nvim-test/dap-ui-test/test/07-anonymous-class-w-adapter-1.24/ind.php:3
$0",
    variablesReference = 20
  },
  command = "evaluate",
  request_seq = 14,
  seq = 85,
  success = true,
  type = "response"
}

...

{
  arguments = {
    variablesReference = 20
  },
  command = "variables",
  seq = 15,
  type = "request"
}

 {
  body = {
    variables = {
       {
        presentationHint = vim.empty_dict(),
        type = "",
        value = "stdClass@anonymous\0/home/test/nvim-test/dap-ui-test/test/07-anonymous-class-w-adapter-1.24/ind.ph
p:3$0",
        variablesReference = 0
      },
      {
        evaluateName = "z",
        name = "z",
        presentationHint = {
          visibility = "public"
        },
        type = "int",
        value = "1",
        variablesReference = 0
      } 
   }
  },
  command = "variables",
  request_seq = 15,
  seq = 88,
  success = true,
  type = "response"
}

przepompownia · 2022-02-23T00:44:42Z

On Vimspector log message looks as expected and no problem with evaluation:

2022-02-23 01:32:06,045 - DEBUG - Visual selection: ['$obj'] from 2/0 -> 2/3
2022-02-23 01:32:06,046 - DEBUG - Sending Message: {"command": "evaluate", "arguments": {"expression": "$obj", "context": "hover", "frameId": 1}, "seq": 12, "type": "request"}
2022-02-23 01:32:06,052 - DEBUG - Message received: {'seq': 16, 'type': 'response', 'request_seq': 12, 'command': 'evaluate', 'success': True, 'body': {'result': 'stdClass@anonymous\x00/home/test/dev/test/vim-test-envs/dap-ui-test/test/07-anonymous-class-w-adapter-1.24/ind.php:3$0', 'variablesReference': 5}}
2022-02-23 01:32:06,067 - DEBUG - Sending Message: {"command": "variables", "arguments": {"variablesReference": 5}, "seq": 13, "type": "request"}
2022-02-23 01:32:06,071 - DEBUG - Message received: {'seq': 17, 'type': 'response', 'request_seq': 13, 'command': 'variables', 'success': True, 'body': {'variables': [{'name': 'z', 'value': '1', 'type': 'int', 'variablesReference': 0, 'presentationHint': {'visibility': 'public'}, 'evaluateName': '$obj->z'}]}}

It would be good to catch original messages instead of logs converted by the client.

zobo · 2022-02-23T06:12:25Z

Now I figured it out. The problem comes after expanding the eval result. And indeed there it can be reproduced... Pushing out a fix.

przepompownia · 2022-02-23T09:43:59Z

Now I get the correct response without complain from the clients:

[ DEBUG ] 2022-02-23T10:38:48Z+0100 ] ...dap-ui-test/pack/bundle/opt/nvim-dap/lua/dap/session.lua:561 ] {
  body = {
    variables = { {
        evaluateName = "z",
        name = "z",
        presentationHint = {
          visibility = "public"
        },
        type = "int",
        value = "1",
        variablesReference = 0
      } }
  },
  command = "variables",
  request_seq = 15,
  seq = 88,
  success = true,
  type = "response"
}

I am glad that we managed to close it. Thanks again!

przepompownia mentioned this issue Feb 21, 2022

Handle possibly broken responses from evaluate mfussenegger/nvim-dap#447

Closed

zobo self-assigned this Feb 22, 2022

zobo added the bug label Feb 22, 2022

zobo linked a pull request Feb 22, 2022 that will close this issue

fix: filter extended property children by tag name #752

Merged

zobo closed this as completed in #752 Feb 22, 2022

zobo linked a pull request Feb 23, 2022 that will close this issue

fix: handle root extended property on eval response #754

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Possibly broken responses from `evaluate` #751

Possibly broken responses from `evaluate` #751

przepompownia commented Feb 21, 2022

zobo commented Feb 22, 2022

zobo commented Feb 22, 2022

przepompownia commented Feb 22, 2022

zobo commented Feb 22, 2022

przepompownia commented Feb 22, 2022

przepompownia commented Feb 22, 2022 •

edited

Loading

przepompownia commented Feb 23, 2022 •

edited

Loading

zobo commented Feb 23, 2022

przepompownia commented Feb 23, 2022

Possibly broken responses from evaluate #751

Possibly broken responses from evaluate #751

Comments

przepompownia commented Feb 21, 2022

zobo commented Feb 22, 2022

zobo commented Feb 22, 2022

przepompownia commented Feb 22, 2022

zobo commented Feb 22, 2022

przepompownia commented Feb 22, 2022

przepompownia commented Feb 22, 2022 • edited Loading

przepompownia commented Feb 23, 2022 • edited Loading

zobo commented Feb 23, 2022

przepompownia commented Feb 23, 2022

Possibly broken responses from `evaluate` #751

Possibly broken responses from `evaluate` #751

przepompownia commented Feb 22, 2022 •

edited

Loading

przepompownia commented Feb 23, 2022 •

edited

Loading