Add more server-side debugger logging, small tweaks to server-side error paths

Added some more logging on the server when debugging. Log warnings during shutdown (normal and from the signal handler) when there are debuggers attached. Minor tweaks to some of the error handling paths, with more log messages instead of silent failures. Also moved server-side closing of the thrift buffer to proxy destruction.

hphp/runtime/base/crash_reporter.cpp

@@ -21,6 +21,7 @@
 #include "runtime/base/program_functions.h"
 #include "runtime/base/execution_context.h"
 #include "runtime/ext/ext_error.h"
+#include "runtime/eval/debugger/debugger.h"
 
 namespace HPHP {
 
@@ -78,6 +79,10 @@ static void bt_handler(int sig) {
 
   Logger::Error("Core dumped: %s", strsignal(sig));
 
+  // Give the debugger a chance to do extra logging if there are any attached
+  // debugger clients.
+  Eval::Debugger::LogShutdown(Eval::Debugger::ShutdownKind::Abnormal);
+
   if (!g_context.isNull()) {
     // sync up gdb Dwarf info so that gdb can do a full backtrace
     // from the core file. Do this at the very end as syncing needs

hphp/runtime/eval/debugger/debugger.cpp

@@ -50,6 +50,7 @@ DebuggerProxyPtr Debugger::StartClient(const DebuggerClientOptions &options) {
 
 void Debugger::Stop() {
   TRACE(2, "Debugger::Stop\n");
+  LogShutdown(ShutdownKind::Normal);
   s_debugger.m_proxyMap.clear();
   DebuggerServer::Stop();
   if (s_clientStarted) {
@@ -149,6 +150,29 @@ void Debugger::DebuggerSession(const DebuggerClientOptions& options,
   }
 }
 
+void Debugger::LogShutdown(ShutdownKind shutdownKind) {
+  int proxyCount = s_debugger.countConnectedProxy();
+  if (proxyCount > 0) {
+    Logger::Warning(DEBUGGER_LOG_TAG "%s with connected debuggers!",
+                    shutdownKind == ShutdownKind::Normal ?
+                      "Normal shutdown" : "Unexpected crash",
+                    proxyCount);
+
+    for (const auto& proxyEntry: s_debugger.m_proxyMap) {
+      auto sid = proxyEntry.first;
+      auto proxy = proxyEntry.second;
+      auto dummySid = StringData::GetStaticString(proxy->getDummyInfo().id());
+      if (sid != dummySid) {
+        auto sandbox = proxy->getSandbox();
+        if (sandbox.valid()) {
+          Logger::Warning(DEBUGGER_LOG_TAG "Debugging %s\n",
+                          sandbox.desc().c_str());
+        }
+      }
+    }
+  }
+}
+
 ///////////////////////////////////////////////////////////////////////////////
 
 void Debugger::InterruptSessionStarted(const char *file,
@@ -552,6 +576,8 @@ void Debugger::updateProxySandbox(DebuggerProxyPtr proxy,
   }
 }
 
+///////////////////////////////////////////////////////////////////////////////
+
 DebuggerDummyEnv::DebuggerDummyEnv() {
   TRACE(2, "DebuggerDummyEnv::DebuggerDummyEnv\n");
   g_vmContext->enterDebuggerDummyEnv();
@@ -562,6 +588,8 @@ DebuggerDummyEnv::~DebuggerDummyEnv() {
   g_vmContext->exitDebuggerDummyEnv();
 }
 
+///////////////////////////////////////////////////////////////////////////////
+
 EvalBreakControl::EvalBreakControl(bool noBreak) {
   TRACE(2, "EvalBreakControl::EvalBreakControl\n");
   m_noBreakSave = g_vmContext->m_dbgNoBreak;

hphp/runtime/eval/debugger/debugger.h

@@ -24,6 +24,11 @@
 #include <tbb/concurrent_queue.h>
 
 namespace HPHP { namespace Eval {
+
+// Tag used on server log messages to highlight that they are likely useful to
+// show to users.
+#define DEBUGGER_LOG_TAG "[DBGINFO] "
+
 ///////////////////////////////////////////////////////////////////////////////
 // The Debugger generally manages proxies, sandboxes, and is the inital handler
 // of interrupts from the VM. It associates VM threads with sandboxes, and
@@ -32,23 +37,17 @@ namespace HPHP { namespace Eval {
 
 class Debugger {
 public:
-  /**
-   * Start/stop Debugger for remote debugging.
-   */
+  // Start/stop Debugger for remote debugging.
   static bool StartServer();
   static DebuggerProxyPtr StartClient(const DebuggerClientOptions &options);
   static void Stop();
 
-  /**
-   * Add a new sandbox a debugger can connect to.
-   */
+  // Add a new sandbox a debugger can connect to.
   static void RegisterSandbox(const DSandboxInfo &sandbox);
   static void UnregisterSandbox(CStrRef id);
   static void RegisterThread();
 
-  /**
-   * Add/remove/change DebuggerProxy.
-   */
+  //  Add/remove/change DebuggerProxy.
   static DebuggerProxyPtr CreateProxy(SmartPtr<Socket> socket, bool local);
   static void RemoveProxy(DebuggerProxyPtr proxy);
   static bool SwitchSandbox(DebuggerProxyPtr proxy, const std::string &newId,
@@ -69,9 +68,7 @@ public:
   static void DebuggerSession(const DebuggerClientOptions& options,
                               const std::string& file, bool restart);
 
-  /**
-   * Called from differnt time point of execution thread.
-   */
+  // Called from differnt time point of execution thread.
   static void InterruptSessionStarted(const char *file,
                                       const char *error = nullptr);
   static void InterruptSessionEnded(const char *file);
@@ -79,24 +76,26 @@ public:
   static void InterruptRequestEnded(const char *url);
   static void InterruptPSPEnded(const char *url);
 
-  /**
-   * Called when a user handler fails to handle an exception.
-   */
+  // Called when a user handler fails to handle an exception.
   static bool InterruptException(CVarRef e);
 
-  /**
-   * Interrupt from VM
-   */
+  // Interrupt from VM
   static void InterruptVMHook(int type = BreakPointReached,
                               CVarRef e = null_variant);
 
-  /**
-   * Surround text with color, if set.
-   */
+  // Surround text with color, if set.
   static void SetTextColors();
   static String ColorStdout(CStrRef s);
   static String ColorStderr(CStrRef s);
 
+  // Log debugging state when we're shutting the server down.
+  enum ShutdownKind {
+    Normal,
+    Abnormal
+  };
+
+  static void LogShutdown(ShutdownKind shutdownKind);
+
 private:
   static Debugger s_debugger;
   static bool s_clientStarted;

hphp/runtime/eval/debugger/debugger_command.cpp

@@ -33,8 +33,7 @@ bool DebuggerCommand::send(DebuggerThriftBuffer &thrift) {
     sendImpl(thrift);
     thrift.flush();
   } catch (...) {
-    Logger::Verbose("DebuggerCommand::send(): a socket error has happened");
-    thrift.close();
+    Logger::Error("DebuggerCommand::send(): a socket error has happened");
     return false;
   }
   return true;
@@ -45,8 +44,7 @@ bool DebuggerCommand::recv(DebuggerThriftBuffer &thrift) {
   try {
     recvImpl(thrift);
   } catch (...) {
-    Logger::Verbose("DebuggerCommand::recv(): a socket error has happened");
-    thrift.close();
+    Logger::Error("DebuggerCommand::recv(): a socket error has happened");
     return false;
   }
   return true;
@@ -89,7 +87,7 @@ bool DebuggerCommand::Receive(DebuggerThriftBuffer &thrift,
     thrift.read(type);
     thrift.read(clsname);
   } catch (...) {
-    Logger::Verbose("%s => DebuggerCommand::Receive(): socket error", caller);
+    Logger::Error("%s => DebuggerCommand::Receive(): socket error", caller);
     return true;
   }
 
@@ -139,7 +137,7 @@ bool DebuggerCommand::Receive(DebuggerThriftBuffer &thrift,
       return true;
   }
   if (!cmd->recv(thrift)) {
-    Logger::Verbose("%s => DebuggerCommand::Receive(): socket error", caller);
+    Logger::Error("%s => DebuggerCommand::Receive(): socket error", caller);
     cmd.reset();
   }
   return true;

hphp/runtime/eval/debugger/debugger_command.h

@@ -97,9 +97,15 @@ public:
 
   virtual void list(DebuggerClient *client);
   virtual bool help(DebuggerClient *client);
+
+  // Client-side work for a command. Returning false indicates a failure to
+  // communicate with the server (for commands that do so).
   virtual bool onClient(DebuggerClient *client);
   bool onClientD(DebuggerClient *client);
   virtual void setClientOutput(DebuggerClient *client);
+
+  // Server-side work for a command. Returning false indicates a failure to
+  // communicate with the client (for commands that do so).
   virtual bool onServer(DebuggerProxy *proxy);
   virtual void sendImpl(DebuggerThriftBuffer &thrift);
   virtual void recvImpl(DebuggerThriftBuffer &thrift);

hphp/runtime/eval/debugger/debugger_proxy.cpp

@@ -277,7 +277,7 @@ void DebuggerProxy::interrupt(CmdInterrupt &cmd) {
   if (checkFlowBreak(cmd)) {
     while (true) {
       try {
-        Lock lock(m_signalMutex);
+        Lock lock(m_signalMutex); // Block the signal polling thread.
         m_signum = CmdSignal::SignalNone;
         processInterrupt(cmd);
       } catch (const DebuggerException &e) {
@@ -342,18 +342,32 @@ void DebuggerProxy::pollSignal() {
       }
     }
 
+    // Block any threads that might be interrupting from communicating with the
+    // client until we're done with this poll.
     Lock lock(m_signalMutex);
 
     // Send CmdSignal over to the client and wait for a response.
     CmdSignal cmd;
-    if (!cmd.onServer(this)) break; // on socket error
+    if (!cmd.onServer(this)) {
+      Logger::Error("Failed to send CmdSignal to client, socket error");
+      break;
+    }
 
+    // We will loop forever until DebuggerClient sends us something, modulo
+    // transport failure or a shutdown request.
     DebuggerCommandPtr res;
     while (!DebuggerCommand::Receive(m_thrift, res,
                                      "DebuggerProxy::pollSignal()")) {
-      // We will wait forever until DebuggerClient sends us something.
+      if (m_stopped) {
+        Logger::Warning("DebuggerProxy signal thread asked to stop while "
+                        "waiting for CmdSignal back from the client");
+        break;
+      }
+    }
+    if (!res) {
+      Logger::Error("Failed to get CmdSignal back from client, socket error");
+      break;
     }
-    if (!res) break;
 
     CmdSignalPtr sig = dynamic_pointer_cast<CmdSignal>(res);
     if (!sig) {
@@ -364,9 +378,15 @@ void DebuggerProxy::pollSignal() {
     m_signum = sig->getSignal();
 
     if (m_signum != CmdSignal::SignalNone) {
+      TRACE(2, "DebuggerProxy::pollSignal got interrupt signal from client\n");
       Debugger::RequestInterrupt(shared_from_this());
     }
   }
+  if (!m_stopped) {
+    Logger::Error("DebuggerProxy signal thread has lost communication with the "
+                  "client, stopping proxy.");
+    forceQuit();
+  }
 }
 
 void DebuggerProxy::forceQuit() {
@@ -540,7 +560,6 @@ void DebuggerProxy::checkStop() {
   TRACE(5, "DebuggerProxy::checkStop\n");
   if (m_stopped) {
     Debugger::RemoveProxy(shared_from_this());
-    m_thrift.close();
     throw DebuggerClientExitException();
   }
 }
@@ -549,6 +568,7 @@ void DebuggerProxy::processInterrupt(CmdInterrupt &cmd) {
   TRACE(2, "DebuggerProxy::processInterrupt\n");
   // Do the server-side work for this interrupt, which just notifies the client.
   if (!cmd.onServer(this)) {
+    Logger::Error("Failed to send CmdInterrupt to client, socket error");
     Debugger::RemoveProxy(shared_from_this()); // on socket error
     return;
   }
@@ -584,17 +604,27 @@ void DebuggerProxy::processInterrupt(CmdInterrupt &cmd) {
         throw DebuggerClientExitException();
       }
     }
+    bool cmdFailure = false;
     try {
       // Perform the server-side work for this command.
-      if (!res || !res->onServer(this)) {
-        Debugger::RemoveProxy(shared_from_this());
-        return;
+      if (res) {
+        if (!res->onServer(this)) {
+          Logger::Error("Failed to execute cmd %d from client, socket error",
+                        res->getType());
+          cmdFailure = true;
+        }
+      } else {
+        Logger::Error("Failed to receive cmd from client, socket error");
+        cmdFailure = true;
       }
     } catch (const DebuggerException &e) {
       throw;
     } catch (...) {
-      Logger::Error("onServer() throws non DebuggerException: %d",
+      Logger::Error("Cmd type %d onServer() threw non DebuggerException",
                     res->getType());
+      cmdFailure = true;
+    }
+    if (cmdFailure) {
       Debugger::RemoveProxy(shared_from_this());
       return;
     }