diff --git a/hphp/runtime/base/runtime_option.cpp b/hphp/runtime/base/runtime_option.cpp index eac48c593..cc932b095 100644 --- a/hphp/runtime/base/runtime_option.cpp +++ b/hphp/runtime/base/runtime_option.cpp @@ -435,6 +435,7 @@ std::string RuntimeOption::SandboxLogsRoot; bool RuntimeOption::EnableDebugger = false; bool RuntimeOption::EnableDebuggerServer = false; +bool RuntimeOption::EnableDebuggerUsageLog = false; int RuntimeOption::DebuggerServerPort = 8089; int RuntimeOption::DebuggerDefaultRpcPort = 8083; std::string RuntimeOption::DebuggerDefaultRpcAuth; @@ -442,7 +443,6 @@ std::string RuntimeOption::DebuggerRpcHostDomain; int RuntimeOption::DebuggerDefaultRpcTimeout = 30; std::string RuntimeOption::DebuggerDefaultSandboxPath; std::string RuntimeOption::DebuggerStartupDocument; -std::string RuntimeOption::DebuggerUsageLogFile; std::string RuntimeOption::SendmailPath; std::string RuntimeOption::MailForceExtraParameters; @@ -1172,10 +1172,10 @@ void RuntimeOption::Load(Hdf &config, StringVec *overwrites /* = NULL */, Hdf debugger = eval["Debugger"]; EnableDebugger = debugger["EnableDebugger"].getBool(); EnableDebuggerServer = debugger["EnableDebuggerServer"].getBool(); + EnableDebuggerUsageLog = debugger["EnableDebuggerUsageLog"].getBool(); DebuggerServerPort = debugger["Port"].getUInt16(8089); DebuggerDefaultSandboxPath = debugger["DefaultSandboxPath"].getString(); DebuggerStartupDocument = debugger["StartupDocument"].getString(); - DebuggerUsageLogFile = debugger["UsageLogFile"].getString(); DebuggerDefaultRpcPort = debugger["RPC.DefaultPort"].getUInt16(8083); DebuggerDefaultRpcAuth = debugger["RPC.DefaultAuth"].getString(); diff --git a/hphp/runtime/base/runtime_option.h b/hphp/runtime/base/runtime_option.h index 423d85bd3..0a4e68f02 100644 --- a/hphp/runtime/base/runtime_option.h +++ b/hphp/runtime/base/runtime_option.h @@ -487,6 +487,7 @@ public: // Debugger options static bool EnableDebugger; static bool EnableDebuggerServer; + static bool EnableDebuggerUsageLog; static int DebuggerServerPort; static int DebuggerDefaultRpcPort; static std::string DebuggerDefaultRpcAuth; @@ -494,7 +495,6 @@ public: static int DebuggerDefaultRpcTimeout; static std::string DebuggerDefaultSandboxPath; static std::string DebuggerStartupDocument; - static std::string DebuggerUsageLogFile; // Mail options static std::string SendmailPath; diff --git a/hphp/runtime/eval/debugger/debugger.cpp b/hphp/runtime/eval/debugger/debugger.cpp index af7e80b84..9d32141b4 100644 --- a/hphp/runtime/eval/debugger/debugger.cpp +++ b/hphp/runtime/eval/debugger/debugger.cpp @@ -586,6 +586,45 @@ void Debugger::updateProxySandbox(DebuggerProxyPtr proxy, } } +/////////////////////////////////////////////////////////////////////////////// +// Helpers for usage logging + +// NB: the usage logger is not owned by the Debugger. The caller will call this +// again with nullptr before destroying the given usage logger. +void Debugger::SetUsageLogger(DebuggerUsageLogger *usageLogger) { + TRACE(1, "Debugger::SetUsageLogger\n"); + s_debugger.m_usageLogger = usageLogger; +} + +void Debugger::InitUsageLogging() { + TRACE(1, "Debugger::InitUsageLogging\n"); + if (s_debugger.m_usageLogger) s_debugger.m_usageLogger->init(); +} + +void Debugger::UsageLog(const std::string &mode, const std::string &cmd, + const std::string &data) { + if (s_debugger.m_usageLogger) s_debugger.m_usageLogger->log(mode, cmd, data); +} + +const char *Debugger::InterruptTypeName(CmdInterrupt &cmd) { + switch (cmd.getInterruptType()) { + case SessionStarted: return "SessionStarted"; + case SessionEnded: return "SessionEnded"; + case RequestStarted: return "RequestStarted"; + case RequestEnded: return "RequestEnded"; + case PSPEnded: return "PSPEnded"; + case HardBreakPoint: return "HardBreakPoint"; + case BreakPointReached: return "BreakPointReached"; + case ExceptionThrown: return "ExceptionThrown"; + default: + return "unknown"; + } +} + +void Debugger::UsageLogInterrupt(const std::string &mode, CmdInterrupt &cmd) { + UsageLog(mode, "interrupt", InterruptTypeName(cmd)); +} + /////////////////////////////////////////////////////////////////////////////// DebuggerDummyEnv::DebuggerDummyEnv() { diff --git a/hphp/runtime/eval/debugger/debugger.h b/hphp/runtime/eval/debugger/debugger.h index 13e10e157..7e950ea54 100644 --- a/hphp/runtime/eval/debugger/debugger.h +++ b/hphp/runtime/eval/debugger/debugger.h @@ -35,8 +35,12 @@ namespace HPHP { namespace Eval { // sandboxes with proxies. Interrupts get minimal handling before being handed // off to the proper proxy. +DECLARE_BOOST_TYPES(CmdInterrupt); + class Debugger { public: + Debugger() : m_usageLogger(nullptr) {} + // Start/stop Debugger for remote debugging. static bool StartServer(); static DebuggerProxyPtr StartClient(const DebuggerClientOptions &options); @@ -96,6 +100,13 @@ public: static void LogShutdown(ShutdownKind shutdownKind); + // Usage logging + static void SetUsageLogger(DebuggerUsageLogger *usageLogger); + static void InitUsageLogging(); + static void UsageLog(const std::string &mode, const std::string &cmd, + const std::string &data = ""); + static void UsageLogInterrupt(const std::string &mode, CmdInterrupt &cmd); + private: static Debugger s_debugger; static bool s_clientStarted; @@ -104,6 +115,8 @@ private: InterruptSite *site = nullptr, const char *error = nullptr); static void InterruptWithUrl(int type, const char *url); + static const char *InterruptTypeName(CmdInterrupt &cmd); + typedef tbb::concurrent_hash_map ProxyMap; ProxyMap m_proxyMap; @@ -151,6 +164,10 @@ private: bool force); void retireDummySandboxThread(DummySandbox* toRetire); void cleanupDummySandboxThreads(); + + // A usage logger which is set by a provider to an implementation-specific + // subclass if usage logging is enabled. + DebuggerUsageLogger *m_usageLogger; }; class DebuggerDummyEnv { diff --git a/hphp/runtime/eval/debugger/debugger_base.h b/hphp/runtime/eval/debugger/debugger_base.h index 7a8dffbda..23e214f54 100644 --- a/hphp/runtime/eval/debugger/debugger_base.h +++ b/hphp/runtime/eval/debugger/debugger_base.h @@ -60,7 +60,7 @@ class DebuggerClientExitException : public DebuggerException { }; class DebuggerRestartException : public DebuggerException { public: - DebuggerRestartException(StringVecPtr args) : m_args(args) {} + explicit DebuggerRestartException(StringVecPtr args) : m_args(args) {} ~DebuggerRestartException() throw() {} virtual const char *what() const throw() { @@ -127,7 +127,7 @@ DECLARE_BOOST_TYPES(DSandboxInfo); class DSandboxInfo { public: DSandboxInfo() {} - DSandboxInfo(const std::string &id) { set(id);} + explicit DSandboxInfo(const std::string &id) { set(id);} std::string m_user; std::string m_name; @@ -197,6 +197,18 @@ public: void save(Hdf node); }; +/////////////////////////////////////////////////////////////////////////////// +// Simple base class which can be overridden to provide implementation-specific +// usage logging for the debugger from both client- and server-side. + +class DebuggerUsageLogger { +public: + virtual ~DebuggerUsageLogger() {} + virtual void init() {} + virtual void log(const std::string &mode, const std::string &cmd, + const std::string &data) {} +}; + /////////////////////////////////////////////////////////////////////////////// }} diff --git a/hphp/runtime/eval/debugger/debugger_client.cpp b/hphp/runtime/eval/debugger/debugger_client.cpp index 592529122..5abc68cfa 100644 --- a/hphp/runtime/eval/debugger/debugger_client.cpp +++ b/hphp/runtime/eval/debugger/debugger_client.cpp @@ -103,7 +103,7 @@ void DebuggerClient::onSignal(int sig) { "press Ctrl-C again to quit.", secWait); } else { info("Pausing program execution, please wait..."); - usageLogSignal(); + usageLog("signal"); m_sigTime = now; } m_signum = CmdSignal::SignalBreak; @@ -409,9 +409,9 @@ DebuggerClient::DebuggerClient(std::string name /* = "" */) m_acLen(0), m_acIndex(0), m_acPos(0), m_acLiveListsDirty(true), m_threadId(0), m_listLine(0), m_listLineFocus(0), m_frame(0), m_clientState(StateUninit), m_inApiUse(false), - m_nameForApi(name), m_usageLogFP(nullptr) { + m_nameForApi(name) { TRACE(2, "DebuggerClient::DebuggerClient\n"); - initUsageLogging(); + Debugger::InitUsageLogging(); } DebuggerClient::~DebuggerClient() { @@ -423,7 +423,6 @@ DebuggerClient::~DebuggerClient() { fclose(f); setLogFileHandler(nullptr); } - finiUsageLogging(); } void DebuggerClient::reset() { @@ -618,7 +617,7 @@ void DebuggerClient::init(const DebuggerClientOptions &options) { m_options.user = Process::GetCurrentUser(); } - usageLogInit(); + usageLog("init"); loadConfig(); @@ -1000,12 +999,14 @@ DebuggerCommandPtr DebuggerClient::waitForNextInterrupt() { expected); return DebuggerCommandPtr(); } + } else { + CmdInterruptPtr intr = dynamic_pointer_cast(cmd); + Debugger::UsageLogInterrupt(getUsageMode(), *intr.get()); } m_sigTime = 0; m_machine->m_interrupting = true; setClientState(StateReadyForCommand); m_inputState = TakingCommand; - usageLogInterrupt(cmd); return cmd; } } @@ -1033,7 +1034,8 @@ void DebuggerClient::runImpl() { return; } m_sigTime = 0; - usageLogInterrupt(cmd); + CmdInterruptPtr intr = dynamic_pointer_cast(cmd); + Debugger::UsageLogInterrupt(getUsageMode(), *intr.get()); { cmd->onClient(*this); } @@ -1829,7 +1831,7 @@ DebuggerCommandPtr DebuggerClient::recvFromServer(int expected) { error("wire error: %s", res->getWireError().data()); } if (res->is((DebuggerCommand::Type)expected)) { - usageLogDone(boost::lexical_cast(expected)); + usageLog("done", boost::lexical_cast(expected)); break; } @@ -1838,7 +1840,8 @@ DebuggerCommandPtr DebuggerClient::recvFromServer(int expected) { throw DebuggerProtocolException(); } - usageLogInterrupt(res); + CmdInterruptPtr intr = dynamic_pointer_cast(res); + Debugger::UsageLogInterrupt(getUsageMode(), *intr.get()); if (isApiMode()) { // Hit breakpoint during eval @@ -2257,78 +2260,14 @@ void DebuggerClient::resetSmartAllocatedMembers() { /////////////////////////////////////////////////////////////////////////////// // helpers for usage logging -void DebuggerClient::initUsageLogging() { - TRACE(2, "DebuggerClient::initUsageLogging\n"); - // Usage log file is a runtime option instead of debugger config because - // it is for internal monitoring and we don't want users to modify this. - if (RuntimeOption::DebuggerUsageLogFile.empty()) { - return; - } - mode_t old = umask(0); - m_usageLogFP = fopen(RuntimeOption::DebuggerUsageLogFile.c_str(), "a"); - if (!m_usageLogFP) { - Logger::Error("failed to open debugger usage log file %s", - RuntimeOption::DebuggerUsageLogFile.c_str()); - } - umask(old); +const char *DebuggerClient::getUsageMode() { + return isApiMode() ? "api" : "terminal"; } -void DebuggerClient::finiUsageLogging() { - TRACE(2, "DebuggerClient::finiUsageLogging\n"); - if (m_usageLogFP) { - fclose(m_usageLogFP); - m_usageLogFP = nullptr; - } +void DebuggerClient::usageLog(const std::string &cmd, const std::string &data) { + Debugger::UsageLog(getUsageMode(), cmd, data); } -void DebuggerClient::usageLog(const std::string& cmd, const std::string& line) { - TRACE(2, "DebuggerClient::usageLog\n"); - if (!m_usageLogFP) { - return; - } - - if (m_usageLogHeader.empty()) { - std::string login = m_options.user; - std::string host = Process::GetHostName(); - std::string clientMode = isApiMode() ? "api" : "terminal"; - m_usageLogHeader = login + " " + host + " hhvm " + clientMode; - } - - struct timespec tp; - gettime(CLOCK_REALTIME, &tp); - -#define MAX_LINE 1024 - char buf[MAX_LINE]; - int len = snprintf(buf, MAX_LINE, "%s %" PRId64 " %" PRId64 " %s #### %s", - m_usageLogHeader.c_str(), - (int64_t)tp.tv_sec, (int64_t)tp.tv_nsec, - cmd.c_str(), line.c_str()); - len = len >= MAX_LINE ? MAX_LINE - 1: len; - buf[len] = '\n'; -#undef MAX_LINE - fwrite(buf, len + 1, 1, m_usageLogFP); - fflush(m_usageLogFP); -} - -void DebuggerClient::usageLogInterrupt(DebuggerCommandPtr cmd) { - TRACE(2, "DebuggerClient::usageLogInterrupt\n"); - CmdInterruptPtr intr = dynamic_pointer_cast(cmd); - if (!intr) { - return; - } - switch (intr->getInterruptType()) { - case SessionStarted: usageLog("interrupt", "SessionStarted"); break; - case SessionEnded: usageLog("interrupt", "SessionEnded"); break; - case RequestStarted: usageLog("interrupt", "RequestStarted"); break; - case RequestEnded: usageLog("interrupt", "RequestEnded"); break; - case PSPEnded: usageLog("interrupt", "PSPEnded"); break; - case HardBreakPoint: usageLog("interrupt", "HardBreakPoint"); break; - case BreakPointReached: usageLog("interrupt", "BreakPointReached"); break; - case ExceptionThrown: usageLog("interrupt", "ExceptionThrown"); break; - default: - usageLog("interrupt", "unknown"); - } -} /////////////////////////////////////////////////////////////////////////////// // configuration diff --git a/hphp/runtime/eval/debugger/debugger_client.h b/hphp/runtime/eval/debugger/debugger_client.h index 4357d5b80..7631a0a71 100644 --- a/hphp/runtime/eval/debugger/debugger_client.h +++ b/hphp/runtime/eval/debugger/debugger_client.h @@ -30,9 +30,11 @@ namespace HPHP { class StringBuffer; namespace Eval { + /////////////////////////////////////////////////////////////////////////////// DECLARE_BOOST_TYPES(DebuggerCommand); +DECLARE_BOOST_TYPES(CmdInterrupt); class DebuggerClient { public: static int LineWidth; @@ -483,15 +485,8 @@ private: std::string m_nameForApi; // usage logging - FILE* m_usageLogFP; - std::string m_usageLogHeader; - void initUsageLogging(); - void finiUsageLogging(); - void usageLog(const std::string& cmd, const std::string& line); - void usageLogInit() { usageLog("init", ""); } - void usageLogSignal() { usageLog("signal", ""); } - void usageLogDone(const std::string& cmdType) { usageLog("done", cmdType); } - void usageLogInterrupt(DebuggerCommandPtr cmd); + const char *getUsageMode(); + void usageLog(const std::string &cmd, const std::string &data = ""); }; /////////////////////////////////////////////////////////////////////////////// diff --git a/hphp/runtime/eval/debugger/debugger_proxy.cpp b/hphp/runtime/eval/debugger/debugger_proxy.cpp index df7c15fd7..e76365864 100644 --- a/hphp/runtime/eval/debugger/debugger_proxy.cpp +++ b/hphp/runtime/eval/debugger/debugger_proxy.cpp @@ -37,6 +37,7 @@ DebuggerProxy::DebuggerProxy(SmartPtr socket, bool local) TRACE(2, "DebuggerProxy::DebuggerProxy\n"); m_thrift.create(socket); m_dummyInfo = DSandboxInfo::CreateDummyInfo((int64_t)this); + Debugger::UsageLog("server", "connnect", socket->getAddress()); } DebuggerProxy::~DebuggerProxy() { @@ -49,6 +50,8 @@ DebuggerProxy::~DebuggerProxy() { } delete m_injTables; + + Debugger::UsageLog("server", "disconnect"); TRACE_RB(2, "DebuggerProxy::~DebuggerProxy complete\n"); } @@ -590,6 +593,8 @@ void DebuggerProxy::processInterrupt(CmdInterrupt &cmd) { return; } + Debugger::UsageLogInterrupt("server", cmd); + // Wait for commands from the debugger client and process them. We'll stay // here until we get a command that should cause the thread to continue. while (true) { @@ -602,6 +607,7 @@ void DebuggerProxy::processInterrupt(CmdInterrupt &cmd) { checkStop(); if (res) { TRACE_RB(2, "Proxy got cmd type %d\n", res->getType()); + Debugger::UsageLog("server", boost::lexical_cast(res->getType())); // Any control flow command gets installed here and we continue execution. m_flow = dynamic_pointer_cast(res); if (m_flow) { diff --git a/hphp/runtime/eval/debugger/debugger_server.cpp b/hphp/runtime/eval/debugger/debugger_server.cpp index fba6eac61..1873e4150 100644 --- a/hphp/runtime/eval/debugger/debugger_server.cpp +++ b/hphp/runtime/eval/debugger/debugger_server.cpp @@ -110,6 +110,8 @@ void DebuggerServer::stop() { void DebuggerServer::accept() { TRACE(2, "DebuggerServer::accept\n"); + // Setup server-side usage logging before accepting any connections. + Debugger::InitUsageLogging(); // server loop while (!m_stopped) { struct pollfd fds[1];