Save build metadata (#596)

Bring in the new build metadata module and add calls to store this info in the cache

bin/compile

@@ -44,6 +44,12 @@ source "$BP_DIR/lib/cache.sh"
 source "$BP_DIR/lib/dependencies.sh"
 # shellcheck source=lib/plugin.sh
 source "$BP_DIR/lib/plugin.sh"
+# shellcheck source=lib/kvstore.sh
+source "$BP_DIR/lib/kvstore.sh"
+# shellcheck source=lib/metadata.sh
+source "$BP_DIR/lib/metadata.sh"
+# shellcheck source=lib/build-data.sh
+source "$BP_DIR/lib/build-data.sh"
 
 export PATH="$BUILD_DIR/.heroku/node/bin:$BUILD_DIR/.heroku/yarn/bin":$PATH
 
@@ -68,12 +74,18 @@ handle_failure() {
 }
 trap 'handle_failure' ERR
 
+### Initalize metadata store
+bd_create "$CACHE_DIR"
+
 ### Check initial state
 
 [ -e "$BUILD_DIR/node_modules" ] && PREBUILD=true || PREBUILD=false
 [ -f "$BUILD_DIR/yarn.lock" ] && YARN=true || YARN=false
 [ -f "$BUILD_DIR/package-lock.json" ] && NPM_LOCK=true || NPM_LOCK=false
 
+### Save build info
+log_initial_state
+ 
 ### Failures that should be caught immediately
 
 fail_dot_heroku "$BUILD_DIR"
@@ -86,6 +98,7 @@ warn_missing_package_json "$BUILD_DIR"
 ### Behavior flags
 [ ! "$NEW_BUILD_SCRIPT_BEHAVIOR" ] && NEW_BUILD_SCRIPT_BEHAVIOR=$(read_json "$BUILD_DIR/package.json" ".[\"heroku-run-build-script\"]")
 warn_build_script_behavior_opt_in "$NEW_BUILD_SCRIPT_BEHAVIOR" | output "$LOG_FILE"
+log_build_script_opt_in "$NEW_BUILD_SCRIPT_BEHAVIOR"
 
 ### Compile
 
@@ -117,6 +130,10 @@ install_bins() {
   npm_engine=$(read_json "$BUILD_DIR/package.json" ".engines.npm")
   yarn_engine=$(read_json "$BUILD_DIR/package.json" ".engines.yarn")
 
+  bd_set "node-version-request" "$node_engine"
+  bd_set "npm-version-request" "$npm_engine"
+  bd_set "yarn-version-request" "$yarn_engine"
+
   if [ -n "$iojs_engine" ]; then
     echo "engines.iojs (package.json):  $iojs_engine (iojs)"
   else
@@ -141,6 +158,7 @@ install_bins() {
     monitor "install-npm-binary" install_npm "$npm_engine" "$BUILD_DIR/.heroku/node" $NPM_LOCK
     node_version="$(node --version)"
     mcount "version.node.$node_version"
+    bd_set "node-version" "$node_version"
   fi
 
   # Download yarn if there is a yarn.lock file or if the user
@@ -152,8 +170,10 @@ install_bins() {
 
   if $YARN; then
     mcount "version.yarn.$(yarn --version)"
+    bd_set "yarn-version" "$(yarn --version)"
   else
     mcount "version.npm.$(npm --version)"
+    bd_set "npm-version" "$(npm --version)"
   fi
 
   warn_old_npm
@@ -204,6 +224,7 @@ restore_cache() {
   fi
 
   mcount "cache.$cache_status"
+  bd_set "cache-status" "$cache_status"
 }
 
 restore_cache | output "$LOG_FILE"
@@ -279,6 +300,7 @@ summarize_build() {
   fi
 
   mmeasure 'modules.size' "$(measure_size)"
+  bd_set "node-modules-size" "$(measure_size)"
 }
 
 install_plugin "$BP_DIR" "$BUILD_DIR"
@@ -286,7 +308,10 @@ install_plugin "$BP_DIR" "$BUILD_DIR"
 header "Build succeeded!" | output "$LOG_FILE"
 mcount "compile"
 summarize_build | output "$LOG_FILE"
+bd_set "node-build-success" "true"
 
 warn_no_start "$BUILD_DIR"
 warn_unmet_dep "$LOG_FILE"
 warn_old_npm_lockfile $NPM_LOCK
+
+log_build_data >> "$BUILDPACK_LOG_FILE"

lib/build-data.sh

@@ -7,6 +7,8 @@ bd_create() {
   local cache_dir="$1"
   BUILD_DATA_FILE="$cache_dir/build-data/node"
   kv_create "$BUILD_DATA_FILE"
+  # make sure this doesnt grow over time
+  kv_clear "$BUILD_DATA_FILE"
 }
 
 bd_get() {

lib/cache.sh

@@ -114,10 +114,13 @@ save_default_cache_directories() {
   # bower_components
   if [[ -e "$build_dir/bower_components" ]]; then
     mcount "cache.saved-bower-components"
+    bd_set "cached-bower-components" "true"
     echo "- bower_components"
     mkdir -p "$cache_dir/node/cache/bower_components"
     cp -a "$build_dir/bower_components" "$(dirname "$cache_dir/node/cache/bower_components")"
   fi
+
+  bd_set "node-custom-cache-dirs" "false"
 }
 
 save_custom_cache_directories() {
@@ -138,4 +141,6 @@ save_custom_cache_directories() {
       echo "- $cachepath (nothing to cache)"
     fi
   done
+
+  bd_set "node-custom-cache-dirs" "true"
 }

lib/dependencies.sh

@@ -75,6 +75,11 @@ log_build_scripts() {
   heroku_postbuild=$(read_json "$build_dir/package.json" ".scripts[\"heroku-postbuild\"]")
   postinstall=$(read_json "$build_dir/package.json" ".scripts[\"heroku-postbuild\"]")
 
+  bd_set "build-script" "$build"
+  bd_set "postinstall-script" "$postinstall"
+  bd_set "heroku-prebuild-script" "$heroku_prebuild"
+  bd_set "heroku-postbuild-script" "$heroku_prebuild"
+
   if [ -n "$build" ]; then
     mcount "scripts.build"
 
@@ -139,16 +144,20 @@ yarn_prune_devdependencies() {
 
   if [ "$NODE_ENV" == "test" ]; then
     echo "Skipping because NODE_ENV is 'test'"
+    bd_set "skipped-prune" "true"
     return 0
   elif [ "$NODE_ENV" != "production" ]; then
     echo "Skipping because NODE_ENV is not 'production'"
+    bd_set "skipped-prune" "true"
     return 0
   elif [ -n "$YARN_PRODUCTION" ]; then
     echo "Skipping because YARN_PRODUCTION is '$YARN_PRODUCTION'"
+    bd_set "skipped-prune" "true"
     return 0
   else 
     cd "$build_dir" || return
     monitor "yarn-prune" yarn install --frozen-lockfile --ignore-engines --ignore-scripts --prefer-offline 2>&1
+    bd_set "skipped-prune" "false"
   fi
 }
 
@@ -199,12 +208,15 @@ npm_prune_devdependencies() {
 
   if [ "$NODE_ENV" == "test" ]; then
     echo "Skipping because NODE_ENV is 'test'"
+    bd_set "skipped-prune" "true"
     return 0
   elif [ "$NODE_ENV" != "production" ]; then
     echo "Skipping because NODE_ENV is not 'production'"
+    bd_set "skipped-prune" "true"
     return 0
   elif [ -n "$NPM_CONFIG_PRODUCTION" ]; then
     echo "Skipping because NPM_CONFIG_PRODUCTION is '$NPM_CONFIG_PRODUCTION'"
+    bd_set "skipped-prune" "true"
     return 0
   elif [ "$npm_version" == "5.3.0" ]; then
     mcount "skip-prune-issue-npm-5.3.0"
@@ -213,6 +225,7 @@ npm_prune_devdependencies() {
     echo ""
     echo "You can silence this warning by updating to at least npm 5.7.1 in your package.json"
     echo "https://devcenter.heroku.com/articles/nodejs-support#specifying-an-npm-version"
+    bd_set "skipped-prune" "true"
     return 0
   elif [ "$npm_version" == "5.6.0" ] ||
        [ "$npm_version" == "5.5.1" ] ||
@@ -227,9 +240,11 @@ npm_prune_devdependencies() {
     echo ""
     echo "You can silence this warning by updating to at least npm 5.7.1 in your package.json"
     echo "https://devcenter.heroku.com/articles/nodejs-support#specifying-an-npm-version"
+    bd_set "skipped-prune" "true"
     return 0
   else
     cd "$build_dir" || return
     monitor "npm-prune" npm prune --userconfig "$build_dir/.npmrc" 2>&1
+    bd_set "skipped-prune" "false"
   fi
 }

lib/failure.sh

@@ -513,6 +513,9 @@ warn_prebuilt_modules() {
   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'
+    bd_set "checked-in-node-modules" "true"
+  else
+    bd_set "checked-in-node-modules" "false"
   fi
 }
 

lib/metadata.sh

+#!/usr/bin/env bash
+
+log_initial_state() {
+  if "$YARN"; then
+    bd_set "node-package-manager" "yarn"
+    bd_set "has-node-lock-file" "true"
+  else
+    bd_set "node-package-manager" "npm"
+    bd_set "has-node-lock-file" "$NPM_LOCK"
+  fi
+
+  bd_set "new-build-script-opt-in" "false"
+
+  bd_set "stack" "$STACK"
+}
+
+log_build_script_opt_in() {
+  local opted_in="$1"
+  if [[ "$opted_in" = true ]]; then
+    bd_set "build-script-opt-in" "true"
+  else
+    bd_set "build-script-opt-in" "false"
+  fi
+}
\ No newline at end of file

lib/monitor.sh

@@ -58,4 +58,7 @@ monitor() {
 
   mtime "exec.$command_name.time" "${start}"
   mmeasure "exec.$command_name.memory" "$(cat "$peak_mem_output")"
+
+  bd_time "$command_name-time" "$start"
+  bd_set "$command_name-memory" "$(cat "$peak_mem_output")"
 }

test/run

@@ -1031,6 +1031,56 @@ testMemoryMetrics() {
   assertFileNotContains "measure#buildpack.nodejs.exec.heroku-postbuild.memory=" $metrics_log
 }
 
+testBuildMetaData() {
+  env_dir=$(mktmpdir)
+  local log_file=$(mktemp)
+  echo "$log_file" > $env_dir/BUILDPACK_LOG_FILE
+
+  compile "pre-post-build-scripts" "$(mktmpdir)" $env_dir
+
+  # build info
+  assertFileContains "node-package-manager=npm" $log_file
+  assertFileContains "checked-in-node-modules=false" $log_file
+  assertFileContains "has-node-lock-file=false" $log_file
+  assertFileContains "cache-status=not-found" $log_file
+  assertFileContains "node-build-success=true" $log_file
+
+  # binary versions
+  assertFileContains "node-version-request=~0.10.0" $log_file
+  assertFileContains "npm-version-request= " $log_file
+
+  # log build scripts
+  assertFileContains "heroku-prebuild-script=\"echo heroku-prebuild hook message\"" $log_file
+  assertFileContains "heroku-postbuild-script=\"echo heroku-prebuild hook message\"" $log_file
+  assertFileContains "build-script= " $log_file
+
+  # monitor calls
+  assertFileContains "install-node-binary-memory=" $log_file
+  assertFileContains "install-node-binary-time=" $log_file
+  assertFileContains "install-npm-binary-time=" $log_file
+  assertFileContains "install-npm-binary-memory=" $log_file
+  assertFileContains "heroku-prebuild-time=" $log_file
+  assertFileContains "heroku-prebuild-memory=" $log_file
+  assertFileContains "npm-install-time=" $log_file
+  assertFileContains "npm-install-memory=" $log_file
+  assertFileContains "heroku-postbuild-time=" $log_file
+  assertFileContains "heroku-postbuild-memory=" $log_file
+  assertFileContains "npm-prune-memory=" $log_file
+  assertFileContains "npm-prune-time=" $log_file
+
+  # erase the log file
+  echo "" > $log_file
+  compile "yarn" "$(mktmpdir)" $env_dir
+
+  assertFileContains "node-package-manager=yarn" $log_file
+  assertFileContains "has-node-lock-file=true" $log_file
+  assertFileContains "yarn-version-request=1.x" $log_file
+  assertFileContains "yarn-version=1." $log_file
+  assertFileContains "install-yarn-binary-memory=" $log_file
+  assertFileContains "install-yarn-binary-time=" $log_file
+  assertFileContains "node-build-success=true" $log_file
+}
+
 testBinDetectWarnings() {
   detect "slugignore-package-json"
   assertCapturedError "'package.json' listed in '.slugignore' file"