First cl for verbose workspaces (ability to log certain potentially non-hermetic events that happen as part of repository rules).

In the interest of smaller cls, adding plumbing first with the rest to follow.

Creates and posts a new EventBus message for workspace rule events (only execution for now); conditional on a flag, registers a listener to output those events.

In the future:
- Better structure for the events: will create a proto with appropriate messages and more information per event
- Add more events
- Allowing to specify log file rather than dumping to INFO
- Log levels, full or alerts only

RELNOTES: None
PiperOrigin-RevId: 203132761

11 files changed, 339 insertions, 34 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/BUILD b/src/main/java/com/google/devtools/build/lib/BUILD
index eae6943f2f..b6ffe9f48e 100644
--- a/src/main/java/com/google/devtools/build/lib/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/BUILD
@@ -24,6 +24,7 @@ filegroup(
         "//src/main/java/com/google/devtools/build/lib/buildeventstream:srcs",
         "//src/main/java/com/google/devtools/build/lib/buildeventstream/transports:srcs",
         "//src/main/java/com/google/devtools/build/lib/causes:srcs",
+        "//src/main/java/com/google/devtools/build/lib/bazel/debug:srcs",
         "//src/main/java/com/google/devtools/build/lib/clock:srcs",
         "//src/main/java/com/google/devtools/build/lib/cmdline:srcs",
         "//src/main/java/com/google/devtools/build/lib/collect/compacthashset:srcs",
@@ -720,6 +721,7 @@ java_library(
         "//src/main/java/com/google/devtools/build/lib:io",
         "//src/main/java/com/google/devtools/build/lib:packages-internal",
         "//src/main/java/com/google/devtools/build/lib:util",
+        "//src/main/java/com/google/devtools/build/lib/bazel/debug:workspace-rule-module",
         "//src/main/java/com/google/devtools/build/lib/bazel/repository/cache",
         "//src/main/java/com/google/devtools/build/lib/bazel/repository/downloader",
         "//src/main/java/com/google/devtools/build/lib/buildeventservice",
@@ -826,6 +828,7 @@ java_library(
         "//src/main/java/com/google/devtools/build/lib:skylarkinterface",
         "//src/main/java/com/google/devtools/build/lib:util",
         "//src/main/java/com/google/devtools/build/lib/actions",
+        "//src/main/java/com/google/devtools/build/lib/bazel/debug:workspace-rule-event",
         "//src/main/java/com/google/devtools/build/lib/bazel/repository/cache",
         "//src/main/java/com/google/devtools/build/lib/bazel/repository/downloader",
         "//src/main/java/com/google/devtools/build/lib/buildeventstream",
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java b/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java
index e96c815036..38a8ae77e1 100644
--- a/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java
+++ b/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java
@@ -43,6 +43,7 @@ public final class Bazel {
           com.google.devtools.build.lib.bazel.BazelWorkspaceStatusModule.class,
           com.google.devtools.build.lib.bazel.BazelDiffAwarenessModule.class,
           com.google.devtools.build.lib.bazel.BazelRepositoryModule.class,
+          com.google.devtools.build.lib.bazel.debug.WorkspaceRuleModule.class,
           com.google.devtools.build.lib.skylarkdebug.module.SkylarkDebuggerModule.class,
           com.google.devtools.build.lib.bazel.repository.RepositoryResolvedModule.class,
           com.google.devtools.build.lib.bazel.SpawnLogModule.class,
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/debug/BUILD b/src/main/java/com/google/devtools/build/lib/bazel/debug/BUILD
new file mode 100644
index 0000000000..208d4e1254
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/bazel/debug/BUILD
@@ -0,0 +1,44 @@
+# Description:
+#   Debugging helpers and modules
+package(
+    default_visibility = ["//src:__subpackages__"],
+)
+
+filegroup(
+    name = "srcs",
+    srcs = glob(["**"]),
+    visibility = [
+        "//src:__pkg__",
+        "//src/main/java/com/google/devtools/build/lib:__pkg__",
+        "//src/test/shell/bazel:__pkg__",
+    ],
+)
+
+java_library(
+    name = "workspace-rule-event",
+    srcs = ["WorkspaceRuleEvent.java"],
+    deps = [
+        "//src/main/java/com/google/devtools/build/lib:events",
+    ],
+)
+
+java_library(
+    name = "workspace-rule-module",
+    srcs = ["WorkspaceRuleModule.java"],
+    deps = [
+        ":debugging-options",
+        ":workspace-rule-event",
+        "//src/main/java/com/google/devtools/build/lib:events",
+        "//src/main/java/com/google/devtools/build/lib:runtime",
+        "//src/main/java/com/google/devtools/common/options",
+        "//third_party:guava",
+    ],
+)
+
+java_library(
+    name = "debugging-options",
+    srcs = ["DebuggingOptions.java"],
+    deps = [
+        "//src/main/java/com/google/devtools/common/options",
+    ],
+)
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/debug/DebuggingOptions.java b/src/main/java/com/google/devtools/build/lib/bazel/debug/DebuggingOptions.java
new file mode 100644
index 0000000000..2761b61d6f
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/bazel/debug/DebuggingOptions.java
@@ -0,0 +1,31 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.devtools.build.lib.bazel.debug;
+
+import com.google.devtools.common.options.Option;
+import com.google.devtools.common.options.OptionDocumentationCategory;
+import com.google.devtools.common.options.OptionEffectTag;
+import com.google.devtools.common.options.OptionsBase;
+
+/** Options for debugging and verbosity tools. */
+public final class DebuggingOptions extends OptionsBase {
+  @Option(
+      name = "experimental_workspace_rules_logging",
+      defaultValue = "null",
+      documentationCategory = OptionDocumentationCategory.LOGGING,
+      effectTags = {OptionEffectTag.UNKNOWN},
+      help = "Log certain Workspace Rules events")
+  public String workspaceRulesLogging;
+}
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/debug/WorkspaceRuleEvent.java b/src/main/java/com/google/devtools/build/lib/bazel/debug/WorkspaceRuleEvent.java
new file mode 100644
index 0000000000..059b08adae
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/bazel/debug/WorkspaceRuleEvent.java
@@ -0,0 +1,40 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+package com.google.devtools.build.lib.bazel.debug;
+
+import com.google.devtools.build.lib.events.ExtendedEventHandler.ProgressLike;
+import com.google.devtools.build.lib.events.Location;
+
+/** An event to record events happening during workspace rule resolution */
+public final class WorkspaceRuleEvent implements ProgressLike {
+  String location;
+  String description;
+
+  /**
+   * Creates a new WorkspaceRuleEvent with the given description.
+   *
+   * <p>Note: we will add more granular information as needed.
+   */
+  public WorkspaceRuleEvent(Location location, String description) {
+    this.location = location.print();
+    this.description = description;
+  }
+
+  /*
+   * @return a message to log for this event
+   */
+  public String logMessage() {
+    return location + ": " + description;
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/debug/WorkspaceRuleModule.java b/src/main/java/com/google/devtools/build/lib/bazel/debug/WorkspaceRuleModule.java
new file mode 100644
index 0000000000..bd5406d478
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/bazel/debug/WorkspaceRuleModule.java
@@ -0,0 +1,55 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+package com.google.devtools.build.lib.bazel.debug;
+
+import com.google.common.collect.ImmutableList;
+import com.google.common.eventbus.EventBus;
+import com.google.common.eventbus.Subscribe;
+import com.google.devtools.build.lib.events.Event;
+import com.google.devtools.build.lib.events.Reporter;
+import com.google.devtools.build.lib.runtime.BlazeModule;
+import com.google.devtools.build.lib.runtime.CommandEnvironment;
+import com.google.devtools.common.options.OptionsBase;
+
+/** A module for logging workspace rule events */
+public final class WorkspaceRuleModule extends BlazeModule {
+  private Reporter reporter;
+  private EventBus eventBus;
+
+  @Override
+  public void beforeCommand(CommandEnvironment env) {
+
+    reporter = env.getReporter();
+    eventBus = env.getEventBus();
+
+    if (env.getOptions() == null || env.getOptions().getOptions(DebuggingOptions.class) == null) {
+      reporter.handle(Event.error("Installation is corrupt: could not retrieve debugging options"));
+      return;
+    }
+
+    if (env.getOptions().getOptions(DebuggingOptions.class).workspaceRulesLogging != null) {
+      eventBus.register(this);
+    }
+  }
+
+  @Override
+  public Iterable<Class<? extends OptionsBase>> getCommonCommandOptions() {
+    return ImmutableList.<Class<? extends OptionsBase>>of(DebuggingOptions.class);
+  }
+
+  @Subscribe
+  public void workspaceRuleEventReceived(WorkspaceRuleEvent event) {
+    reporter.handle(Event.info(event.logMessage()));
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/repository/skylark/SkylarkRepositoryContext.java b/src/main/java/com/google/devtools/build/lib/bazel/repository/skylark/SkylarkRepositoryContext.java
index f245e1dc73..476c47c3dd 100644
--- a/src/main/java/com/google/devtools/build/lib/bazel/repository/skylark/SkylarkRepositoryContext.java
+++ b/src/main/java/com/google/devtools/build/lib/bazel/repository/skylark/SkylarkRepositoryContext.java
@@ -19,6 +19,7 @@ import com.google.common.base.Optional;
 import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableMap;
 import com.google.devtools.build.lib.actions.FileValue;
+import com.google.devtools.build.lib.bazel.debug.WorkspaceRuleEvent;
 import com.google.devtools.build.lib.bazel.repository.DecompressorDescriptor;
 import com.google.devtools.build.lib.bazel.repository.DecompressorValue;
 import com.google.devtools.build.lib.bazel.repository.cache.RepositoryCache.KeyType;
@@ -230,9 +231,14 @@ public class SkylarkRepositoryContext
 
   @Override
   public SkylarkExecutionResult execute(
-      SkylarkList<Object> arguments, Integer timeout, SkylarkDict<String, String> environment,
-      boolean quiet)
+      SkylarkList<Object> arguments,
+      Integer timeout,
+      SkylarkDict<String, String> environment,
+      boolean quiet,
+      Location location)
       throws EvalException, RepositoryFunctionException {
+    WorkspaceRuleEvent w = new WorkspaceRuleEvent(location, "Executing a command.");
+    env.getListener().post(w);
     createDirectory(outputDirectory);
     return SkylarkExecutionResult.builder(osObject.getEnvironmentVariables())
         .addArguments(arguments)
diff --git a/src/main/java/com/google/devtools/build/lib/skylarkbuildapi/repository/BUILD b/src/main/java/com/google/devtools/build/lib/skylarkbuildapi/repository/BUILD
index 52c66e945d..251d0c25bd 100644
--- a/src/main/java/com/google/devtools/build/lib/skylarkbuildapi/repository/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/skylarkbuildapi/repository/BUILD
@@ -19,6 +19,7 @@ java_library(
     name = "repository",
     srcs = glob(["*.java"]),
     deps = [
+        "//src/main/java/com/google/devtools/build/lib:events",
         "//src/main/java/com/google/devtools/build/lib:skylarkinterface",
         "//src/main/java/com/google/devtools/build/lib:syntax",
         "//src/main/java/com/google/devtools/build/lib/cmdline",
diff --git a/src/main/java/com/google/devtools/build/lib/skylarkbuildapi/repository/SkylarkRepositoryContextApi.java b/src/main/java/com/google/devtools/build/lib/skylarkbuildapi/repository/SkylarkRepositoryContextApi.java
index 09bd1760f8..698f307ba0 100644
--- a/src/main/java/com/google/devtools/build/lib/skylarkbuildapi/repository/SkylarkRepositoryContextApi.java
+++ b/src/main/java/com/google/devtools/build/lib/skylarkbuildapi/repository/SkylarkRepositoryContextApi.java
@@ -15,6 +15,7 @@
 package com.google.devtools.build.lib.skylarkbuildapi.repository;
 
 import com.google.devtools.build.lib.cmdline.Label;
+import com.google.devtools.build.lib.events.Location;
 import com.google.devtools.build.lib.skylarkbuildapi.StructApi;
 import com.google.devtools.build.lib.skylarkinterface.Param;
 import com.google.devtools.build.lib.skylarkinterface.ParamType;
@@ -197,40 +198,39 @@ public interface SkylarkRepositoryContextApi<RepositoryFunctionExceptionT extend
               + " returns an <code>exec_result</code> structure containing the output of the"
               + " command. The <code>environment</code> map can be used to override some"
               + " environment variables to be passed to the process.",
+      useLocation = true,
       parameters = {
-          @Param(
-              name = "arguments",
-              type = SkylarkList.class,
-              doc =
-                  "List of arguments, the first element should be the path to the program to "
-                      + "execute."
-          ),
-          @Param(
-              name = "timeout",
-              type = Integer.class,
-              named = true,
-              defaultValue = "600",
-              doc = "maximum duration of the command in seconds (default is 600 seconds)."
-          ),
-          @Param(
-              name = "environment",
-              type = SkylarkDict.class,
-              defaultValue = "{}",
-              named = true,
-              doc = "force some environment variables to be set to be passed to the process."
-          ),
-          @Param(
-              name = "quiet",
-              type = Boolean.class,
-              defaultValue = "True",
-              named = true,
-              doc = "If stdout and stderr should be printed to the terminal."
-          ),
-      }
-  )
+        @Param(
+            name = "arguments",
+            type = SkylarkList.class,
+            doc =
+                "List of arguments, the first element should be the path to the program to "
+                    + "execute."),
+        @Param(
+            name = "timeout",
+            type = Integer.class,
+            named = true,
+            defaultValue = "600",
+            doc = "maximum duration of the command in seconds (default is 600 seconds)."),
+        @Param(
+            name = "environment",
+            type = SkylarkDict.class,
+            defaultValue = "{}",
+            named = true,
+            doc = "force some environment variables to be set to be passed to the process."),
+        @Param(
+            name = "quiet",
+            type = Boolean.class,
+            defaultValue = "True",
+            named = true,
+            doc = "If stdout and stderr should be printed to the terminal."),
+      })
   public SkylarkExecutionResultApi execute(
-      SkylarkList<Object> arguments, Integer timeout, SkylarkDict<String, String> environment,
-      boolean quiet)
+      SkylarkList<Object> arguments,
+      Integer timeout,
+      SkylarkDict<String, String> environment,
+      boolean quiet,
+      Location location)
       throws EvalException, RepositoryFunctionExceptionT;
 
   @SkylarkCallable(
diff --git a/src/test/shell/bazel/BUILD b/src/test/shell/bazel/BUILD
index 4b9117faac..b7d28b6146 100644
--- a/src/test/shell/bazel/BUILD
+++ b/src/test/shell/bazel/BUILD
@@ -647,3 +647,10 @@ test_suite(
     ],
     visibility = ["//src/test/shell:__pkg__"],
 )
+
+sh_test(
+    name = "bazel_workspaces_test",
+    srcs = ["bazel_workspaces_test.sh"],
+    data = [":test-deps"],
+    tags = ["no_windows"],
+)
diff --git a/src/test/shell/bazel/bazel_workspaces_test.sh b/src/test/shell/bazel/bazel_workspaces_test.sh
new file mode 100755
index 0000000000..49bf897ff9
--- /dev/null
+++ b/src/test/shell/bazel/bazel_workspaces_test.sh
@@ -0,0 +1,117 @@
+#!/bin/bash
+#
+# Copyright 2018 The Bazel Authors. All rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#    http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+# Tests verbosity behavior on workspace initialization
+
+CURRENT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)"
+source "${CURRENT_DIR}/../integration_test_setup.sh" \
+  || { echo "integration_test_setup.sh not found!" >&2; exit 1; }
+
+
+function test_execute() {
+  create_new_workspace
+  cat > BUILD <<EOF
+genrule(
+   name="test",
+   srcs=["@repo//:t.txt"],
+   outs=["out.txt"],
+   cmd="echo Result > \$(location out.txt)"
+)
+EOF
+  cat >> repos.bzl <<EOF
+def _executeMe(repository_ctx):
+  repository_ctx.execute(["echo", "testing!"])
+  build_contents = "package(default_visibility = ['//visibility:public'])\n\n"
+  build_contents += "exports_files([\"t.txt\"])\n"
+  repository_ctx.file("BUILD", build_contents, False)
+  repository_ctx.file("t.txt", "HELLO!\n", False)
+
+ex_repo = repository_rule(
+  implementation = _executeMe,
+  local = True,
+)
+EOF
+  cat >> WORKSPACE <<EOF
+load("//:repos.bzl", "ex_repo")
+ex_repo(name = "repo")
+EOF
+
+  bazel build //:test --experimental_workspace_rules_logging=yes &> $TEST_log || fail "could not build //:test"
+  executes=`grep "repos.bzl:2:3: Executing a command." $TEST_log | wc -l`
+  if [ "$executes" -ne "1" ]
+  then
+    fail "Expected exactly 1 occurrence of the given command, got $executes"
+  fi
+
+  # Cached executions are not replayed
+  bazel build //:test --experimental_workspace_rules_logging=yes &> output || fail "could not build //:test"
+  cat output &> $TEST_log
+  executes=`grep "repos.bzl:2:3: Executing a command." output | wc -l`
+  if [ "$executes" -ne "0" ]
+  then
+    fail "Expected exactly 0 occurrence of the given command, got $executes"
+  fi
+}
+
+function test_reexecute() {
+  create_new_workspace
+  cat > BUILD <<EOF
+genrule(
+   name="test",
+   srcs=["@repo//:t.txt"],
+   outs=["out.txt"],
+   cmd="echo Result > \$(location out.txt)"
+)
+EOF
+  cat >> repos.bzl <<EOF
+def _executeMe(repository_ctx):
+  repository_ctx.execute(["echo", "testing!"])
+  build_contents = "package(default_visibility = ['//visibility:public'])\n\n"
+  build_contents += "exports_files([\"t.txt\"])\n"
+  repository_ctx.file("BUILD", build_contents, False)
+  repository_ctx.symlink(Label("@another//:dummy.txt"), "t.txt")
+
+ex_repo = repository_rule(
+  implementation = _executeMe,
+  local = True,
+)
+
+def _another(repository_ctx):
+  build_contents = "exports_files([\"dummy.txt\"])\n"
+  repository_ctx.file("BUILD", build_contents, False)
+  repository_ctx.file("dummy.txt", "dummy\n", False)
+
+a_repo = repository_rule(
+  implementation = _another,
+  local = True,
+)
+EOF
+  cat >> WORKSPACE <<EOF
+load("//:repos.bzl", "ex_repo")
+load("//:repos.bzl", "a_repo")
+ex_repo(name = "repo")
+a_repo(name = "another")
+EOF
+
+  bazel build //:test --experimental_workspace_rules_logging=yes &> $TEST_log || fail "could not build //:test"
+  executes=`grep "repos.bzl:2:3: Executing a command." $TEST_log | wc -l`
+  if [ "$executes" -le "2" ]
+  then
+    fail "Expected at least 2 occurrences of the given command, got $executes"
+  fi
+}
+
+run_suite "workspaces_tests"