F5, run to the next break point not working?

[kenpeter]

Hi,

I am working on Drupal 7 and open a file. I press F10 to set a break point. I press F5, then run Drupal. The debugger dropped me into the /var/aegir/platforms/staging/drupal-7.27/index.php, which is the entry point of Drupal 7. I pressed F5 and run to the end of script, instead of the break point. The F5 is working in other situations though.

Here is the log

- [Info] {Fri 23 2015 12:21:19} Searching for win by name /var/aegir/platforms/staging/drupal-7.27/profiles/foa/modules/custom/faeprofile/faeprofile.module
- [Info] {Fri 23 2015 12:21:19} Win 1, name /var/aegir/platforms/staging/drupal-7.27/profiles/foa/modules/custom/faeprofile/faeprofile.module
- [Info] {Fri 23 2015 12:21:19} Returning window number 1
- [Info] {Fri 23 2015 12:21:19} Found connection from ('127.0.0.1', 49521)
- [Info] {Fri 23 2015 12:21:19} Updated line number of breakpoint 11000 to 1690
- [Info] {Fri 23 2015 12:21:19} Registering 1 breakpoints with the debugger
- [Debug] {Fri 23 2015 12:21:19} Command: breakpoint_set -i 1 -t line -f file:///var/aegir/platforms/staging/drupal-7.27/profiles/foa/modules/custom/faeprofile/faeprofile.module -n 1690 -s enabled
- [Debug] {Fri 23 2015 12:21:19} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="breakpoint_set" transaction_id="1" state="enabled" id="186230001"></response>
- [Debug] {Fri 23 2015 12:21:19} Command: context_names -i 2
- [Debug] {Fri 23 2015 12:21:19} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="context_names" transaction_id="2"><context name="Locals" id="0"></context><context name="Superglobals" id="1"></context></response>
- [Debug] {Fri 23 2015 12:21:19} Available context names: {0: 'Locals', 1: 'Superglobals'}
- [Debug] {Fri 23 2015 12:21:19} Command: step_into -i 3
- [Debug] {Fri 23 2015 12:21:19} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="step_into" transaction_id="3" status="break" reason="ok"><xdebug:message filename="file:///var/aegir/platforms/staging/drupal-7.27/index.php" lineno="17"></xdebug:message></response>
- [Info] {Fri 23 2015 12:21:19} Getting stack information
- [Debug] {Fri 23 2015 12:21:19} Command: stack_get -i 4
- [Debug] {Fri 23 2015 12:21:19} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="stack_get" transaction_id="4"><stack where="{main}" level="0" type="file" filename="file:///var/aegir/platforms/staging/drupal-7.27/index.php" lineno="17"></stack></response>
- [Info] {Fri 23 2015 12:21:19} Moving to current position in source window
- [Info] {Fri 23 2015 12:21:19} Setting source file: /var/aegir/platforms/staging/drupal-7.27/index.php
- [Info] {Fri 23 2015 12:21:19} Placing pointer sign on line 17
- [Info] {Fri 23 2015 12:21:19} Getting Locals variables
- [Debug] {Fri 23 2015 12:21:19} Command: context_get -i 5 -c 0
- [Debug] {Fri 23 2015 12:21:19} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="5" context="0"></response>
- [Info] {Fri 23 2015 12:21:19} Writing 0 properties to the context window
- [Debug] {Fri 23 2015 12:21:19} Writing to context window:
[ *Locals ] [ Superglobals ]

- Locals at /var/aegir/platforms/staging/drupal-7.27/index.php:17


- [Info] {Fri 23 2015 12:21:22} Running
- [Debug] {Fri 23 2015 12:21:22} Command: run -i 6
- [Debug] {Fri 23 2015 12:21:22} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="run" transaction_id="6" status="stopping" reason="ok"></response>
- [Info] {Fri 23 2015 12:21:22} Debugging session has ended
- [Info] {Fri 23 2015 12:21:22} Closing the connection
- [Debug] {Fri 23 2015 12:21:22} Closing the socket

[MichaelMackus]

This seems to happen to me occasionally as well. Breakpoints don't get hit properly in my SF2 application (usually in some Twig extension or some class method nested deep somewhere), but F9 (run to line) seems to work fine 99% of the time.

[joonty]

Hi there!

I don't know if it's the formatting or the fact that I'm viewing this on mobile (not exactly ideal) but it seems like the XML responses from xdebug are truncated to only the XML definition. Can you confirm this? That would suggest something has gone awry.

Thanks

[kenpeter]

That is the full log I had. XML responses from xdebug are truncated to only the XML definition. I can confirm this.

[mtift]

I'm having a similar problem (although I'd be happy to file a separate issue if other disagree). I can get this to stop on function lines, but not go "into" them. With some functions, I can get it to stop and then enter them with F9, but not most. Unfortunately, I can't get into the functions I want to examine.

I'm working with I'm on Debian 8 (Jessie), PHP 5.6.7-1, Xdebug v2.3.2, vim-nox, and Python 2.7.9. I've tried disabling all vim plugins.

Here is my log:

- [Info] {Wed 29 2015 09:05:00} Searching for win by name /var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php
- [Info] {Wed 29 2015 09:05:00} Win 1, name /var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php
- [Info] {Wed 29 2015 09:05:00} Returning window number 1
- [Info] {Wed 29 2015 09:05:00} Found connection from ('127.0.0.1', 52463)
- [Debug] {Wed 29 2015 09:05:00} Command: feature_set -i 1 -n max_depth -v 2048
- [Debug] {Wed 29 2015 09:05:00} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="1" feature="max_depth" success="1"></response>
- [Info] {Wed 29 2015 09:05:00} Updated line number of breakpoint 11000 to 116
- [Info] {Wed 29 2015 09:05:00} Registering 1 breakpoints with the debugger
- [Debug] {Wed 29 2015 09:05:00} Command: breakpoint_set -i 2 -t line -f file:///var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php -n 116 -s enabled
- [Debug] {Wed 29 2015 09:05:00} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="breakpoint_set" transaction_id="2" state="enabled" id="43260001"></response>
- [Debug] {Wed 29 2015 09:05:00} Command: context_names -i 3
- [Debug] {Wed 29 2015 09:05:00} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="context_names" transaction_id="3"><context name="Locals" id="0"></context><context name="Superglobals" id="1"></context></response>
- [Debug] {Wed 29 2015 09:05:00} Available context names: {0: 'Locals', 1: 'Superglobals'}
- [Debug] {Wed 29 2015 09:05:00} Command: run -i 4
- [Debug] {Wed 29 2015 09:05:01} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="run" transaction_id="4" status="break" reason="ok"><xdebug:message filename="file:///var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php" lineno="116"></xdebug:message></response>
- [Info] {Wed 29 2015 09:05:01} Getting stack information
- [Debug] {Wed 29 2015 09:05:01} Command: stack_get -i 5
- [Debug] {Wed 29 2015 09:05:01} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="stack_get" transaction_id="5"><stack where="include_once" level="0" type="file" filename="file:///var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php" lineno="116"></stack><stack where="include_once" level="1" type="file" filename="file:///var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.module" lineno="12"></stack><stack where="drupal_load" level="2" type="file" filename="file:///var/www/d7/includes/bootstrap.inc" lineno="1120"></stack><stack where="module_load_all" level="3" type="file" filename="file:///var/www/d7/includes/module.inc" lineno="24"></stack><stack where="_drupal_bootstrap_full" level="4" type="file" filename="file:///var/www/d7/includes/common.inc" lineno="5214"></stack><stack where="drupal_bootstrap" level="5" type="file" filename="file:///var/www/d7/includes/bootstrap.inc" lineno="2262"></stack><stack where="_drush_bootstrap_drupal_full" level="6" type="file" filename="file:///home/mtift/git/drush/includes/bootstrap.inc" lineno="947"></stack><stack where="drush_bootstrap" level="7" type="file" filename="file:///home/mtift/git/drush/includes/bootstrap.inc" lineno="185"></stack><stack where="drush_bootstrap_to_phase" level="8" type="file" filename="file:///home/mtift/git/drush/includes/bootstrap.inc" lineno="308"></stack><stack where="_drush_bootstrap_and_dispatch" level="9" type="file" filename="file:///home/mtift/git/drush/drush.php" lineno="78"></stack><stack where="drush_main" level="10" type="file" filename="file:///home/mtift/git/drush/drush.php" lineno="61"></stack><stack where="{main}" level="11" type="file" filename="file:///home/mtift/git/drush/drush.php" lineno="16"></stack></response>
- [Info] {Wed 29 2015 09:05:01} Moving to current position in source window
- [Info] {Wed 29 2015 09:05:01} Setting source file: /var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php
- [Info] {Wed 29 2015 09:05:01} Placing pointer sign on line 116
- [Info] {Wed 29 2015 09:05:01} Getting Locals variables
- [Debug] {Wed 29 2015 09:05:01} Command: context_get -i 6 -c 0
- [Debug] {Wed 29 2015 09:05:01} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="6" context="0"><property name="$filename" fullname="$filename" address="56521920" type="string" size="76" encoding="base64"><![CDATA[c2l0ZXMvYWxsL21vZHVsZXMvY29udHJpYi9tZWRpYV90aGVwbGF0Zm9ybV9tcHgvbWVkaWFfdGhlcGxhdGZvcm1fbXB4Lm1vZHVsZQ==]]></property><property name="$files" fullname="$files" address="45827048" type="array" children="1" numchildren="1" page="0" pagesize="32"><property name="module" fullname="$files[&#39;module&#39;]" address="45802464" type="array" children="1" numchildren="22" page="0" pagesize="32"><property name="dblog" fullname="$files[&#39;module&#39;][&#39;dblog&#39;]" address="45801096" type="bool"><![CDATA[1]]></property><property name="devel" fullname="$files[&#39;module&#39;][&#39;devel&#39;]" address="45807920" type="bool"><![CDATA[1]]></property><property name="user" fullname="$files[&#39;module&#39;][&#39;user&#39;]" address="45676016" type="bool"><![CDATA[1]]></property><property name="block" fullname="$files[&#39;module&#39;][&#39;block&#39;]" address="55680984" type="bool"><![CDATA[1]]></property><property name="color" fullname="$files[&#39;module&#39;][&#39;color&#39;]" address="56733056" type="bool"><![CDATA[1]]></property><property name="comment" fullname="$files[&#39;module&#39;][&#39;comment&#39;]" address="57145160" type="bool"><![CDATA[1]]></property><property name="contextual" fullname="$files[&#39;module&#39;][&#39;contextual&#39;]" address="57289024" type="bool"><![CDATA[1]]></property><property name="ctools" fullname="$files[&#39;module&#39;][&#39;ctools&#39;]" address="57555648" type="bool"><![CDATA[1]]></property><property name="dashboard" fullname="$files[&#39;module&#39;][&#39;dashboard&#39;]" address="57677368" type="bool"><![CDATA[1]]></property><property name="elements" fullname="$files[&#39;module&#39;][&#39;elements&#39;]" address="57745328" type="bool"><![CDATA[1]]></property><property name="encrypt" fullname="$files[&#39;module&#39;][&#39;encrypt&#39;]" address="57745448" type="bool"><![CDATA[1]]></property><property name="field" fullname="$files[&#39;module&#39;][&#39;field&#39;]" address="57823136" type="bool"><![CDATA[1]]></property><property name="field_sql_storage" fullname="$files[&#39;module&#39;][&#39;field_sql_storage&#39;]" address="58805720" type="bool"><![CDATA[1]]></property><property name="field_ui" fullname="$files[&#39;module&#39;][&#39;field_ui&#39;]" address="58830280" type="bool"><![CDATA[1]]></property><property name="file" fullname="$files[&#39;module&#39;][&#39;file&#39;]" address="58855688" type="bool"><![CDATA[1]]></property><property name="file_entity" fullname="$files[&#39;module&#39;][&#39;file_entity&#39;]" address="58975120" type="bool"><![CDATA[1]]></property><property name="filter" fullname="$files[&#39;module&#39;][&#39;filter&#39;]" address="60290960" type="bool"><![CDATA[1]]></property><property name="help" fullname="$files[&#39;module&#39;][&#39;help&#39;]" address="60180656" type="bool"><![CDATA[1]]></property><property name="image" fullname="$files[&#39;module&#39;][&#39;image&#39;]" address="60180704" type="bool"><![CDATA[1]]></property><property name="list" fullname="$files[&#39;module&#39;][&#39;list&#39;]" address="60875616" type="bool"><![CDATA[1]]></property><property name="media" fullname="$files[&#39;module&#39;][&#39;media&#39;]" address="60875040" type="bool"><![CDATA[1]]></property><property name="media_internet" fullname="$files[&#39;module&#39;][&#39;media_internet&#39;]" address="61124112" type="bool"><![CDATA[1]]></property></property></property><property name="$name" fullname="$name" address="55679144" type="string" size="21" encoding="base64"><![CDATA[bWVkaWFfdGhlcGxhdGZvcm1fbXB4]]></property><property name="$type" fullname="$type" address="55865304" type="string" size="6" encoding="base64"><![CDATA[bW9kdWxl]]></property></response>
- [Info] {Wed 29 2015 09:05:01} Writing 27 properties to the context window
- [Debug] {Wed 29 2015 09:05:01} Writing to context window:
[ *Locals ] [ Superglobals ]

- Locals at /var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php:116

 ⬦ $filename = (string [76]) `sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.module`
 â–¾ $files = (array [1])
   â–¾ $files['module'] = (array [22])
     ⬦ $files['module']['dblog'] = (bool) 1
     ⬦ $files['module']['devel'] = (bool) 1
     ⬦ $files['module']['user'] = (bool) 1
     ⬦ $files['module']['block'] = (bool) 1
     ⬦ $files['module']['color'] = (bool) 1
     ⬦ $files['module']['comment'] = (bool) 1
     ⬦ $files['module']['contextual'] = (bool) 1
     ⬦ $files['module']['ctools'] = (bool) 1
     ⬦ $files['module']['dashboard'] = (bool) 1
     ⬦ $files['module']['elements'] = (bool) 1
     ⬦ $files['module']['encrypt'] = (bool) 1
     ⬦ $files['module']['field'] = (bool) 1
     ⬦ $files['module']['field_sql_storage'] = (bool) 1
     ⬦ $files['module']['field_ui'] = (bool) 1
     ⬦ $files['module']['file'] = (bool) 1
     ⬦ $files['module']['file_entity'] = (bool) 1
     ⬦ $files['module']['filter'] = (bool) 1
     ⬦ $files['module']['help'] = (bool) 1
     ⬦ $files['module']['image'] = (bool) 1
     ⬦ $files['module']['list'] = (bool) 1
     ⬦ $files['module']['media'] = (bool) 1
     ⬦ $files['module']['media_internet'] = (bool) 1
 ⬦ $name = (string [21]) `media_theplatform_mpx`
 ⬦ $type = (string [6]) `module`

- [Info] {Wed 29 2015 09:05:08} /var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php
- [Info] {Wed 29 2015 09:05:08} /var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php
- [Info] {Wed 29 2015 09:05:08} Running to position: line 120 of /var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php
- [Debug] {Wed 29 2015 09:05:08} Command: breakpoint_set -i 7 -t line -f file:///var/www/d7/sites/all/modules/contrib/media_theplatform_mpx/media_theplatform_mpx.video.php -n 120 -s enabled -r 1
- [Debug] {Wed 29 2015 09:05:08} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="breakpoint_set" transaction_id="7" state="enabled" id="43260002"></response>
- [Info] {Wed 29 2015 09:05:08} Running
- [Debug] {Wed 29 2015 09:05:08} Command: run -i 8
- [Debug] {Wed 29 2015 09:05:11} Response: <?xml version="1.0" encoding="iso-8859-1"?>
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="run" transaction_id="8" status="stopping" reason="ok"></response>
- [Info] {Wed 29 2015 09:05:11} Debugging session has ended
- [Info] {Wed 29 2015 09:05:11} Closing the connection
- [Debug] {Wed 29 2015 09:05:11} Closing the socket

[joonty]

This one's stumped me a bit. I hate apparently random bugs.

@mtift is the series of steps that you showed in the log reproducible each time? Or does it vary? Also, is it any different if you set the second breakpoint manually rather than using run to cursor?

[kepford]

I am also seeing the same issue.

[BlackIkeEagle]

So if I understand correctly the steps-to-reproduce are:

• set breakpoint
• start debugger
• reload page
• breakpoint is skipped

[kepford]

Well no. You are dropped into index.php and depending on how you step through it may skip th breakpoint. The issue is that it breaks at index.php

[BlackIkeEagle]

@kepford so you don't want to break on first line

then just set g:vdebug_options["break_on_open"] (default = 1) to 0

[BlackIkeEagle]

I think a workaround for @kenpeter is to keep break on first line on and set the breakpoint once you have a debugging session started.

• F5 -> start debugging session
• refresh page
• open your desired file in new tab in vim and set breakpoint with F10
• go back to the debugging view
• F5 -> run to the just set breakpoint

[Miljar]

I can confirm this behavior:

• Use F10 to set breakpoint
• Press F5 to start debugging session
• Refresh the page
• Debugging breaks on the first line of the entry file (app.php in case of a Symfony2 project)

The workaround suggested by @BlackIkeEagle works, but is a bit odd.

[kepford]

Thanks @BlackIkeEagle, that config change worked for me.

[cincodenada]

Okay, so to be clear, this issue isn't about the debugger breaking on the entry point of the application - that's intended behavior, and is configurable. @kepford, the issue that concerns me in your comment is this bit:

depending on how you step through it may skip the breakpoint

Are you not seeing that any more after disabling the initial entry point?

@Miljar Did you observe unexpected behavior other than the debugger breaking on the entry file?

@kenpeter, others: does @BlackIkeEagle's proposed workaround work consistently to break where you want? To be clear:

• Start the debugger (F5), letting it stop on the entry point
• Set the desired breakpoint (in a new tab)
• Continue the debugger (F5)

If that consistently works, and setting the breakpoint before starting the debugger consistently doesn't work (or doesn't work consistently), that may be helpful in getting to the bottom of this. Any logs, of course, are always welcome.

[kenpeter]

@BlackIkeEagle @cincodenada It seems working by far.