[NaCl SDK] ppapi_simple logging improvements.

Add a new verbosity level called TRACE, and move a lot
of the message to this level.  This means the default
level for Debug builds (LOG) is a little less chatty.
Write all log message to stderr rather than stdout, so
that we don't pullute the stdout the application with our
messages (think minizip using ppapi_simple).

Also, use NACL_SDK_DEBUG to determine if we are building
a debug build, so the verbosity level is set correctly
in debug builds.

make build_projects.py -v pass V=1 to the make commands
that it runs.

When using the common.mk build system, pass --debug-libs
to create_html in debug builds.  Otherwise release libs
are deployed by create_nmf.

BUG=
R=binji@chromium.org, noelallen@chromium.org

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

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@209526 0039d316-1c4b-4281-b951-d872f2087c98

11 files changed, 136 insertions, 90 deletions

diff --git a/native_client_sdk/src/build_tools/build_projects.py b/native_client_sdk/src/build_tools/build_projects.py
index db07e32..e081137 100755
--- a/native_client_sdk/src/build_tools/build_projects.py
+++ b/native_client_sdk/src/build_tools/build_projects.py
@@ -141,7 +141,8 @@ def UpdateProjects(pepperdir, platform, project_tree, toolchains,
                                        targets)
 
 
-def BuildProjectsBranch(pepperdir, platform, branch, deps, clean, config):
+def BuildProjectsBranch(pepperdir, platform, branch, deps, clean, config,
+                        verbose):
   make_dir = os.path.join(pepperdir, branch)
   print "\n\nMake: " + make_dir
   if platform == 'win':
@@ -150,10 +151,14 @@ def BuildProjectsBranch(pepperdir, platform, branch, deps, clean, config):
   else:
     make = 'make'
 
+
   extra_args = ['CONFIG='+config]
   if not deps:
     extra_args += ['IGNORE_DEPS=1']
 
+  if verbose:
+    extra_args += ['V=1']
+
   try:
     buildbot_common.Run([make, '-j8', 'TOOLCHAIN=all'] + extra_args,
                         cwd=make_dir)
@@ -168,17 +173,19 @@ def BuildProjectsBranch(pepperdir, platform, branch, deps, clean, config):
 
 
 def BuildProjects(pepperdir, platform, project_tree, deps=True,
-                  clean=False, config='Debug'):
+                  clean=False, config='Debug', verbose=False):
   # First build libraries
   build_order = ['src', 'testlibs']
   for branch in build_order:
     if branch in project_tree:
-      BuildProjectsBranch(pepperdir, platform, branch, deps, clean, config)
+      BuildProjectsBranch(pepperdir, platform, branch, deps, clean, config,
+                          verbose)
 
   # Build everything else.
   for branch in project_tree:
     if branch not in build_order:
-      BuildProjectsBranch(pepperdir, platform, branch, deps, clean, config)
+      BuildProjectsBranch(pepperdir, platform, branch, deps, clean, config,
+                          verbose)
 
 
 def main(args):
@@ -253,7 +260,8 @@ def main(args):
     else:
       configs = ['Debug', 'Release']
     for config in configs:
-      BuildProjects(pepperdir, platform, project_tree, config=config)
+      BuildProjects(pepperdir, platform, project_tree,
+                    config=config, verbose=options.verbose)
 
   return 0
 
diff --git a/native_client_sdk/src/build_tools/build_sdk.py b/native_client_sdk/src/build_tools/build_sdk.py
index e9c8d82..658a2a1 100755
--- a/native_client_sdk/src/build_tools/build_sdk.py
+++ b/native_client_sdk/src/build_tools/build_sdk.py
@@ -927,10 +927,9 @@ def main(args):
     # of the build.
     del os.environ['NACL_SDK_ROOT']
 
-  BuildStepCleanPepperDirs(pepperdir, pepperdir_old)
-  BuildStepMakePepperDirs(pepperdir, ['include', 'toolchain', 'tools'])
-
   if not options.skip_toolchain:
+    BuildStepCleanPepperDirs(pepperdir, pepperdir_old)
+    BuildStepMakePepperDirs(pepperdir, ['include', 'toolchain', 'tools'])
     BuildStepDownloadToolchains()
     BuildStepUntarToolchains(pepperdir, platform, arch, toolchains)
 
diff --git a/native_client_sdk/src/libraries/ppapi_simple/ps.h b/native_client_sdk/src/libraries/ppapi_simple/ps.h
index 080065c..fe5205b 100644
--- a/native_client_sdk/src/libraries/ppapi_simple/ps.h
+++ b/native_client_sdk/src/libraries/ppapi_simple/ps.h
@@ -131,5 +131,4 @@ void* PSUserCreateInstance(PP_Instance inst) {                     \
 EXTERN_C_END
 
 
-#endif  // PPAPI_SIMPLE_PPAPI_SIMPLE_H
-
+#endif  // PPAPI_SIMPLE_PS_H_
diff --git a/native_client_sdk/src/libraries/ppapi_simple/ps_context_2d.h b/native_client_sdk/src/libraries/ppapi_simple/ps_context_2d.h
index 707a53d..30d0cf9 100644
--- a/native_client_sdk/src/libraries/ppapi_simple/ps_context_2d.h
+++ b/native_client_sdk/src/libraries/ppapi_simple/ps_context_2d.h
@@ -2,8 +2,8 @@
  * Use of this source code is governed by a BSD-style license that can be
  * found in the LICENSE file. */
 
-#ifndef PPAPI_SIMPLE_PS_CONTEXT_2D
-#define PPAPI_SIMPLE_PS_CONTEXT_2D
+#ifndef PPAPI_SIMPLE_PS_CONTEXT_2D_H_
+#define PPAPI_SIMPLE_PS_CONTEXT_2D_H_
 
 #include "ppapi/c/pp_resource.h"
 #include "ppapi/c/ppb_graphics_2d.h"
@@ -64,4 +64,4 @@ int PSContext2DSwapBuffer(PSContext2D_t* ctx);
 
 EXTERN_C_END
 
-#endif  // PPAPI_SIMPLE_PS_CONTEXT_2D
+#endif  /* PPAPI_SIMPLE_PS_CONTEXT_2D_H_ */
diff --git a/native_client_sdk/src/libraries/ppapi_simple/ps_event.h b/native_client_sdk/src/libraries/ppapi_simple/ps_event.h
index b02f54d..731f053 100644
--- a/native_client_sdk/src/libraries/ppapi_simple/ps_event.h
+++ b/native_client_sdk/src/libraries/ppapi_simple/ps_event.h
@@ -2,7 +2,6 @@
  * Use of this source code is governed by a BSD-style license that can be
  * found in the LICENSE file. */
 
-
 #ifndef PPAPI_SIMPLE_PS_EVENT_H_
 #define PPAPI_SIMPLE_PS_EVENT_H_
 
@@ -91,5 +90,4 @@ void PSEventPostResource(PSEventType type, PP_Resource resource);
 
 EXTERN_C_END
 
-#endif  // PPAPI_SIMPLE_PS_EVENT_H_
-
+#endif  /* PPAPI_SIMPLE_PS_EVENT_H_ */
diff --git a/native_client_sdk/src/libraries/ppapi_simple/ps_instance.cc b/native_client_sdk/src/libraries/ppapi_simple/ps_instance.cc
index 7388bc9..4612a52 100644
--- a/native_client_sdk/src/libraries/ppapi_simple/ps_instance.cc
+++ b/native_client_sdk/src/libraries/ppapi_simple/ps_instance.cc
@@ -5,7 +5,6 @@
 #include <errno.h>
 #include <fcntl.h>
 #include <pthread.h>
-#include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <sys/types.h>
@@ -57,7 +56,7 @@ struct StartInfo {
 // The starting point for 'main'.  We create this thread to hide the real
 // main pepper thread which must never be blocked.
 void* PSInstance::MainThreadThunk(void *info) {
-  s_InstanceObject->Log("Got MainThreadThunk.\n");
+  s_InstanceObject->Trace("Got MainThreadThunk.\n");
   StartInfo* si = static_cast<StartInfo*>(info);
   si->inst_->main_loop_ = new pp::MessageLoop(si->inst_);
   si->inst_->main_loop_->AttachToCurrentThread();
@@ -69,20 +68,24 @@ void* PSInstance::MainThreadThunk(void *info) {
   delete[] si->argv_;
   delete si;
 
+  // Exit the entire process once the 'main' thread returns.
+  // The error code will be available to javascript via
+  // the exitcode paramater of the crash event.
+  exit(ret);
   return NULL;
 }
 
 // The default implementation supports running a 'C' main.
 int PSInstance::MainThread(int argc, char *argv[]) {
-  if (main_cb_) {
-    Log("Starting MAIN.\n");
-    int ret = main_cb_(argc, argv);
-    Log("Main thread returned with %d.\n", ret);
-    return ret;
+  if (!main_cb_) {
+    Error("No main defined.\n");
+    return 0;
   }
 
-  Error("No main defined.\n");
-  return 0;
+  Trace("Starting MAIN.\n");
+  int ret = main_cb_(argc, argv);
+  Log("Main thread returned with %d.\n", ret);
+  return ret;
 }
 
 PSInstance::PSInstance(PP_Instance instance, const char *argv[])
@@ -90,13 +93,13 @@ PSInstance::PSInstance(PP_Instance instance, const char *argv[])
       pp::MouseLock(this),
       pp::Graphics3DClient(this),
       main_loop_(NULL),
-      verbosity_(PSV_LOG),
+      verbosity_(PSV_WARN),
       events_enabled_(PSE_NONE),
       fd_tty_(-1) {
   // Set the single Instance object
   s_InstanceObject = this;
 
-#ifdef DEBUG
+#ifdef NACL_SDK_DEBUG
   SetVerbosity(PSV_LOG);
 #endif
 
@@ -130,13 +133,7 @@ bool PSInstance::Init(uint32_t arg,
   si->argv_[0] = NULL;
 
   // Process arguments passed into Module INIT from JavaScript
-  for (uint32_t i=0; i < arg; i++) {
-    if (argv[i]) {
-      Log("ARG %s=%s\n", argn[i], argv[i]);
-    } else {
-      Log("ARG %s\n", argn[i]);
-    }
-
+  for (uint32_t i = 0; i < arg; i++) {
     // If we start with PM prefix set the instance argument map
     if (0 == strncmp(argn[i], "ps_", 3)) {
       std::string key = argn[i];
@@ -145,25 +142,33 @@ bool PSInstance::Init(uint32_t arg,
       continue;
     }
 
+    // Chrome passed @dev as an internal extra attribute in
+    // some cases.  Ignore this.
+    if (0 == strcmp(argn[i], "@dev")) {
+      continue;
+    }
+
     // If this is the 'src' tag, then get the NMF name.
     if (!strcmp("src", argn[i])) {
       char *name = new char[strlen(argv[i]) + 1];
       strcpy(name, argv[i]);
       si->argv_[0] = name;
-    }
-    else {
-      // Otherwise turn it into arguments
-      char *key = new char[strlen(argn[i]) + 3];
-      key[0] = '-';
-      key[1] = '-';
-      strcpy(&key[2], argn[i]);
-
-      si->argv_[si->argc_++] = key;
-      if (argv[i] && argv[i][0]) {
-        char *val = new char[strlen(argv[i]) + 1];
-        strcpy(val, argv[i]);
-        si->argv_[si->argc_++] = val;
-      }
+    } else {
+      // Otherwise turn html tag attributes into arguments
+      // that get passed to the main funciton.  Attributes
+      // without values get transformed into "--name" and
+      // attributes with values become "--name=value".
+      int arglen = strlen(argn[i]) + 3;
+      if (argv[i] && argv[i][0])
+        arglen += strlen(argv[i]) + 1;
+
+      char* arg = new char[arglen];
+      if (argv[i] && argv[i][0])
+        sprintf(arg, "--%s=%s", argn[i], argv[i]);
+      else
+        sprintf(arg, "--%s", argn[i]);
+
+      si->argv_[si->argc_++] = arg;
     }
   }
 
@@ -175,16 +180,32 @@ bool PSInstance::Init(uint32_t arg,
   }
 
   PSInterfaceInit();
+  bool props_processed = ProcessProperties();
 
-  if (ProcessProperties()) {
-    pthread_t main_thread;
-    int ret = pthread_create(&main_thread, NULL, MainThreadThunk, si);
-    Log("Created thread: %d.\n", ret);
-    return ret == 0;
+  // Log arg values only once ProcessProperties has been
+  // called so that the ps_verbosity attribute will be in
+  // effect.
+  for (uint32_t i = 0; i < arg; i++) {
+    if (argv[i]) {
+      Trace("attribs[%d] '%s=%s'\n", i, argn[i], argv[i]);
+    } else {
+      Trace("attribs[%d] '%s'\n", i, argn[i]);
+    }
   }
 
-  Log("Skipping create thread.\n");
-  return false;
+  for (uint32_t i = 0; i < si->argc_; i++) {
+    Trace("argv[%d] '%s'\n", i, si->argv_[i]);
+  }
+
+  if (!props_processed) {
+    Warn("Skipping create thread.\n");
+    return false;
+  }
+
+  pthread_t main_thread;
+  int ret = pthread_create(&main_thread, NULL, MainThreadThunk, si);
+  Trace("Created thread: %d.\n", ret);
+  return ret == 0;
 }
 
 const char* PSInstance::GetProperty(const char* key, const char* def) {
@@ -195,7 +216,7 @@ const char* PSInstance::GetProperty(const char* key, const char* def) {
   return def;
 }
 
-// Processes the properties passed fixed at compile time via the
+// Processes the properties set at compile time via the
 // initialization macro, or via dynamically set embed attributes
 // through instance DidCreate.
 bool PSInstance::ProcessProperties() {
@@ -241,28 +262,39 @@ void PSInstance::SetVerbosity(Verbosity verbosity) {
   verbosity_ = verbosity;
 }
 
-void PSInstance::Log(const char *fmt, ...) {
-  if (verbosity_ >= PSV_LOG) {
-    va_list ap;
-    va_start(ap, fmt);
-    vfprintf(stdout, fmt, ap);
+void PSInstance::VALog(Verbosity verbosity, const char *fmt, va_list args) {
+  if (verbosity <= verbosity_) {
+    fprintf(stderr, "ps: ");
+    vfprintf(stderr, fmt, args);
   }
 }
 
+void PSInstance::Trace(const char *fmt, ...) {
+  va_list ap;
+  va_start(ap, fmt);
+  VALog(PSV_TRACE, fmt, ap);
+  va_end(ap);
+}
+
+void PSInstance::Log(const char *fmt, ...) {
+  va_list ap;
+  va_start(ap, fmt);
+  VALog(PSV_LOG, fmt, ap);
+  va_end(ap);
+}
+
 void PSInstance::Warn(const char *fmt, ...) {
-  if (verbosity_ >= PSV_WARN) {
-    va_list ap;
-    va_start(ap, fmt);
-    vfprintf(stdout, fmt, ap);
-  }
+  va_list ap;
+  va_start(ap, fmt);
+  VALog(PSV_WARN, fmt, ap);
+  va_end(ap);
 }
 
 void PSInstance::Error(const char *fmt, ...) {
-  if (verbosity_ >= PSV_ERROR) {
-    va_list ap;
-    va_start(ap, fmt);
-    vfprintf(stderr, fmt, ap);
-  }
+  va_list ap;
+  va_start(ap, fmt);
+  VALog(PSV_ERROR, fmt, ap);
+  va_end(ap);
 }
 
 void PSInstance::SetEnabledEvents(uint32_t mask) {
@@ -374,7 +406,7 @@ void PSInstance::ReleaseEvent(PSEvent* event) {
 }
 
 void PSInstance::HandleMessage(const pp::Var& message) {
-  Log("Got Message\n");
+  Trace("Got Message\n");
   PostEvent(PSE_INSTANCE_HANDLEMESSAGE, message.pp_var());
 }
 
diff --git a/native_client_sdk/src/libraries/ppapi_simple/ps_instance.h b/native_client_sdk/src/libraries/ppapi_simple/ps_instance.h
index 9e6318b..f02d574 100644
--- a/native_client_sdk/src/libraries/ppapi_simple/ps_instance.h
+++ b/native_client_sdk/src/libraries/ppapi_simple/ps_instance.h
@@ -1,12 +1,11 @@
-/* Copyright (c) 2013 The Chromium Authors. All rights reserved.
- * Use of this source code is governed by a BSD-style license that can be
- * found in the LICENSE file.
- */
-
+// Copyright (c) 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
 
 #ifndef PPAPI_SIMPLE_PS_INSTANCE_H_
 #define PPAPI_SIMPLE_PS_INSTANCE_H_
 
+#include <stdarg.h>
 #include <map>
 
 #include "ppapi/c/pp_instance.h"
@@ -35,11 +34,14 @@ typedef std::map<std::string, std::string> PropertyMap_t;
 // Graphics3DClient interfaces.
 class PSInstance : public pp::Instance, pp::MouseLock, pp::Graphics3DClient {
  public:
+  // Verbosity levels, ecplicitly numbered since we pass these
+  // in from html attributes as numberic values.
   enum Verbosity {
-    PSV_SILENT,
-    PSV_ERROR,
-    PSV_WARN,
-    PSV_LOG,
+    PSV_SILENT = 0,
+    PSV_ERROR = 1,
+    PSV_WARN = 2,
+    PSV_LOG = 3,
+    PSV_TRACE = 4,
   };
 
   // Returns a pointer to the global instance
@@ -61,6 +63,7 @@ class PSInstance : public pp::Instance, pp::MouseLock, pp::Graphics3DClient {
 
   // Logging Functions
   void SetVerbosity(Verbosity verbosity);
+  void Trace(const char *fmt, ...);
   void Log(const char *fmt, ...);
   void Warn(const char *fmt, ...);
   void Error(const char *fmt, ...);
@@ -86,6 +89,10 @@ class PSInstance : public pp::Instance, pp::MouseLock, pp::Graphics3DClient {
   // This function will create a new thread which will run the pseudo main.
   virtual bool Init(uint32_t argc, const char* argn[], const char* argv[]);
 
+  // Output log message to stderr if the current verbosity is set
+  // at or above the given verbosity.
+  void VALog(Verbosity verbosity, const char *fmt, va_list args);
+
   // Called whenever the in-browser window changes size, it will pass a
   // context change request to whichever thread is handling rendering.
   virtual void DidChangeView(const pp::View& view);
@@ -133,4 +140,3 @@ class PSInstance : public pp::Instance, pp::MouseLock, pp::Graphics3DClient {
 };
 
 #endif  // PPAPI_MAIN_PS_INSTANCE_H_
-
diff --git a/native_client_sdk/src/libraries/ppapi_simple/ps_interface.h b/native_client_sdk/src/libraries/ppapi_simple/ps_interface.h
index 16ecdc0..9607b1a 100644
--- a/native_client_sdk/src/libraries/ppapi_simple/ps_interface.h
+++ b/native_client_sdk/src/libraries/ppapi_simple/ps_interface.h
@@ -2,7 +2,6 @@
  * Use of this source code is governed by a BSD-style license that can be
  * found in the LICENSE file. */
 
-
 #ifndef PPAPI_SIMPLE_PS_INTERFACE_H_
 #define PPAPI_SIMPLE_PS_INTERFACE_H_
 
@@ -68,4 +67,5 @@ const PPB_WebSocket* PSInterfaceWebSocket();
 void PSInterfaceInit();
 
 EXTERN_C_END
-#endif  /* PPAPI_SIMPLE_PS_INTERFACE_H */
\ No newline at end of file
+
+#endif  /* PPAPI_SIMPLE_PS_INTERFACE_H */
diff --git a/native_client_sdk/src/libraries/ppapi_simple/ps_main.h b/native_client_sdk/src/libraries/ppapi_simple/ps_main.h
index c37ac5d..9e18edf 100644
--- a/native_client_sdk/src/libraries/ppapi_simple/ps_main.h
+++ b/native_client_sdk/src/libraries/ppapi_simple/ps_main.h
@@ -1,6 +1,6 @@
-// Copyright (c) 2012 The Chromium Authors. All rights reserved.
-// Use of this source code is governed by a BSD-style license that can be
-// found in the LICENSE file.
+/* Copyright (c) 2012 The Chromium Authors. All rights reserved.
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file. */
 
 #ifndef PPAPI_SIMPLE_PS_MAIN_H_
 #define PPAPI_SIMPLE_PS_MAIN_H_
@@ -34,5 +34,4 @@ void* PSMainCreate(PP_Instance inst, PSMainFunc_t func, const char **argv);
 
 EXTERN_C_END
 
-#endif  /* PPAPI_SIMPLE_PPAPI_SIMPLE_MAIN_H_ */
-
+#endif  /* PPAPI_SIMPLE_PS_MAIN_H_ */
diff --git a/native_client_sdk/src/tools/create_html.py b/native_client_sdk/src/tools/create_html.py
index c0d1eb4..8634d4a 100755
--- a/native_client_sdk/src/tools/create_html.py
+++ b/native_client_sdk/src/tools/create_html.py
@@ -136,6 +136,8 @@ def CreateHTML(filenames, options):
     cmd = [create_nmf, '-s', staging, '-o', nmf] + filenames
     if options.verbose:
       cmd.append('-v')
+    if options.debug_libs:
+      cmd.append('--debug-libs')
     Log(cmd)
     try:
       subprocess.check_call(cmd)
@@ -158,6 +160,8 @@ def main(argv):
   parser = optparse.OptionParser(usage, description=description, epilog=epilog)
   parser.add_option('-v', '--verbose', action='store_true',
                     help='Verbose output')
+  parser.add_option('-d', '--debug-libs', action='store_true',
+                    help='When calling create_nmf request debug libaries')
   parser.add_option('-o', '--output', dest='output',
                     help='Name of html file to write (default is '
                          'input name with .html extension)',
diff --git a/native_client_sdk/src/tools/nacl_gcc.mk b/native_client_sdk/src/tools/nacl_gcc.mk
index d7edbbe..b03251c 100644
--- a/native_client_sdk/src/tools/nacl_gcc.mk
+++ b/native_client_sdk/src/tools/nacl_gcc.mk
@@ -382,6 +382,7 @@ ARCH_SUFFIXES := $(foreach arch,$(ARCHES),_$(arch).nexe)
 NMF := python $(NACL_SDK_ROOT)/tools/create_nmf.py
 ifeq ($(CONFIG),Debug)
 NMF_FLAGS += --debug-libs
+HTML_FLAGS += --debug-libs
 endif
 
 EXECUTABLES=$(foreach arch,$(ARCH_SUFFIXES),$(OUTDIR)/$(1)$(arch)) $(GLIBC_SO_LIST)
@@ -400,5 +401,5 @@ CREATE_HTML := python $(NACL_SDK_ROOT)/tools/create_html.py
 define HTML_RULE
 all: $(OUTDIR)/$(1).html
 $(OUTDIR)/$(1).html: $(EXECUTABLES)
-	$(call LOG,CREATE_HTML,$$@,$(CREATE_HTML) -o $$@ $$^)
+	$(call LOG,CREATE_HTML,$$@,$(CREATE_HTML) $(HTML_FLAGS) -o $$@ $$^)
 endef