Add client- and server-side logging to the debugger

Log details about debugger usage from both client and server side. Added a new runtime option to control whether the logging is used or not. There's a base class for a usage logger defined and used under runtime/eval/debugger.

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();

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;

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() {

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<const StringData*, DebuggerProxyPtr,
                                    StringDataHashCompare> 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 {

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) {}
+};
+
 ///////////////////////////////////////////////////////////////////////////////
 }}
 

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<CmdInterrupt>(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<CmdInterrupt>(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<string>(expected));
+      usageLog("done", boost::lexical_cast<string>(expected));
       break;
     }
 
@@ -1838,7 +1840,8 @@ DebuggerCommandPtr DebuggerClient::recvFromServer(int expected) {
       throw DebuggerProtocolException();
     }
 
-    usageLogInterrupt(res);
+    CmdInterruptPtr intr = dynamic_pointer_cast<CmdInterrupt>(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<CmdInterrupt>(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

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 = "");
 };
 
 ///////////////////////////////////////////////////////////////////////////////

hphp/runtime/eval/debugger/debugger_proxy.cpp

@@ -37,6 +37,7 @@ DebuggerProxy::DebuggerProxy(SmartPtr<Socket> 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<string>(res->getType()));
       // Any control flow command gets installed here and we continue execution.
       m_flow = dynamic_pointer_cast<CmdFlowControl>(res);
       if (m_flow) {

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];