I can haz moar usage logging?

Add a bit more usage logging for the debugger, and ensure that there is a common field between clients and servers thats easy to search on, i.e., sandbox id.

hphp/runtime/debugger/cmd/cmd_extended.cpp

@@ -160,6 +160,7 @@ bool CmdExtended::invokeHelp(DebuggerClient &client, const std::string &cls) {
 }
 
 bool CmdExtended::invokeClient(DebuggerClient &client, const std::string &cls){
+  client.usageLogCommand("extended", cls);
   DebuggerCommandPtr cmd = CreateExtendedCommand(cls);
   if (cmd) {
     cmd->onClient(client);

hphp/runtime/debugger/cmd/cmd_extended.h

@@ -39,13 +39,13 @@ public:
 
   virtual bool onServer(DebuggerProxy &proxy);
 
+protected:
   // so CmdUser can override these functions
   virtual const ExtendedCommandMap &getCommandMap();
   virtual void invokeList(DebuggerClient &client, const std::string &cls);
   virtual bool invokeHelp(DebuggerClient &client, const std::string &cls);
   virtual bool invokeClient(DebuggerClient &client, const std::string &cls);
 
-protected:
   virtual void onClientImpl(DebuggerClient &client);
   void helpImpl(DebuggerClient &client, const char *name);
 

hphp/runtime/debugger/cmd/cmd_machine.cpp

@@ -169,6 +169,7 @@ bool CmdMachine::AttachSandbox(DebuggerClient &client,
                sandbox->desc().c_str());
   CmdMachinePtr cmdMachine = client.xend<CmdMachine>(&cmd);
   if (cmdMachine->m_succeed) {
+    client.setSandbox(sandbox);
     client.playMacro("startup");
   } else {
     // Note: it would be nice to give them more info about the process we think

hphp/runtime/debugger/cmd/cmd_user.cpp

@@ -96,6 +96,7 @@ bool CmdUser::invokeHelp(DebuggerClient &client, const std::string &cls) {
 }
 
 bool CmdUser::invokeClient(DebuggerClient &client, const std::string &cls) {
+  client.usageLogCommand("user", cls);
   p_DebuggerClientCmdUser pclient(NEWOBJ(c_DebuggerClientCmdUser)());
   pclient->m_client = &client;
   try {

hphp/runtime/debugger/debugger.cpp

@@ -597,9 +597,10 @@ void Debugger::InitUsageLogging() {
   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);
+void Debugger::UsageLog(const std::string &mode, const std::string &sandboxId,
+                        const std::string &cmd, const std::string &data) {
+  if (s_debugger.m_usageLogger) s_debugger.m_usageLogger->log(mode, sandboxId,
+                                                              cmd, data);
 }
 
 const char *Debugger::InterruptTypeName(CmdInterrupt &cmd) {
@@ -618,8 +619,10 @@ const char *Debugger::InterruptTypeName(CmdInterrupt &cmd) {
   }
 }
 
-void Debugger::UsageLogInterrupt(const std::string &mode, CmdInterrupt &cmd) {
-  UsageLog(mode, "interrupt", InterruptTypeName(cmd));
+void Debugger::UsageLogInterrupt(const std::string &mode,
+                                 const std::string &sandboxId,
+                                 CmdInterrupt &cmd) {
+  UsageLog(mode, sandboxId, "interrupt", InterruptTypeName(cmd));
 }
 
 ///////////////////////////////////////////////////////////////////////////////

hphp/runtime/debugger/debugger.h

@@ -100,9 +100,13 @@ public:
   // Usage logging
   static void SetUsageLogger(DebuggerUsageLogger *usageLogger);
   static void InitUsageLogging();
-  static void UsageLog(const std::string &mode, const std::string &cmd,
+  static void UsageLog(const std::string &mode,
+                       const std::string &sandboxId,
+                       const std::string &cmd,
                        const std::string &data = "");
-  static void UsageLogInterrupt(const std::string &mode, CmdInterrupt &cmd);
+  static void UsageLogInterrupt(const std::string &mode,
+                                const std::string &sandboxId,
+                                CmdInterrupt &cmd);
 
 private:
   static Debugger s_debugger;

hphp/runtime/debugger/debugger_base.h

@@ -128,6 +128,7 @@ extern const char *PHP_KEYWORDS[];
 
 ///////////////////////////////////////////////////////////////////////////////
 
+DECLARE_BOOST_TYPES(DSandboxInfo);
 DECLARE_BOOST_TYPES(DMachineInfo);
 class DMachineInfo {
 public:
@@ -141,6 +142,7 @@ public:
 
   bool m_interrupting; // True if the machine is paused at an interrupt
   bool m_sandboxAttached;
+  DSandboxInfoPtr m_sandbox;
   bool m_initialized; // True if the initial connection protocol is complete
   std::string m_rpcHost;
   int m_rpcPort;
@@ -148,7 +150,6 @@ public:
 
 ///////////////////////////////////////////////////////////////////////////////
 
-DECLARE_BOOST_TYPES(DSandboxInfo);
 class DSandboxInfo {
 public:
   DSandboxInfo() {}
@@ -230,8 +231,8 @@ class DebuggerUsageLogger {
 public:
   virtual ~DebuggerUsageLogger() {}
   virtual void init() {}
-  virtual void log(const std::string &mode, const std::string &cmd,
-                   const std::string &data) {}
+  virtual void log(const std::string &mode, const std::string &sandboxId,
+                   const std::string &cmd, const std::string &data) {}
 };
 
 ///////////////////////////////////////////////////////////////////////////////

hphp/runtime/debugger/debugger_client.cpp

@@ -95,16 +95,18 @@ void DebuggerClient::onSignal(int sig) {
       int secWait = 10;
       int secLeft = secWait - (now - m_sigTime);
       if (secLeft <= 0) {
+        usageLogEvent("signal quit");
         error("Program is not responding. Please restart debugger to get a "
               "new connection.");
         quit(); // NB: the machine is running, so can't send a real CmdQuit.
         return;
       }
+      usageLogEvent("signal wait");
       info("Please wait. If not responding in %d second%s, "
            "press Ctrl-C again to quit.", secLeft, secLeft > 1 ? "s" : "");
     } else {
+      usageLogEvent("signal start");
       info("Pausing program execution, please wait...");
-      usageLog("signal");
       m_sigTime = now;
     }
     m_signum = CmdSignal::SignalBreak;
@@ -460,6 +462,7 @@ bool DebuggerClient::connectRPC(const std::string &host, int port) {
   local->m_rpcPort = port;
   switchMachine(local);
   m_rpcHost = "rpc:" + host;
+  usageLogEvent("RPC connect", m_rpcHost);
   return !local->m_interrupting;
 }
 
@@ -613,7 +616,7 @@ void DebuggerClient::init(const DebuggerClientOptions &options) {
     m_options.user = Process::GetCurrentUser();
   }
 
-  usageLog("init");
+  usageLogEvent("init");
 
   loadConfig();
 
@@ -692,26 +695,32 @@ void DebuggerClient::run() {
     } catch (DebuggerServerLostException &e) {
       // Loss of connection
       TRACE_RB(1, "DebuggerClient::run: server lost exception\n");
-      usageLog(m_commandCanonical, "DebuggerServerLostException");
+      usageLogEvent("DebuggerServerLostException", m_commandCanonical);
       reconnect = true;
     } catch (DebuggerProtocolException &e) {
       // Bad or unexpected data. Give reconnect a shot, it could help...
       TRACE_RB(1, "DebuggerClient::run: protocol exception\n");
-      usageLog(m_commandCanonical, "DebuggerProtocolException");
+      usageLogEvent("DebuggerProtocolException", m_commandCanonical);
       reconnect = true;
     } catch (...) {
       TRACE_RB(1, "DebuggerClient::run: unknown exception\n");
-      usageLog(m_commandCanonical, "UnknownException");
+      usageLogEvent("UnknownException", m_commandCanonical);
       Logger::Error("Unhandled exception, exiting.");
     }
     // Note: it's silly to try to reconnect when stopping, or if we have a
     // problem while quitting.
     if (reconnect && !m_stopped && (m_commandCanonical != "quit")) {
-      if (DebuggerClient::reconnect()) continue;
+      usageLogEvent("reconnect attempt", m_commandCanonical);
+      if (DebuggerClient::reconnect()) {
+        usageLogEvent("reconnect success", m_commandCanonical);
+        continue;
+      }
+      usageLogEvent("reconnect failed", m_commandCanonical);
       Logger::Error("Unable to reconnect to server, exiting.");
     }
     break;
   }
+  usageLogEvent("exit");
   // Closing all proxy connections will force the local proxy to pop out of
   // it's wait, and eventually exit the main thread.
   closeAllConnections();
@@ -1028,7 +1037,8 @@ DebuggerCommandPtr DebuggerClient::waitForNextInterrupt() {
         }
       } else {
         CmdInterruptPtr intr = dynamic_pointer_cast<CmdInterrupt>(cmd);
-        Debugger::UsageLogInterrupt(getUsageMode(), *intr.get());
+        Debugger::UsageLogInterrupt(getUsageMode(), getSandboxId(),
+                                    *intr.get());
       }
       m_sigTime = 0;
       m_machine->m_interrupting = true;
@@ -1078,7 +1088,7 @@ DebuggerCommandPtr DebuggerClient::eventLoop(EventLoopKind loopKind,
           cmd->is((DebuggerCommand::Type)expectedCmd)) {
         // For the nested cases, the caller has sent a cmd to the server and is
         // expecting a specific response. When we get it, return it.
-        usageLog("done", boost::lexical_cast<string>(expectedCmd));
+        usageLogEvent("command done", boost::lexical_cast<string>(expectedCmd));
         m_machine->m_interrupting = true; // Machine is stopped
         m_inputState = TakingCommand;
         return cmd;
@@ -1103,7 +1113,7 @@ DebuggerCommandPtr DebuggerClient::eventLoop(EventLoopKind loopKind,
       }
       m_sigTime = 0;
       CmdInterruptPtr intr = dynamic_pointer_cast<CmdInterrupt>(cmd);
-      Debugger::UsageLogInterrupt(getUsageMode(), *intr.get());
+      Debugger::UsageLogInterrupt(getUsageMode(), getSandboxId(), *intr.get());
       cmd->onClient(*this);
 
       // When we make a new connection to a machine, we have to wait for it
@@ -1705,7 +1715,7 @@ bool DebuggerClient::process() {
     }
     case '?': {
       if (match("?")) {
-        usageLog("help", m_line);
+        usageLogCommand("help", m_line);
         CmdHelp().onClient(*this);
         return true;
       }
@@ -1718,7 +1728,7 @@ bool DebuggerClient::process() {
     default: {
       DebuggerCommand *cmd = createCommand();
       if (cmd) {
-        usageLog(m_commandCanonical, m_line);
+        usageLogCommand(m_commandCanonical, m_line);
         if (cmd->is(DebuggerCommand::KindOfRun)) playMacro("startup");
         DebuggerCommandPtr deleter(cmd);
         cmd->onClient(*this);
@@ -1916,12 +1926,12 @@ void DebuggerClient::processTakeCode() {
 
   char first = m_line[0];
   if (first == '@') {
-    usageLog("@", m_line);
+    usageLogCommand("@", m_line);
     m_code = string("<?php ") + (m_line.c_str() + 1) + ";";
     processEval();
     return;
   } else if (first == '=') {
-    usageLog("=", m_line);
+    usageLogCommand("=", m_line);
     while (m_line.at(m_line.size() - 1) == ';') {
       // strip the trailing ;
       m_line = m_line.substr(0, m_line.size() - 1);
@@ -1930,7 +1940,7 @@ void DebuggerClient::processTakeCode() {
     processEval();
     return;
   } else if (first != '<') {
-    usageLog("eval", m_line);
+    usageLogCommand("eval", m_line);
     // User entered something that did not start with @, =, or <
     // and also was not a debugger command. Interpret it as PHP.
     m_code = "<?php ";
@@ -1938,7 +1948,7 @@ void DebuggerClient::processTakeCode() {
     processEval();
     return;
   }
-  usageLog("<?php", m_line);
+  usageLogCommand("<?php", m_line);
   m_code = "<?php ";
   m_code += m_line.substr(m_command.length()) + "\n";
   m_inputState = TakingCode;
@@ -1981,6 +1991,23 @@ DSandboxInfoPtr DebuggerClient::getSandbox(int index) const {
   return DSandboxInfoPtr();
 }
 
+// Update the current sandbox in the current machine. This should always be
+// called once we're attached to a machine.
+void DebuggerClient::setSandbox(DSandboxInfoPtr sandbox) {
+  assert(m_machine != nullptr);
+  m_machine->m_sandbox = sandbox;
+}
+
+// Return the ID of the current sandbox, if there is one. If we're connected to
+// a machine that is attached to a sandbox, then we'll have an ID.
+std::string DebuggerClient::getSandboxId() {
+  if ((m_machine != nullptr) && m_machine->m_sandboxAttached &&
+      (m_machine->m_sandbox != nullptr)) {
+    return m_machine->m_sandbox->id();
+  }
+  return "None";
+}
+
 void DebuggerClient::updateThreads(DThreadInfoPtrVec threads) {
   TRACE(2, "DebuggerClient::updateThreads\n");
   m_threads = threads;
@@ -2247,6 +2274,7 @@ void DebuggerClient::record(const char *line) {
 
 bool DebuggerClient::apiGrab() {
   TRACE(2, "DebuggerClient::apiGrab\n");
+  usageLogEvent("api grab");
   Lock l(m_inApiUseLck);
   if (m_inApiUse) {
     return false;
@@ -2257,6 +2285,7 @@ bool DebuggerClient::apiGrab() {
 
 void DebuggerClient::apiFree() {
   TRACE(2, "DebuggerClient::apiFree\n");
+  usageLogEvent("api grab");
   Lock l(m_inApiUseLck);
   m_inApiUse = false;
 }
@@ -2277,10 +2306,18 @@ const char *DebuggerClient::getUsageMode() {
   return isApiMode() ? "api" : "terminal";
 }
 
-void DebuggerClient::usageLog(const std::string &cmd, const std::string &data) {
-  Debugger::UsageLog(getUsageMode(), cmd, data);
+// Log the execution of a command.
+void DebuggerClient::usageLogCommand(const std::string &cmd,
+                                     const std::string &data) {
+  Debugger::UsageLog(getUsageMode(), getSandboxId(), cmd, data);
 }
 
+// Log random, interesting events in the client.
+void DebuggerClient::usageLogEvent(const std::string &eventName,
+                                   const std::string &data) {
+  Debugger::UsageLog(getUsageMode(), getSandboxId(),
+                     "ClientEvent: " + eventName, data);
+}
 
 ///////////////////////////////////////////////////////////////////////////////
 // configuration

hphp/runtime/debugger/debugger_client.h

@@ -223,6 +223,8 @@ public:
     m_sandboxes = sandboxes;
   }
   DSandboxInfoPtr getSandbox(int index) const;
+  void setSandbox(DSandboxInfoPtr sandbox);
+  std::string getSandboxId();
 
   /**
    * Thread functions.
@@ -342,6 +344,11 @@ public:
   }
   std::string getCurrentUser() const { return m_options.user; }
 
+  // Usage logging
+  void usageLogCommand(const std::string &cmd, const std::string &data);
+  void usageLogEvent(const std::string &eventName,
+                     const std::string &data = "");
+
 private:
   enum InputState {
     TakingCommand,
@@ -487,7 +494,6 @@ private:
 
   // usage logging
   const char *getUsageMode();
-  void usageLog(const std::string &cmd, const std::string &data = "");
 };
 
 ///////////////////////////////////////////////////////////////////////////////

hphp/runtime/debugger/debugger_proxy.cpp

@@ -37,7 +37,8 @@ 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());
+  Debugger::UsageLog("server", m_dummyInfo.id(),
+                     "connnect", socket->getAddress());
 }
 
 DebuggerProxy::~DebuggerProxy() {
@@ -49,7 +50,7 @@ DebuggerProxy::~DebuggerProxy() {
     m_dummySandbox->stop();
   }
 
-  Debugger::UsageLog("server", "disconnect");
+  Debugger::UsageLog("server", getSandboxId(), "disconnect");
   TRACE_RB(2, "DebuggerProxy::~DebuggerProxy complete\n");
 }
 
@@ -548,7 +549,7 @@ void DebuggerProxy::processInterrupt(CmdInterrupt &cmd) {
     return;
   }
 
-  Debugger::UsageLogInterrupt("server", cmd);
+  Debugger::UsageLogInterrupt("server", getSandboxId(), 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.
@@ -562,7 +563,8 @@ 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()));
+      Debugger::UsageLog("server", getSandboxId(),
+                         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) {