NaCl cleanup: Remove not-very-useful debug logging in the plugin code

This removes all the PLUGIN_PRINTF/MODULE_PRINTF calls from
components/nacl/renderer/plugin/.

There aren't very many of these logging calls left now.  They don't
look useful to have in release binaries, and it's against Chromium
style to keep this sort of logging in the code.  Anyone doing
debugging can manually add their own logging.

My main motivation here is to remove a non-standard logging mechanism
that depends on some native_client/ headers.

BUG= https://bugs.chromium.org/p/nativeclient/issues/detail?id=2832
TEST=e.g. NaClBrowserTestPnacl.PPAPICore (tests PNaCl translation)

Review URL: https://codereview.chromium.org/1631413002

Cr-Commit-Position: refs/heads/master@{#371865}

components/nacl/renderer/plugin/module_ppapi.cc

@@ -16,16 +16,12 @@ namespace plugin {
 ModulePpapi::ModulePpapi() : pp::Module(),
                              init_was_successful_(false),
                              private_interface_(NULL) {
-  MODULE_PRINTF(("ModulePpapi::ModulePpapi (this=%p)\n",
-                 static_cast<void*>(this)));
 }
 
 ModulePpapi::~ModulePpapi() {
   if (init_was_successful_) {
     NaClNrdAllModulesFini();
   }
-  MODULE_PRINTF(("ModulePpapi::~ModulePpapi (this=%p)\n",
-                 static_cast<void*>(this)));
 }
 
 bool ModulePpapi::Init() {
@@ -34,8 +30,6 @@ bool ModulePpapi::Init() {
       GetBrowserInterface(PPB_NACL_PRIVATE_INTERFACE));
 
   if (NULL == private_interface_) {
-    MODULE_PRINTF(("ModulePpapi::Init failed: "
-                   "GetBrowserInterface returned NULL\n"));
     return false;
   }
   SetNaClInterface(private_interface_);
@@ -57,13 +51,7 @@ bool ModulePpapi::Init() {
 }
 
 pp::Instance* ModulePpapi::CreateInstance(PP_Instance pp_instance) {
-  MODULE_PRINTF(("ModulePpapi::CreateInstance (pp_instance=%" NACL_PRId32
-                 ")\n",
-                 pp_instance));
-  Plugin* plugin = new Plugin(pp_instance);
-  MODULE_PRINTF(("ModulePpapi::CreateInstance (return %p)\n",
-                 static_cast<void* >(plugin)));
-  return plugin;
+  return new Plugin(pp_instance);
 }
 
 }  // namespace plugin
@@ -72,7 +60,6 @@ pp::Instance* ModulePpapi::CreateInstance(PP_Instance pp_instance) {
 namespace pp {
 
 Module* CreateModule() {
-  MODULE_PRINTF(("CreateModule ()\n"));
   return new plugin::ModulePpapi();
 }
 

components/nacl/renderer/plugin/plugin.cc

@@ -28,15 +28,9 @@ void NoOpCallback(void* user_data, int32_t result) {
 namespace plugin {
 
 void Plugin::ShutDownSubprocesses() {
-  PLUGIN_PRINTF(("Plugin::ShutDownSubprocesses (this=%p)\n",
-                 static_cast<void*>(this)));
-
   // Shut down service runtime. This must be done before all other calls so
   // they don't block forever when waiting for the upcall thread to exit.
   main_subprocess_.Shutdown();
-
-  PLUGIN_PRINTF(("Plugin::ShutDownSubprocess (this=%p, return)\n",
-                 static_cast<void*>(this)));
 }
 
 void Plugin::StartSelLdr(ServiceRuntime* service_runtime,
@@ -164,8 +158,6 @@ void Plugin::NexeFileDidOpen(int32_t pp_error) {
 }
 
 void Plugin::BitcodeDidTranslate(int32_t pp_error) {
-  PLUGIN_PRINTF(("Plugin::BitcodeDidTranslate (pp_error=%" NACL_PRId32 ")\n",
-                 pp_error));
   if (pp_error != PP_OK) {
     // Error should have been reported by pnacl. Just return.
     return;
@@ -185,8 +177,6 @@ void Plugin::BitcodeDidTranslate(int32_t pp_error) {
 }
 
 void Plugin::NaClManifestFileDidOpen(int32_t pp_error) {
-  PLUGIN_PRINTF(("Plugin::NaClManifestFileDidOpen (pp_error=%"
-                 NACL_PRId32 ")\n", pp_error));
   if (pp_error != PP_OK)
     return;
 

components/nacl/renderer/plugin/pnacl_coordinator.cc

@@ -62,8 +62,6 @@ PnaclCoordinator* PnaclCoordinator::BitcodeToNative(
     const std::string& pexe_url,
     const PP_PNaClOptions& pnacl_options,
     const pp::CompletionCallback& translate_notify_callback) {
-  PLUGIN_PRINTF(("PnaclCoordinator::BitcodeToNative (plugin=%p, pexe=%s)\n",
-                 static_cast<void*>(plugin), pexe_url.c_str()));
   PnaclCoordinator* coordinator =
       new PnaclCoordinator(plugin, pexe_url,
                            pnacl_options,
@@ -107,9 +105,6 @@ PnaclCoordinator::PnaclCoordinator(
 }
 
 PnaclCoordinator::~PnaclCoordinator() {
-  PLUGIN_PRINTF(("PnaclCoordinator::~PnaclCoordinator (this=%p, "
-                 "translate_thread=%p\n",
-                 static_cast<void*>(this), translate_thread_.get()));
   // Stopping the translate thread will cause the translate thread to try to
   // run translation_complete_callback_ on the main thread.  This destructor is
   // running from the main thread, and by the time it exits, callback_factory_
@@ -143,7 +138,6 @@ void PnaclCoordinator::ReportNonPpapiError(PP_NaClError err_code,
 }
 
 void PnaclCoordinator::ExitWithError() {
-  PLUGIN_PRINTF(("PnaclCoordinator::ExitWithError\n"));
   // Free all the intermediate callbacks we ever created.
   // Note: this doesn't *cancel* the callbacks from the factories attached
   // to the various helper classes (e.g., pnacl_resources). Thus, those
@@ -163,8 +157,6 @@ void PnaclCoordinator::ExitWithError() {
 
 // Signal that Pnacl translation completed normally.
 void PnaclCoordinator::TranslateFinished(int32_t pp_error) {
-  PLUGIN_PRINTF(("PnaclCoordinator::TranslateFinished (pp_error=%"
-                 NACL_PRId32 ")\n", pp_error));
   // Bail out if there was an earlier error (e.g., pexe load failure),
   // or if there is an error from the translation thread.
   if (translate_finish_error_ != PP_OK || pp_error != PP_OK) {
@@ -305,8 +297,6 @@ void PnaclCoordinator::BitcodeStreamGotData(const void* data, int32_t length) {
 }
 
 void PnaclCoordinator::BitcodeStreamDidFinish(int32_t pp_error) {
-  PLUGIN_PRINTF(("PnaclCoordinator::BitcodeStreamDidFinish (pp_error=%"
-                 NACL_PRId32 ")\n", pp_error));
   if (pp_error != PP_OK) {
     // Defer reporting the error and cleanup until after the translation
     // thread returns, because it may be accessing the coordinator's
@@ -370,7 +360,6 @@ pp::CompletionCallback PnaclCoordinator::GetCompileProgressCallback(
 }
 
 void PnaclCoordinator::LoadCompiler() {
-  PLUGIN_PRINTF(("PnaclCoordinator::LoadCompiler"));
   base::TimeTicks compiler_load_start_time = base::TimeTicks::Now();
   pp::CompletionCallback load_finished = callback_factory_.NewCallback(
       &PnaclCoordinator::RunCompile, compiler_load_start_time);
@@ -386,8 +375,6 @@ void PnaclCoordinator::LoadCompiler() {
 
 void PnaclCoordinator::RunCompile(int32_t pp_error,
                                   base::TimeTicks compiler_load_start_time) {
-  PLUGIN_PRINTF(
-      ("PnaclCoordinator::RunCompile (pp_error=%" NACL_PRId32 ")\n", pp_error));
   if (pp_error != PP_OK) {
     ReportNonPpapiError(
         PP_NACL_ERROR_PNACL_LLC_SETUP,
@@ -419,8 +406,6 @@ void PnaclCoordinator::RunCompile(int32_t pp_error,
 }
 
 void PnaclCoordinator::LoadLinker(int32_t pp_error) {
-  PLUGIN_PRINTF(
-      ("PnaclCoordinator::LoadLinker (pp_error=%" NACL_PRId32 ")\n", pp_error));
   // Errors in the previous step would have skipped to TranslateFinished
   // so we only expect PP_OK here.
   DCHECK(pp_error == PP_OK);
@@ -439,8 +424,6 @@ void PnaclCoordinator::LoadLinker(int32_t pp_error) {
 
 void PnaclCoordinator::RunLink(int32_t pp_error,
                                base::TimeTicks ld_load_start_time) {
-  PLUGIN_PRINTF(
-      ("PnaclCoordinator::RunLink (pp_error=%" NACL_PRId32 ")\n", pp_error));
   if (pp_error != PP_OK) {
     ReportNonPpapiError(
         PP_NACL_ERROR_PNACL_LD_SETUP,

components/nacl/renderer/plugin/pnacl_resources.cc

@@ -77,8 +77,6 @@ bool PnaclResources::ReadResourceInfo() {
 
 
 bool PnaclResources::StartLoad() {
-  PLUGIN_PRINTF(("PnaclResources::StartLoad\n"));
-
   // Do a blocking load of each of the resources.
   std::vector<ResourceType> to_load;
   if (use_subzero_) {

components/nacl/renderer/plugin/pnacl_translate_thread.cc

@@ -87,7 +87,6 @@ void PnaclTranslateThread::SetupState(
     PP_PNaClOptions* pnacl_options,
     const std::string& architecture_attributes,
     PnaclCoordinator* coordinator) {
-  PLUGIN_PRINTF(("PnaclTranslateThread::SetupState)\n"));
   compiler_subprocess_ = compiler_subprocess;
   ld_subprocess_ = ld_subprocess;
   obj_files_ = obj_files;
@@ -103,7 +102,6 @@ void PnaclTranslateThread::SetupState(
 
 void PnaclTranslateThread::RunCompile(
     const pp::CompletionCallback& compile_finished_callback) {
-  PLUGIN_PRINTF(("PnaclTranslateThread::RunCompile)\n"));
   DCHECK(started());
   DCHECK(compiler_subprocess_->service_runtime());
   compiler_subprocess_active_ = true;
@@ -127,7 +125,6 @@ void PnaclTranslateThread::RunCompile(
 }
 
 void PnaclTranslateThread::RunLink() {
-  PLUGIN_PRINTF(("PnaclTranslateThread::RunLink)\n"));
   DCHECK(started());
   DCHECK(ld_subprocess_->service_runtime());
   ld_subprocess_active_ = true;
@@ -212,8 +209,6 @@ void PnaclTranslateThread::DoCompile() {
                                compiler_channel_peer_pid_));
   }
 
-  PLUGIN_PRINTF(("DoCompile using subzero: %d\n", pnacl_options_->use_subzero));
-
   pp::Core* core = pp::Module::Get()->core();
   base::TimeTicks do_compile_start_time = base::TimeTicks::Now();
 
@@ -245,7 +240,6 @@ void PnaclTranslateThread::DoCompile() {
                     std::string("Stream init failed: ") + error_str);
     return;
   }
-  PLUGIN_PRINTF(("PnaclCoordinator: StreamInit successful\n"));
 
   // llc process is started.
   while(!done_ || data_buffers_.size() > 0) {
@@ -253,15 +247,11 @@ void PnaclTranslateThread::DoCompile() {
     while(!done_ && data_buffers_.size() == 0) {
       buffer_cond_.Wait();
     }
-    PLUGIN_PRINTF(("PnaclTranslateThread awake (done=%d, size=%" NACL_PRIuS
-                   ")\n",
-                   done_, data_buffers_.size()));
     if (data_buffers_.size() > 0) {
       std::string data;
       data.swap(data_buffers_.front());
       data_buffers_.pop_front();
       cond_mu_.Release();
-      PLUGIN_PRINTF(("StreamChunk\n"));
 
       if (!compiler_channel_filter_->Send(
               new PpapiMsg_PnaclTranslatorCompileChunk(data, &success))) {
@@ -278,7 +268,6 @@ void PnaclTranslateThread::DoCompile() {
         // console.
         break;
       }
-      PLUGIN_PRINTF(("StreamChunk Successful\n"));
       core->CallOnMainThread(
           0,
           coordinator_->GetCompileProgressCallback(data.size()),
@@ -287,7 +276,6 @@ void PnaclTranslateThread::DoCompile() {
       cond_mu_.Release();
     }
   }
-  PLUGIN_PRINTF(("PnaclTranslateThread done with chunks\n"));
   // Finish llc.
   if (!compiler_channel_filter_->Send(
           new PpapiMsg_PnaclTranslatorCompileEnd(&success, &error_str))) {
@@ -373,8 +361,6 @@ void PnaclTranslateThread::DoLink() {
   GetNaClInterface()->LogTranslateTime(
       "NaCl.Perf.PNaClLoadTime.LinkTime",
       (base::TimeTicks::Now() - link_start_time).InMicroseconds());
-  PLUGIN_PRINTF(("PnaclCoordinator: link (translator=%p) succeeded\n",
-                 this));
 
   // Shut down the ld subprocess.
   {
@@ -390,8 +376,6 @@ void PnaclTranslateThread::DoLink() {
 void PnaclTranslateThread::TranslateFailed(
     PP_NaClError err_code,
     const std::string& error_string) {
-  PLUGIN_PRINTF(("PnaclTranslateThread::TranslateFailed (error_string='%s')\n",
-                 error_string.c_str()));
   pp::Core* core = pp::Module::Get()->core();
   if (coordinator_error_info_->message().empty()) {
     // Only use our message if one hasn't already been set by the coordinator
@@ -404,7 +388,6 @@ void PnaclTranslateThread::TranslateFailed(
 }
 
 void PnaclTranslateThread::AbortSubprocesses() {
-  PLUGIN_PRINTF(("PnaclTranslateThread::AbortSubprocesses\n"));
   {
     base::AutoLock lock(subprocess_mu_);
     if (compiler_subprocess_ != NULL && compiler_subprocess_active_) {
@@ -427,11 +410,9 @@ void PnaclTranslateThread::AbortSubprocesses() {
 }
 
 PnaclTranslateThread::~PnaclTranslateThread() {
-  PLUGIN_PRINTF(("~PnaclTranslateThread (translate_thread=%p)\n", this));
   AbortSubprocesses();
   if (translate_thread_)
     translate_thread_->Join();
-  PLUGIN_PRINTF(("~PnaclTranslateThread joined\n"));
 }
 
 } // namespace plugin

components/nacl/renderer/plugin/utility.cc

@@ -4,63 +4,11 @@
  * found in the LICENSE file.
  */
 
-#include <stdarg.h>
-#include <stdlib.h>
-#include <string.h>
-
 #include "components/nacl/renderer/plugin/utility.h"
 #include "ppapi/cpp/module.h"
 
 namespace plugin {
 
-int gNaClPluginDebugPrintEnabled = -1;
-
-/*
- * Prints formatted message to the log.
- */
-int NaClPluginPrintLog(const char *format, ...) {
-  va_list arg;
-  int out_size;
-
-  static const int kStackBufferSize = 512;
-  char stack_buffer[kStackBufferSize];
-
-  // Just log locally to stderr if we can't use the nacl interface.
-  if (!GetNaClInterface()) {
-    va_start(arg, format);
-    int rc = vfprintf(stderr, format, arg);
-    va_end(arg);
-    return rc;
-  }
-
-  va_start(arg, format);
-  out_size = vsnprintf(stack_buffer, kStackBufferSize, format, arg);
-  va_end(arg);
-  if (out_size < kStackBufferSize) {
-    GetNaClInterface()->Vlog(stack_buffer);
-  } else {
-    // Message too large for our stack buffer; we have to allocate memory
-    // instead.
-    char *buffer = static_cast<char*>(malloc(out_size + 1));
-    va_start(arg, format);
-    vsnprintf(buffer, out_size + 1, format, arg);
-    va_end(arg);
-    GetNaClInterface()->Vlog(buffer);
-    free(buffer);
-  }
-  return out_size;
-}
-
-/*
- * Currently looks for presence of NACL_PLUGIN_DEBUG and returns
- * 0 if absent and 1 if present.  In the future we may include notions
- * of verbosity level.
- */
-int NaClPluginDebugPrintCheckEnv() {
-  char* env = getenv("NACL_PLUGIN_DEBUG");
-  return (NULL != env);
-}
-
 // We cache the NaCl interface pointer and ensure that its set early on, on the
 // main thread. This allows GetNaClInterface() to be used from non-main threads.
 static const PPB_NaCl_Private* g_nacl_interface = NULL;

components/nacl/renderer/plugin/utility.h

@@ -12,8 +12,6 @@
 #include <stdint.h>
 
 #include "components/nacl/renderer/ppb_nacl_private.h"
-#include "native_client/src/shared/platform/nacl_threads.h"
-#include "native_client/src/shared/platform/nacl_time.h"
 
 #define SRPC_PLUGIN_DEBUG 1
 
@@ -22,42 +20,6 @@ namespace plugin {
 const PPB_NaCl_Private* GetNaClInterface();
 void SetNaClInterface(const PPB_NaCl_Private* nacl_interface);
 
-// Debugging print utility
-extern int gNaClPluginDebugPrintEnabled;
-extern int NaClPluginPrintLog(const char *format, ...);
-extern int NaClPluginDebugPrintCheckEnv();
-#if SRPC_PLUGIN_DEBUG
-#define INIT_PLUGIN_LOGGING() do {                                    \
-    if (-1 == ::plugin::gNaClPluginDebugPrintEnabled) {               \
-      ::plugin::gNaClPluginDebugPrintEnabled =                        \
-          ::plugin::NaClPluginDebugPrintCheckEnv();                   \
-    }                                                                 \
-} while (0)
-
-#define PLUGIN_PRINTF(args) do {                                      \
-    INIT_PLUGIN_LOGGING();                                            \
-    if (0 != ::plugin::gNaClPluginDebugPrintEnabled) {                \
-      ::plugin::NaClPluginPrintLog("PLUGIN %" NACL_PRIu64 ": ",       \
-                                   NaClGetTimeOfDayMicroseconds());   \
-      ::plugin::NaClPluginPrintLog args;                              \
-    }                                                                 \
-  } while (0)
-
-// MODULE_PRINTF is used in the module because PLUGIN_PRINTF uses a
-// a timer that may not yet be initialized.
-#define MODULE_PRINTF(args) do {                                      \
-    INIT_PLUGIN_LOGGING();                                            \
-    if (0 != ::plugin::gNaClPluginDebugPrintEnabled) {                \
-      ::plugin::NaClPluginPrintLog("MODULE: ");                       \
-      ::plugin::NaClPluginPrintLog args;                              \
-    }                                                                 \
-  } while (0)
-#else
-#  define PLUGIN_PRINTF(args) do { if (0) { printf args; } } while (0)
-#  define MODULE_PRINTF(args) do { if (0) { printf args; } } while (0)
-/* allows DCE but compiler can still do format string checks */
-#endif
-
 }  // namespace plugin
 
 #endif  // COMPONENTS_NACL_RENDERER_PLUGIN_UTILITY_H_

components/nacl/renderer/ppb_nacl_private.h

@@ -281,8 +281,6 @@ struct PPB_NaCl_Private {
    * platform.
    */
   const char* (*GetSandboxArch)(void);
-  /* Logs the message via VLOG. */
-  void (*Vlog)(const char* message);
   /* Initializes internal state for a NaCl plugin. */
   void (*InitializePlugin)(PP_Instance instance,
                            uint32_t argc,

components/nacl/renderer/ppb_nacl_private_impl.cc

@@ -898,10 +898,6 @@ PP_Bool NaClDebugEnabledForURL(const char* alleged_nmf_url) {
       should_debug);
 }
 
-void Vlog(const char* message) {
-  VLOG(1) << message;
-}
-
 void InitializePlugin(PP_Instance instance,
                       uint32_t argc,
                       const char* argn[],
@@ -1714,7 +1710,6 @@ const PPB_NaCl_Private nacl_interface = {
   &InstanceCreated,
   &InstanceDestroyed,
   &GetSandboxArch,
-  &Vlog,
   &InitializePlugin,
   &RequestNaClManifest,
   &GetManifestBaseURL,