instrument basic metrics (#393)

* instrument basic metrics
* remove extraneous failure count
* better warning and failure hierarchy
* remove strict unset check to be compatible with stdlib

bin/compile

@@ -5,12 +5,12 @@
 
 set -o errexit    # always exit on error
 set -o pipefail   # don't ignore exit codes when piping output
-set -o nounset    # fail on unset variables
 unset GIT_DIR     # Avoid GIT_DIR leak from previous build steps
 
 ### Constants
 
 DEFAULT_CACHE="node_modules bower_components"
+BPLOG_PREFIX="buildpack.nodejs"
 
 ### Configure directories
 
@@ -26,8 +26,13 @@ export PATH="$BUILD_DIR/.heroku/node/bin:$BUILD_DIR/.heroku/yarn/bin":$PATH
 LOG_FILE=$(mktemp -t node-build-log.XXXXX)
 echo "" > "$LOG_FILE"
 
+STDLIB_FILE=$(mktemp -t stdlib.XXXXX)
+BUILDPACK_LOG_FILE=${BUILDPACK_LOG_FILE:-/dev/null}
+
 ### Load dependencies
 
+curl --silent --retry 5 --retry-max-time 15 'https://lang-common.s3.amazonaws.com/buildpack-stdlib/latest/stdlib.sh' > "$STDLIB_FILE"
+source "$STDLIB_FILE"
 source $BP_DIR/lib/output.sh
 source $BP_DIR/lib/json.sh
 source $BP_DIR/lib/failure.sh
@@ -91,13 +96,18 @@ install_bins() {
     warn_node_engine "$iojs_engine"
     install_iojs "$iojs_engine" "$BUILD_DIR/.heroku/node"
     echo "Using bundled npm version for iojs compatibility: `npm --version`"
+    mcount "version.iojs.$(node --version)"
   else
     warn_node_engine "$node_engine"
     install_nodejs "$node_engine" "$BUILD_DIR/.heroku/node"
     install_npm "$npm_engine" "$BUILD_DIR/.heroku/node"
+    mcount "version.node.$(node --version)"
   fi
   if $YARN; then
     install_yarn "$BUILD_DIR/.heroku/yarn" "$yarn_engine"
+    mcount "version.yarn.$(yarn --version)"
+  else
+    mcount "version.npm.$(npm --version)"
   fi
 
   warn_old_npm
@@ -127,6 +137,8 @@ restore_cache() {
   else
     echo "Skipping cache restore ($cache_status)"
   fi
+
+  mcount "cache.$cache_status"
 }
 
 header "Restoring cache"
@@ -134,6 +146,10 @@ restore_cache | output "$LOG_FILE"
 
 build_dependencies() {
   run_if_present 'heroku-prebuild'
+
+  local cache_status="$(get_cache_status)"
+  local start=$(nowms)
+
   if $YARN; then
     yarn_node_modules "$BUILD_DIR"
   elif $PREBUILD; then
@@ -142,6 +158,9 @@ build_dependencies() {
   else
     npm_node_modules "$BUILD_DIR"
   fi
+
+  mtime "modules.time.cache.$cache_status" "${start}"
+
   run_if_present 'heroku-postbuild'
   # TODO: run_if_present 'build'
 }
@@ -173,6 +192,8 @@ summarize_build() {
   if $NODE_VERBOSE; then
     list_dependencies "$BUILD_DIR"
   fi
+
+  mmeasure 'modules.size' "$(measure_size)"
 }
 
 header "Build succeeded!"

lib/cache.sh

@@ -18,9 +18,9 @@ load_signature() {
 
 get_cache_status() {
   if ! ${NODE_MODULES_CACHE:-true}; then
-    echo "disabled by config"
+    echo "disabled"
   elif [ "$(create_signature)" != "$(load_signature)" ]; then
-    echo "new runtime signature"
+    echo "new-signature"
   else
     echo "valid"
   fi

lib/dependencies.sh

+measure_size() {
+  echo "$((du -s node_modules 2>/dev/null || echo 0) | awk '{print $1}')"
+}
+
 list_dependencies() {
   local build_dir="$1"
 

lib/failure.sh

@@ -30,6 +30,7 @@ failure_message() {
 fail_invalid_package_json() {
   if ! cat ${1:-}/package.json | $JQ "." 1>/dev/null; then
     error "Unable to parse package.json"
+    mcount 'failures.parse.package-json'
     return 1
   fi
 }
@@ -54,10 +55,13 @@ warn_node_engine() {
   local node_engine=${1:-}
   if [ "$node_engine" == "" ]; then
     warning "Node version not specified in package.json" "https://devcenter.heroku.com/articles/nodejs-support#specifying-a-node-js-version"
+    mcount 'warnings.node.unspecified'
   elif [ "$node_engine" == "*" ]; then
     warning "Dangerous semver range (*) in engines.node" "https://devcenter.heroku.com/articles/nodejs-support#specifying-a-node-js-version"
+    mcount 'warnings.node.star'
   elif [ ${node_engine:0:1} == ">" ]; then
     warning "Dangerous semver range (>) in engines.node" "https://devcenter.heroku.com/articles/nodejs-support#specifying-a-node-js-version"
+    mcount 'warnings.node.greater'
   fi
 }
 
@@ -65,6 +69,7 @@ warn_prebuilt_modules() {
   local build_dir=${1:-}
   if [ -e "$build_dir/node_modules" ]; then
     warning "node_modules checked into source control" "https://blog.heroku.com/node-habits-2016#9-only-git-the-important-bits"
+    mcount 'warnings.modules.prebuilt'
   fi
 }
 
@@ -72,6 +77,7 @@ warn_missing_package_json() {
   local build_dir=${1:-}
   if ! [ -e "$build_dir/package.json" ]; then
     warning "No package.json found"
+    mcount 'warnings.no-package'
   fi
 }
 
@@ -80,12 +86,14 @@ warn_old_npm() {
   if [ "${npm_version:0:1}" -lt "2" ]; then
     local latest_npm="$(curl --silent --get --retry 5 --retry-max-time 15 https://semver.herokuapp.com/npm/stable)"
     warning "This version of npm ($npm_version) has several known issues - consider upgrading to the latest release ($latest_npm)" "https://devcenter.heroku.com/articles/nodejs-support#specifying-an-npm-version"
+    mcount 'warnings.npm.old'
   fi
 }
 
 warn_young_yarn() {
   if $YARN; then
     warning "This project was built with yarn, which is new and under development. Some projects can still be built more reliably with npm" "https://devcenter.heroku.com/articles/nodejs-support#build-behavior"
+    mcount 'warnings.yarn.young'
   fi
 }
 
@@ -93,12 +101,15 @@ warn_untracked_dependencies() {
   local log_file="$1"
   if grep -qi 'gulp: not found' "$log_file" || grep -qi 'gulp: command not found' "$log_file"; then
     warning "Gulp may not be tracked in package.json" "https://devcenter.heroku.com/articles/troubleshooting-node-deploys#ensure-you-aren-t-relying-on-untracked-dependencies"
+    mcount 'warnings.modules.untracked.gulp'
   fi
   if grep -qi 'grunt: not found' "$log_file" || grep -qi 'grunt: command not found' "$log_file"; then
     warning "Grunt may not be tracked in package.json" "https://devcenter.heroku.com/articles/troubleshooting-node-deploys#ensure-you-aren-t-relying-on-untracked-dependencies"
+    mcount 'warnings.modules.untracked.grunt'
   fi
   if grep -qi 'bower: not found' "$log_file" || grep -qi 'bower: command not found' "$log_file"; then
     warning "Bower may not be tracked in package.json" "https://devcenter.heroku.com/articles/troubleshooting-node-deploys#ensure-you-aren-t-relying-on-untracked-dependencies"
+    mcount 'warnings.modules.untracked.bower'
   fi
 }
 
@@ -106,6 +117,7 @@ warn_angular_resolution() {
   local log_file="$1"
   if grep -qi 'Unable to find suitable version for angular' "$log_file"; then
     warning "Bower may need a resolution hint for angular" "https://github.com/bower/bower/issues/1746"
+    mcount 'warnings.angular.resolution'
   fi
 }
 
@@ -113,10 +125,12 @@ warn_missing_devdeps() {
   local log_file="$1"
   if grep -qi 'cannot find module' "$log_file"; then
     warning "A module may be missing from 'dependencies' in package.json" "https://devcenter.heroku.com/articles/troubleshooting-node-deploys#ensure-you-aren-t-relying-on-untracked-dependencies"
+    mcount 'warnings.modules.missing'
     if [ "$NPM_CONFIG_PRODUCTION" == "true" ]; then
       local devDeps=$(read_json "$BUILD_DIR/package.json" ".devDependencies")
       if [ "$devDeps" != "" ]; then
         warning "This module may be specified in 'devDependencies' instead of 'dependencies'" "https://devcenter.heroku.com/articles/nodejs-support#devdependencies"
+        mcount 'warnings.modules.devdeps'
       fi
     fi
   fi
@@ -129,6 +143,7 @@ warn_no_start() {
     if [ "$startScript" == "" ]; then
       if ! [ -e "$BUILD_DIR/server.js" ]; then
         warn "This app may not specify any way to start a node process" "https://devcenter.heroku.com/articles/nodejs-support#default-web-process-type"
+        mcount 'warnings.unstartable'
       fi
     fi
   fi
@@ -138,6 +153,7 @@ warn_econnreset() {
   local log_file="$1"
   if grep -qi 'econnreset' "$log_file"; then
     warning "ECONNRESET issues may be related to npm versions" "https://github.com/npm/registry/issues/10#issuecomment-217141066"
+    mcount 'warnings.econnreset'
   fi
 }
 
@@ -146,5 +162,6 @@ warn_unmet_dep() {
   local package_manager=$(detect_package_manager)
   if grep -qi 'unmet dependency' "$log_file" || grep -qi 'unmet peer dependency' "$log_file"; then
     warn "Unmet dependencies don't fail $package_manager install but may cause runtime issues" "https://github.com/npm/npm/issues/7494"
+    mcount 'warnings.modules.unmet'
   fi
 }

test/run

@@ -54,7 +54,7 @@ testBuildWithCache() {
   cache=$(mktmpdir)
 
   compile "stable-node" $cache
-  assertCaptured "Skipping cache restore (new runtime"
+  assertCaptured "Skipping cache restore (new-signature"
   assertEquals "1" "$(ls -1 $cache/node/node_modules | grep hashish | wc -l | tr -d ' ')"
   assertCapturedSuccess
 
@@ -282,7 +282,7 @@ testSignatureInvalidation() {
 
   compile "node-0.12.7" $cache
   assertCaptured "Downloading and installing node 0.12.7"
-  assertCaptured "Skipping cache restore (new runtime"
+  assertCaptured "Skipping cache restore (new-signature"
   assertCapturedSuccess
 }