Odd behaviour with Vagrant, PHPStorm and Xdebug

[euphio]

I'm having problems getting PhpStorm and the internal Xdebug in HHVM playing nicely on a vagrant box, so thought I'd post this here as it looks like a potential bug.

PhpStorm is listening on Port 9080, if I remove all remote servers upon first run PhpStorm gives me the usual "Incoming Connection from Xdebug".

After I select the correct mapping and the first breakpoint is hit HHVM appears to hang before returning a 504 Gateway Time-out. If I remove the breakpoint then the load is instant, so clearly the PhpStorm and Xdebug appear to be communicating, but the debug window never shows any stack info / break point controls.

I'm on Ubuntu 14.04, Vagrant 1.6.5, PhpStorm 8.0.2
VM is also 14.04 with Nginx + HipHop VM 3.4.1, Extension API: 20140829

php.ini xdebug settings.

xdebug.enable=1
xdebug.remote_enable=1
xdebug.idekey="PHPSTORM"
xdebug.remote_host="10.0.2.2"
xdebug.remote_port="9080"
xdebug.remote_autostart=0
xdebug.remote_connect_back=1

Below is the output from the xdebug remote connection log before the halt:

Log opened at[2014-12-18 14:59:16]
I: Checking remote connect back address.
I: Remote address found, connecting to 192.168.56.1:9089.
I: Connected to client. :-)
-> <init xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" fileuri="file:///var/www/public/index.php" language="PHP" protocol_version="1.0" appid="9660" idekey="PHPSTORM"><engine version=""><![CDATA[xdebug]]></engine><author><![CDATA[HHVM]]></author><url><![CDATA[http://hhvm.com/]]></url><copyright><![CDATA[Copyright (c) 2002-2013 by Derick Rethans]]></copyright></init>

<- feature_set -i 1 -n show_hidden -v 1
-> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="1" feature="show_hidden" success="1"></response>

<- feature_set -i 2 -n max_depth -v 1
-> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="2" feature="max_depth" success="1"></response>

<- feature_set -i 3 -n max_children -v 100
-> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="3" feature="max_children" success="1"></response>

<- status -i 4
-> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="status" transaction_id="4" status="starting" reason="ok"></response>

<- step_into -i 5
-> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" status="break" reason="ok" command="step_into" transaction_id="5"><xdebug:message lineno="12" filename="file:///var/www/public/index.php"></xdebug:message></response>

<- breakpoint_set -i 6 -t line -f file:///var/www/public/index.php -n 32
-> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="breakpoint_set" transaction_id="6" id="18" state="enabled"></response>

After this a very peculiar thing happens though, if I click the "Add method to skip list" button in PhpStorm, It continues communicating with Xdebug as if stepping through variables, one with each click, for example:

<- stack_get -i 8
-> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="stack_get" transaction_id="8"><stack where="{main}" level="0" type="file" filename="file:///var/www/public/index.php" lineno="12"></stack></response>

Eventually the expected controls are shown after several of these "stack_get" calls have been hackily stepped through in this manner.

[roman-shuhov]

I have very similar issue with hhvm debug. My xdebug configuration is following:

xdebug.enable = 1
 xdebug.remote_enable = 1
 xdebug.remote_autostart = 1
 xdebug.remote_connect_back = 1
 xdebug.remote_port = 9999
 xdebug.remote_host = "172.16.97.1"

I'm using PHPStorm 8.0.3.

When I try to debug php project with just a checkbox "Break at first line in PHP Scripts" it works fine. But, if i try to put any breakpoint in the code, HHVM just hangs and doesn't respond. It starts work again only after HHVM restart.

Moreover, if i set breakpoint after PHPStorm breaks at the first line, and remove this breakpoint before script ends, hhvm works fine.

VM is 14.04 with Apache + HipHop VM 3.5.0

I also got exception report in my logs:

Host: packer-vmware-iso
 ProcessID: 9459
 ThreadID: 7fa5223ff700
 ThreadPID: 9464
 Name: unknown program
 Type: Segmentation fault
 Runtime: hhvm
 Version: tags/HHVM-3.5.0-0-ga90f4733cfa0d8fefdafc7433f758f78cdc75424
 DebuggerCount: 0


 # 0  folly::IOBuf::countChainElements() const at /usr/bin/hhvm:0
 # 1  folly::AsyncSocket::writeChain(folly::AsyncSocket::WriteCallback*, std::unique_ptr<folly::IOBuf,   std::default_delete<folly::IOBuf> >&&, folly::WriteFlags) at /usr/bin/hhvm:0
 # 2  HPHP::FastCGISession::writeStream(unsigned short, HPHP::FastCGISession::RecordType, std::          unique_ptr<folly::IOBuf, std::default_delete<folly::IOBuf> >) at /usr/bin/hhvm:0
 # 3  HPHP::FastCGITransaction::onStdOut(std::unique_ptr<folly::IOBuf, std::default_delete<folly::       IOBuf> >) at /usr/bin/hhvm:0
# 4  std::_Function_handler<void (), HPHP::FastCGITransport::sendImpl(void const*, int, int, bool)::    {lambda()#1}>::_M_invoke(std::_Any_data const&) at fastcgi-transport.cpp:0
 # 5  folly::EventBase::runFunctionPtr(std::function<void ()>*) at /usr/bin/hhvm:0
 # 6  folly::EventBase::FunctionRunner::messageAvailable(std::pair<void (*)(void*), void*>&&) at /usr/   bin/hhvm:0
 # 7  folly::NotificationQueue<std::pair<void (*)(void*), void*> >::Consumer::consumeMessages(bool) at / usr/bin/hhvm:0
 # 8  event_base_loop at /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5:0
 # 9  folly::EventBase::loopBody(int) at /usr/bin/hhvm:0
 # 10 folly::EventBase::loopForever() at /usr/bin/hhvm:0
 # 11 proxygen::WorkerThread::runLoop() at /usr/bin/hhvm:0
 # 12 std::thread::_Impl<std::_Bind_simple<proxygen::WorkerThread::start()::{lambda()#1} ()> >::         _M_run() at WorkerThread.cpp:0
 # 13 std::this_thread::__sleep_for(std::chrono::duration<long, std::ratio<1l, 1l> >, std::chrono::      duration<long, std::ratio<1l, 1000000000l> >) at /usr/lib/x86_64-linux-gnu/libstdc++.so.6:0
 # 14 start_thread at /lib/x86_64-linux-gnu/libpthread.so.0:0
 # 15 clone at /lib/x86_64-linux-gnu/libc.so.6:0

[roman-shuhov]

that's also probably related to #4351

[jwatzman]

@euphio can you confirm if HHVM is crashing or not? If so this does sound like #4351.

[euphio]

My experience with this lead me to believe it was more likely a hang, than irrecoverable crash, due to the weird hack I explained above.

@roman-shuhov try setting a breakpoint very early in the code (first couple of lines), wait for the incoming connection to be recognised by PhpStorm and then everything should hang. After this click the "Add method to skip list" button on the debug panel 20-30 times and see if it comes back to life.

[roman-shuhov]

I'm experiencing 2 types of errors:

• when i select "Start listening..." and "Break at first...." phpstorm doesn't do anything and request just hang. If i uncheck "Start listening..." requests start working good.
  Btw, the most strange thing that sometimes it works without any changes in configuration (at least i didn't find the steps to reproduce it a.k.a. make it work correctly)
• when i set breakpoint all requests to hhvm hang. If i remove breakpoint, disable debugging in phpstorm, hhvm fails with "segmentation fault":
  Unhandled server exception: \n
  Core dumped: Segmentation fault
  Stack trace in /tmp/stacktrace.11209.log

Content of the log file
Host: packer-vmware-iso
ProcessID: 11211
ThreadID: 7f5ae33ff700
ThreadPID: 11216
Name: unknown program
Type: Segmentation fault
Runtime: hhvm
Version: tags/HHVM-3.5.0-0-ga90f4733cfa0d8fefdafc7433f758f78cdc75424
DebuggerCount: 0


# 0  folly::IOBuf::countChainElements() const at /usr/bin/hhvm:0
# 1  folly::AsyncSocket::writeChain(folly::AsyncSocket::WriteCallback*, std::unique_ptr<folly::IOBuf, std::default_delete<folly::IOBuf> >&&, folly::WriteFlags) at /usr/bin/hhvm:0
# 2  HPHP::FastCGISession::writeStream(unsigned short, HPHP::FastCGISession::RecordType, std::unique_ptr<folly::IOBuf, std::default_delete<folly::IOBuf> >) at /usr/bin/hhvm:0
# 3  HPHP::FastCGITransaction::onStdOut(std::unique_ptr<folly::IOBuf, std::default_delete<folly::IOBuf> >) at /usr/bin/hhvm:0
# 4  std::_Function_handler<void (), HPHP::FastCGITransport::sendImpl(void const*, int, int, bool)::{lambda()#1}>::_M_invoke(std::_Any_data const&) at fastcgi-transport.cpp:0
# 5  folly::EventBase::runFunctionPtr(std::function<void ()>*) at /usr/bin/hhvm:0
# 6  folly::EventBase::FunctionRunner::messageAvailable(std::pair<void (*)(void*), void*>&&) at /usr/bin/hhvm:0
# 7  folly::NotificationQueue<std::pair<void (*)(void*), void*> >::Consumer::consumeMessages(bool) at /usr/bin/hhvm:0
# 8  event_base_loop at /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5:0
# 9  folly::EventBase::loopBody(int) at /usr/bin/hhvm:0
# 10 folly::EventBase::loopForever() at /usr/bin/hhvm:0
# 11 proxygen::WorkerThread::runLoop() at /usr/bin/hhvm:0
# 12 std::thread::_Impl<std::_Bind_simple<proxygen::WorkerThread::start()::{lambda()#1} ()> >::_M_run() at WorkerThread.cpp:0
# 13 std::this_thread::__sleep_for(std::chrono::duration<long, std::ratio<1l, 1l> >, std::chrono::duration<long, std::ratio<1l, 1000000000l> >) at /usr/lib/x86_64-linux-gnu/libstdc++.so.6:0
# 14 start_thread at /lib/x86_64-linux-gnu/libpthread.so.0:0
# 15 clone at /lib/x86_64-linux-gnu/libc.so.6:0

I also see a lot of warnings: "\nWarning: Could not start xdebug server. Check the remote debugging log for details", but looks like it only happens when phpstorm is not waiting for incoming connections.

Our team is really excited to use hhvm, but buggy debugger is a really big problem for us.

Hope this information helps, let me know if you need more information.

[jwatzman]

@roman-shuhov your issue looks identical to #4351, we can continue over there.

@euphio It sounds like you think HHVM is hanging, but not crashing? Can you attach gdb when this happens, and do thread apply all bt, and paste that here? That will tell us what each thread is trying to do during the hang.

[lbadger]

I am also having the same problem. Here is my stacktrace.

 ThreadID: 7fa04dfff700
 ThreadPID: 9297
 Name: unknown program
 Type: Segmentation fault
 Runtime: hhvm
 Version: tags/HHVM-3.5.1-0-gb723e67c88bc008676687a04dff00db1faf250b3
 DebuggerCount: 0


 # 0  folly::IOBuf::countChainElements() const at /usr/bin/hhvm:0
 # 1  folly::AsyncSocket::writeChain(folly::AsyncSocket::WriteCallback*, std::unique_ptr<folly::IOBuf, std::            default_delete<folly::IOBuf> >&&, folly::WriteFlags) at /usr/bin/hhvm:0
 # 2  HPHP::FastCGISession::writeStream(unsigned short, HPHP::FastCGISession::RecordType, std::unique_ptr<folly::       IOBuf, std::default_delete<folly::IOBuf> >) at /usr/bin/hhvm:0
 # 3  HPHP::FastCGITransaction::onStdOut(std::unique_ptr<folly::IOBuf, std::default_delete<folly::IOBuf> >) at /usr/    bin/hhvm:0
 # 4  std::_Function_handler<void (), HPHP::FastCGITransport::sendImpl(void const*, int, int, bool)::{lambda()#1}>::    _M_invoke(std::_Any_data const&) at fastcgi-transport.cpp:0
 # 5  folly::EventBase::runFunctionPtr(std::function<void ()>*) at /usr/bin/hhvm:0
 # 6  folly::EventBase::FunctionRunner::messageAvailable(std::pair<void (*)(void*), void*>&&) at /usr/bin/hhvm:0
 # 7  folly::NotificationQueue<std::pair<void (*)(void*), void*> >::Consumer::consumeMessages(bool) at /usr/bin/hhvm:0
 # 8  event_base_loop at /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5:0
 # 9  folly::EventBase::loopBody(int) at /usr/bin/hhvm:0
 # 10 folly::EventBase::loopForever() at /usr/bin/hhvm:0
 # 11 proxygen::WorkerThread::runLoop() at /usr/bin/hhvm:0
 # 12 std::thread::_Impl<std::_Bind_simple<proxygen::WorkerThread::start()::{lambda()#1} ()> >::_M_run() at             WorkerThread.cpp:0
 # 13 std::this_thread::__sleep_for(std::chrono::duration<long, std::ratio<1l, 1l> >, std::chrono::duration<long, std:: ratio<1l, 1000000000l> >) at /usr/lib/x86_64-linux-gnu/libstdc++.so.6:0
 # 14 start_thread at /build/buildd/eglibc-2.19/nptl/pthread_create.c:312
 # 15 clone at /build/buildd/eglibc-2.19/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113

[lucabrunox]

Problem

PHPStorm sends commands without waiting for a response. The bug is that HHVM only replies to one of those responses because the tcp read buffer is naive.

Workaround proof

Write a proxy that enforces PHPStorm to wait for the response from HHVM before sending a new request:

import socket
import thread

PROXY_PORT=10000

IDE_HOST="localhost"
IDE_PORT=9000

class XdebugReader:
  def __init__(self, s):
    self.s = s
    self.buf = ""

  def next(self):
    while self.buf.count('\0') < 2:
      self.buf += self.s.recv(4096)
    msg1, msg2, self.buf = self.buf.split('\0', 2)
    msg = msg1+'\0'+msg2+'\0'
    print "xdebug: "+msg
    return msg

class IdeReader:
  def __init__(self, s):
    self.s = s
    self.buf = ""

  def next(self):
    while self.buf.count('\0') < 1:
      self.buf += self.s.recv(4096)
    msg1, self.buf = self.buf.split('\0', 1)
    msg = msg1+'\0'
    print "ide: "+msg
    return msg

def proxy(ide, xdebug):
  xdebug_reader = XdebugReader(xdebug)
  ide_reader = IdeReader(ide)

  msg = xdebug_reader.next()
  ide.send(msg)

  while True:
    msg = ide_reader.next()
    xdebug.send(msg)

    msg = xdebug_reader.next()
    ide.send(msg)

def main():
  s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
  s.bind(('0.0.0.0', PROXY_PORT))
  s.listen(5)

  while True:
    (c, addr) = s.accept()

    p = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
    p.connect((IDE_HOST, IDE_PORT))

    thread.start_new_thread(proxy, (p, c))

main()

Let HHVM xdebug connect to this proxy, and the proxy to your IDE. It will work. Note: this is a workaround for a proof, not a complete workaround because some commands may not work (e.g. setting breakpoints while running the program).

Reproducing

Create a fake IDE server that accept connections directly from xdebug:

import socket
import thread
import time

def client(c):
  while True:
    buf = c.recv(4096)
    print "Got: ", buf

def inputloop(c):
  while True:
    #time.sleep(1)
    m = raw_input().strip()
    c.send("%s\x00" % m)

def main():
  s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
  s.bind(('0.0.0.0', 9000))
  s.listen(5)

  while True:
    (c, addr) = s.accept()
    thread.start_new_thread(client, (c, ))
    try:
      inputloop(c)
    except:
      time.sleep(10000000)

main()

Now create an xdebug.txt to simulate IDE commands like this:

feature_set -i 1 -n show_hidden -v 1
feature_set -i 2 -n max_depth -v 1
feature_set -i 3 -n max_children -v 100
status -i 4
step_into -i 5
breakpoint_set -i 6 -t line -f file:///var/www/public/index.php -n 32

Start the fake server with:

python xdebug.py < xdebug.txt

Now let HHVM connect to the fake server. Note that HHVM only replies to one of the responses:

Got: <response transaction_id="1" ...></response>

Uncomment the time.sleep(0.1) to give HHVM time to reply to each request, and you should see all the responses for all transactions.

Solution

Fix the read buffer of xdebug_server. Now it reads the input in a buffer, parses the first command, and discards the rest of the buffer. So the whole read buffering must be fixed.

Quick fix:

--- a/hphp/runtime/ext/xdebug/xdebug_server.cpp
+++ b/hphp/runtime/ext/xdebug/xdebug_server.cpp
@@ -850,7 +850,7 @@ bool XDebugServer::readInput() {
     }

     // Read into the buffer
-    auto const res = recv(m_socket, &m_buffer[bytes_read], bytes_left, 0);
+    auto const res = recv(m_socket, &m_buffer[bytes_read], 1, 0);
     if (res <= 0) {
       return false;
     }

[RoyHP]

@jwatzman I haven't tested this in the comment above, but it sounds like what is happening.

[jwatzman]

Thanks! Not sure when someone will get to this, but the info above looks super useful, really appreciate it.

[roman-shuhov]

Did anyone have a chance to finally fix this issue? I think a lot of developers are waiting for the ability to debug code with hhvm...

[lucabrunox]

@jwatzman given that the current state is half broken, what about applying that one-line quick fix until the read buffer is rewritten properly?

The only counter argument would be reading 1 byte at time from the socket which is in general slow, but talking about commands given by an IDE I wouldn't bother about this overhead.

[jwatzman]

@lethalman yeah, I think we'd probably take that patch -- can you send a PR?

[jwatzman]

I think I have a proper fix for this under review internally (D2170147).

[lbadger]

I just built 3.8.0-dev still seems to have issues. It connected once with PhpStorm 8.0.3 and seemed to work for a minute.

I checked the HHVM error log and I get

Unhandled server exception: \n

[jwatzman]

@lbadger can you file a new issue for that? The issue here of "HHVM hangs when using PHPStorm's XDebug support" has been fixed.