| #!/bin/bash |
| # |
| # Copyright 2016 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. |
| # |
| # This test exercises action progress reporting. |
| |
| # Load the test setup defined in the parent directory |
| 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; } |
| |
| set -eu |
| |
| # TODO(b/37617303): make tests UI-independent |
| add_to_bazelrc "build --noexperimental_ui" |
| add_to_bazelrc "build --workspace_status_command="$(which true)" --nostamp" |
| add_to_bazelrc "build --show_progress_rate_limit=-1" |
| add_to_bazelrc "build --genrule_strategy=local" |
| |
| # Match progress messages like [42 / 1,337] |
| declare -r PROGRESS_RX="\[[0-9, /]\+\]" |
| |
| # Run a command with a timeout, kill it if too slow or hanging. |
| # |
| # To avoid timing out in the case of blocking commands that never return, this |
| # wrapper will start the command, wait the specified number of seconds, and |
| # then kill the command and return an error. The caller can then fail the test. |
| # |
| # This function does not fail directly because it would have no effect if run in |
| # a subshell (unless with -e). |
| function wait_for_command() { |
| local -r wait_time="$1" |
| shift 1 |
| ($@) & |
| local -r pid="$!" |
| for i in $(seq 1 $wait_time); do |
| # kill -0 checks to see if the process is still alive. If it is, kill |
| # succeeds and we sleep. If it's not, kill fails and we return. |
| kill -0 "$pid" >& /dev/null || return 0 |
| sleep 1 |
| done |
| kill -9 "$pid" |
| # A fail() here would not end the script if we are in a subshell, so the |
| # caller must check the return value. |
| echo "Command $@ did not die within $wait_time seconds" |
| return 1 |
| } |
| |
| function test_respects_progress_interval() { |
| local -r pkg="${FUNCNAME[0]}" |
| mkdir "$pkg" || fail "mkdir $pkg" |
| |
| local -r MATCHER="Executing genrule //${pkg}:x, [0-9] s" |
| |
| cat >"${pkg}/BUILD" <<'EOF' |
| genrule( |
| name = "x", |
| outs = ["y"], |
| cmd = "sleep 5; touch $@", |
| ) |
| EOF |
| |
| bazel build "//${pkg}:x" --progress_report_interval=1 --curses=no --color=no \ |
| >& "$TEST_log" || fail "Expected success" |
| |
| # Do not assert exactly how much time elapsed between "Still waiting" messages |
| # or even whether there were more than one at all. Just assert there was at |
| # least one message. |
| # Logging these messages appears to be a low priority process in bazel and |
| # they are not always reported in a timely manner. |
| expect_log "$MATCHER" |
| } |
| |
| function assert_show_task_finish() { |
| local -r show="$1" # either "show" or "noshow" |
| local -r pkg="$2" |
| |
| cat >${pkg}/BUILD <<'EOF' |
| genrule( |
| name = "x", |
| outs = ["x.out"], |
| cmd = "touch $@", |
| ) |
| EOF |
| |
| bazel build "//${pkg}:x" "--${show}_task_finish" --color=no \ |
| --curses=no --nocache_test_results >& "$TEST_log" || fail "bazel test" |
| |
| expect_log "$PROGRESS_RX Executing genrule //${pkg}:x" |
| if [ "$show" == "show" ]; then |
| expect_log "$PROGRESS_RX Executing genrule //${pkg}:x DONE" |
| else |
| # Negative matching should be as permissive as possible. |
| expect_not_log "DONE" |
| fi |
| } |
| |
| function test_show_task_finish() { |
| local -r pkg="${FUNCNAME[0]}" |
| mkdir "$pkg" || fail "mkdir $pkg" |
| assert_show_task_finish "show" "$pkg" |
| } |
| |
| function test_noshow_task_finish() { |
| local -r pkg="${FUNCNAME[0]}" |
| mkdir "$pkg" || fail "mkdir $pkg" |
| assert_show_task_finish "noshow" "$pkg" |
| } |
| |
| function test_action_counters_dont_account_for_actions_without_progress_msg() { |
| local -r pkg="${FUNCNAME[0]}" |
| mkdir "$pkg" || fail "mkdir $pkg" |
| |
| cat >"${pkg}/BUILD" <<'EOF' |
| genrule( |
| name = "x", |
| srcs = ["y"], |
| outs = ["x.out"], |
| cmd = "echo $< > $@", |
| ) |
| |
| genrule( |
| name = "y", |
| srcs = ["z"], |
| outs = ["y.out"], |
| cmd = "echo $< > $@", |
| ) |
| |
| genrule( |
| name = "z", |
| outs = ["z.out"], |
| cmd = "echo z > $@", |
| ) |
| EOF |
| |
| # Make the workspace_status_command slow, so it will show up in a "Still |
| # waiting" message. Do not modify the workspace status writer action |
| # implementation to have a progress message, because it breaks all kinds of |
| # things. |
| cat >"${pkg}/workspace_status.sh" <<EOF |
| #!/bin/sh |
| sleep 5 |
| EOF |
| |
| chmod +x "${pkg}/workspace_status.sh" |
| |
| bazel build "//${pkg}:x" --show_task_finish --color=no --curses=no \ |
| --workspace_status_command="${pkg}/workspace_status.sh" \ |
| --progress_report_interval=1 \ |
| >& "$TEST_log" || fail "build failed" |
| |
| # We expect a total of 4 actions but only 3 execution messages: |
| # - the 3 genrule actions and their messages |
| # - the workspace status writer action, only counted but not reported as an |
| # executed action, only as a "Still waiting" one. |
| # The counter should reflect no other actions; if it does, it's probably a |
| # bug. |
| # |
| # This used to be buggy. Prior to the bugfix the counter was accounting for 5 |
| # actions, the extra one being the target completion middleman. Since that's |
| # not a real action that the user cares about, we don't want to count it so |
| # the numbers look saner. |
| |
| # It may happen that Skyframe does not discover (enque) the workspace status |
| # writer action immediately, so the counter may initially report 3 total |
| # actions instead of 4. |
| expect_log "\[0 / [34]\] Executing genrule //${pkg}:z$" |
| expect_log "\[1 / [34]\] Executing genrule //${pkg}:z DONE$" |
| expect_log "\[1 / [34]\] Executing genrule //${pkg}:y$" |
| expect_log "\[2 / [34]\] Executing genrule //${pkg}:y DONE$" |
| expect_log "\[2 / 4\] Executing genrule //${pkg}:x$" |
| expect_log "\[3 / 4\] Executing genrule //${pkg}:x DONE$" |
| expect_log "\[3 / 4\] Still waiting for 1 job to complete:" |
| |
| # Open-source Bazel calls this file stable-status.txt, Google internal version |
| # calls it build-info.txt. |
| expect_log "\b\(stable-status\|build-info\).txt\b.*, [0-9] s" |
| } |
| |
| function test_counts_cached_actions_as_completed_ones() { |
| local -r pkg="${FUNCNAME[0]}" |
| mkdir "$pkg" || fail "mkdir $pkg" |
| |
| # DO NOT use cmd="touch $@". The genrules would produce empty files, which are |
| # compared by time stamp rather than content (since they are empty), so change |
| # pruning won't kick in and this test won't work. |
| cat >"${pkg}/BUILD" <<'EOF' |
| genrule( |
| name = "dep1", |
| srcs = ["input"], |
| outs = ["out1"], |
| cmd = "echo foo > $@", |
| ) |
| |
| [genrule( |
| name = "dep%d" % i, |
| srcs = [":dep%d" % (i - 1)], |
| outs = ["out%d" % i], |
| cmd = "echo foo > $@", |
| ) for i in [2, 3, 4, 5, 6, 7]] |
| |
| genrule( |
| name = "x", |
| srcs = [ |
| "input", |
| ":dep7", |
| ], |
| outs = ["outx"], |
| cmd = "echo foo > $@", |
| ) |
| EOF |
| |
| # Run a clean then an incremental build. |
| # |
| # In the first build we should see 9 actions on the right side of the action |
| # counter (8 genrules + 1 workspace status writer), 8 DONE messages, the last |
| # one of which should be target "x". |
| # |
| # In the second build, we should again see 9 actions (9 dirtied) in the |
| # counter, but only two DONE actions (dep1 and x) due to change pruning. |
| # The last action should again be target "x", its completion index 8 or 9 (the |
| # last one might be the workspace status writer action). |
| |
| echo "input-clean" > "${pkg}/input" |
| bazel --nobatch build "//${pkg}:x" --show_task_finish --color=no --curses=no \ |
| >& "$TEST_log" || fail "build failed" |
| expect_log_once "\[[89] / 9\] Executing genrule //${pkg}:x DONE" |
| expect_log_n "\[[1-9] / 9\] Executing genrule //${pkg}:.* DONE" 8 |
| |
| echo "input-incremental" > "${pkg}/input" |
| bazel --nobatch build "//${pkg}:x" --show_task_finish --color=no --curses=no \ |
| >& "$TEST_log" || fail "build failed" |
| expect_log_once "\[[89] / 9\] Executing genrule //${pkg}:x DONE" |
| expect_log_n "\[[1-9] / 9\] Executing genrule //${pkg}:.* DONE" 2 |
| } |
| |
| function test_failed_actions_with_keep_going() { |
| local -r pkg="${FUNCNAME[0]}" |
| mkdir "$pkg" || fail "mkdir $pkg" |
| |
| local -r dep_file="${TEST_TMPDIR}/${pkg}_dep_file" |
| cat >"${pkg}/BUILD" <<EOF |
| genrule( |
| name = "dep", |
| outs = ["dep.out"], |
| cmd = "touch $dep_file; false", |
| ) |
| |
| genrule( |
| name = "top", |
| srcs = [":dep.out"], |
| outs = ["top.out"], |
| cmd = "", |
| ) |
| |
| genrule( |
| name = "longrun", |
| outs = ["longrun.out"], |
| cmd = "while [ ! -f \"$dep_file\" ]; do " + |
| "sleep 1; done; sleep 5", |
| ) |
| EOF |
| |
| bazel build -k -s "//${pkg}:"{top,longrun} --progress_report_interval=1 \ |
| >& "$TEST_log" && fail "build succeeded" |
| expect_log "\[3 / 4\] Still waiting for 1 job to complete:" |
| expect_log "^ *Executing genrule //${pkg}:longrun" |
| } |
| |
| function test_seemingly_too_many_total_actions_due_to_change_pruning() { |
| local -r pkg="${FUNCNAME[0]}" |
| mkdir "$pkg" || fail "mkdir $pkg" |
| |
| # DO NOT use cmd="touch $@". The genrules would produce empty files, which are |
| # compared by time stamp rather than content (since they are empty), so change |
| # pruning won't kick in and this test won't work. |
| cat >"${pkg}/BUILD" <<'EOF' |
| genrule( |
| name = "dep1", |
| srcs = ["input"], |
| outs = ["out1"], |
| cmd = "echo foo > $@", |
| ) |
| |
| [genrule( |
| name = "dep%d" % i, |
| srcs = [":dep%d" % (i - 1)], |
| outs = ["out%d" % i], |
| cmd = "echo foo > $@", |
| ) for i in [2, 3, 4, 5, 6, 7]] |
| |
| genrule( |
| name = "x", |
| srcs = [":dep7"], |
| outs = ["outx"], |
| cmd = "echo foo > $@", |
| ) |
| EOF |
| |
| # Run a clean then an incremental build. |
| # |
| # In the first build we should see 9 actions on the right side of the action |
| # counter (8 genrules + 1 workspace status writer action), 8 DONE messages, |
| # the last one of which should be target "x". |
| # |
| # In the second build, we should again see 9 actions (9 dirtied) in the |
| # counter, but only two DONE actions (dep1 and x) due to change pruning. |
| # The last action should again be target "x", its completion index 8 or 9 (the |
| # last one might be the workspace status writer action). |
| echo "input-clean" > "${pkg}/input" |
| bazel --nobatch build "//${pkg}:x" --show_task_finish --color=no --curses=no \ |
| >& "$TEST_log" || fail "build failed" |
| expect_log_once "\[[89] / 9\] Executing genrule //${pkg}:x DONE" |
| expect_log_n "\[[1-9] / 9\] Executing genrule //${pkg}:.* DONE" 8 |
| |
| echo "input-incremental" > "${pkg}/input" |
| bazel --nobatch build "//${pkg}:x" --show_task_finish --color=no --curses=no \ |
| >& "$TEST_log" || fail "build failed" |
| expect_log_once "\[[12] / 9\] Executing genrule //${pkg}:dep1 DONE" |
| expect_log_once "Executing genrule .* DONE" |
| } |
| |
| function test_counts_exclusive_tests_in_total_work() { |
| local -r pkg="${FUNCNAME[0]}" |
| mkdir "$pkg" || fail "mkdir $pkg" |
| |
| cat >"${pkg}/BUILD" <<'EOF' |
| [sh_test( |
| name = "t%d" % i, |
| srcs = ["test.sh"], |
| tags = ["exclusive", "local"], |
| ) for i in [1, 2, 3]] |
| EOF |
| echo "#!$(which true)" > "${pkg}/test.sh" |
| chmod +x "${pkg}/test.sh" |
| |
| bazel test --nocache_test_results --show_task_finish \ |
| "//${pkg}:all" --color=no --curses=no >& "$TEST_log" \ |
| || fail "build failed" |
| |
| # Extract the numbers from the last [123 / 4,567] progress message. |
| local -r numbers="$(cat "$TEST_log" | grep "Testing //${pkg}:x" \ |
| | sed 's,^.*\[\([0-9, /]*\)\].*$,\1,;s|,||g;s|/| |' | sort -n | tail -n 1)" |
| local -r completed_last="$(echo "$numbers" | awk '{print $2}')" |
| local -r total="$(echo "$numbers" | awk '{print $2}')" |
| |
| assert_equals "$completed_last" "$total" |
| } |
| |
| run_suite "Tests for execution phase progress reporting" |