From e967eb197f03a4d424e3f0d2232015a68264b70a Mon Sep 17 00:00:00 2001 From: Mike Magruder Date: Wed, 8 May 2013 15:06:40 -0700 Subject: [PATCH] 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 | 5 ++ hphp/runtime/eval/debugger/debugger.cpp | 28 +++++++++++ hphp/runtime/eval/debugger/debugger.h | 41 ++++++++-------- .../eval/debugger/debugger_command.cpp | 10 ++-- hphp/runtime/eval/debugger/debugger_command.h | 6 +++ hphp/runtime/eval/debugger/debugger_proxy.cpp | 48 +++++++++++++++---- 6 files changed, 102 insertions(+), 36 deletions(-) diff --git a/hphp/runtime/base/crash_reporter.cpp b/hphp/runtime/base/crash_reporter.cpp index a393d5dd0..13d53261d 100644 --- a/hphp/runtime/base/crash_reporter.cpp +++ b/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 diff --git a/hphp/runtime/eval/debugger/debugger.cpp b/hphp/runtime/eval/debugger/debugger.cpp index 4bbdb95cf..671b0c7c3 100644 --- a/hphp/runtime/eval/debugger/debugger.cpp +++ b/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; diff --git a/hphp/runtime/eval/debugger/debugger.h b/hphp/runtime/eval/debugger/debugger.h index e96bf3924..777830ef4 100644 --- a/hphp/runtime/eval/debugger/debugger.h +++ b/hphp/runtime/eval/debugger/debugger.h @@ -24,6 +24,11 @@ #include 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, 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; diff --git a/hphp/runtime/eval/debugger/debugger_command.cpp b/hphp/runtime/eval/debugger/debugger_command.cpp index a3548779a..9a509208a 100644 --- a/hphp/runtime/eval/debugger/debugger_command.cpp +++ b/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; diff --git a/hphp/runtime/eval/debugger/debugger_command.h b/hphp/runtime/eval/debugger/debugger_command.h index 1b5331df9..07152fe65 100644 --- a/hphp/runtime/eval/debugger/debugger_command.h +++ b/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); diff --git a/hphp/runtime/eval/debugger/debugger_proxy.cpp b/hphp/runtime/eval/debugger/debugger_proxy.cpp index 02e631d5c..0b2b7f1a6 100644 --- a/hphp/runtime/eval/debugger/debugger_proxy.cpp +++ b/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(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; }