ENG-3011 #93 Fix trying to read ahead of the log while preparing peer…

… request

Summary:
Here is the commit message of the Kudu fix by Todd Lipcon
(apache/kudu@a8a7773).

This fixes an error which often ends up in the logs when the WAL is under a lot of load:

```
E0823 01:22:37.049101 24094 consensus_queue.cc:415] T 6ffafa79dd91459fb6a55da4b52f477d P
1a6f2219a4cc41f5803b03f8c4498f56 [LEADER]: Error trying to read ahead of the log while preparing
peer request: Incomplete: Op with index 294511 is ahead of the local log (next sequential op:
294511). Destination peer: Peer: b039d94e5c3f486e907e7567d148cf21, Is new: false, Last received:
3.294511, Next index: 294512, Last known committed idx: 294508, Last exchange result: SUCCESS, Needs
tablet copy: false
```

As described in the JIRA (https://goo.gl/J1DyhM), the issue was the following:

- in LogCache::AppendOperations, we do the following order:
  1. under lock: add new operations to the cache map
  2. outside lock: Log::AsyncAppendReplicates (which may block when under load)
  3. under lock: increase next_sequential_op_index_

- in LogCache::ReadOps(...), we do:
   1. Look for the operation in the cache.
   2. If it's a hit, iterate forward in the cache until we stop "hitting"

So the following interleaving caused the error to be loggged:

Thread 1
---------
- call LogCache::AppendOperations() with batch 10..20
- inserts 10..20 into the cache
- blocks on AsyncAppendReplicates

Thread 2
---------
- preparing a request for a follower, calls ReadOps(10)
--- results in ops 10..20 being copied into the outgoing request
- sends the request

Later, while Thread 1 is still blocked:

- response received from the peer for 10..20. 'last_replicated' = 20, so next_index = 21
- we call ReadOps(21)
--- next_sequential_op_id_ has still not advanced from 10
--- this triggers the error message indicated above

The fix, as hinted in the JIRA (https://goo.gl/J1DyhM), is to update 'next_sequential_op_index_'
before appending to the log, rather than after. This doesn't have any looser guarantees in terms of
durability, since the WAL append itself is completely asynchronous -- appending to the WAL just
enqueues the entries onto an in-memory queue and then asynchronously wakes up the background WAL
appender thread.

The new unit test crashed very rapidly without the fix with a CHECK failure showing the same
Status::Incomplete() message as expected. With the fix it runs reliably.

(end of imported commit message).

-------------------------------------------------------------------------------------------------

In addition to the above, the following enhancements are included in this revision:
- Use YB_DEFINE_ENUM for the RequestTriggerMode enum.
- Miscellaneous comment cleanup.
- A couple of UBSAN suppressions for the AWS C++ client.
- Various improvements to repeat_unit_test.sh: ability to stop on failure, time reporting.
- yb_build.sh fixes for running tests on a different host.
- Try to set unlimited core limit in `run-with-timeout.cc`.
- `remote_build.py` should not force the build type to be "debug" by default -- the default should be decided by `yb_build.sh`.

Test Plan: Jenkins

Reviewers: amitanand, venkatesh, hector, bogdan, bharat

Reviewed By: hector

Subscribers: bharat, ybase

Differential Revision: https://phabricator.dev.yugabyte.com/D4320

bin/remote_build.py

@@ -116,7 +116,7 @@ def main():
                         default=default_path,
                         help='path used for build')
     parser.add_argument('--branch', type=str, default='origin/master', help='base branch for build')
-    parser.add_argument('--build-type', type=str, default='debug', help='build type')
+    parser.add_argument('--build-type', type=str, default=None, help='build type')
     parser.add_argument('--skip-build',
                         action='store_const',
                         const=True,
@@ -138,7 +138,7 @@ def main():
     os.chdir(os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
 
     print("Host: {0}, build type: {1}, remote path: {2}".format(args.host,
-                                                                args.build_type,
+                                                                args.build_type or 'N/A',
                                                                 args.remote_path))
 
     commit = check_output_line(['git', 'merge-base', args.branch, 'HEAD'])
@@ -194,7 +194,9 @@ def main():
     if args.skip_build:
         sys.exit(0)
 
-    ybd_args = [args.build_type]
+    ybd_args = []
+    if args.build_type:
+        ybd_args.append(args.build_type)
 
     if len(args.args) != 0 and args.args[0] == '--':
         ybd_args += args.args[1:]

bin/repeat_unit_test.sh

@@ -45,6 +45,8 @@ Options:
     be allowed.
   --skip-log-compression
     Don't compress kept logs.
+  --stop-at-failure
+    Stop running further iterations after the first failure happens.
 EOT
 }
 
@@ -55,16 +57,6 @@ delete_tmp_files() {
   fi
 }
 
-store_log_file_and_report_result() {
-  if "$skip_log_compression"; then
-    test_log_stored_path="$test_log_path"
-  else
-    gzip "$test_log_path"
-    test_log_stored_path="$test_log_path.gz"
-  fi
-  echo "$1: iteration $iteration (log: $test_log_stored_path)"
-}
-
 set -euo pipefail
 
 . "${0%/*}"/../build-support/common-test-env.sh
@@ -73,7 +65,7 @@ unset TEST_TMPDIR
 
 trap delete_tmp_files EXIT
 
-script_name=${0##*/}
+script_name=${BASH_SOURCE##*/}
 script_name_no_ext=${script_name%.sh}
 skip_address_already_in_use=false
 
@@ -92,14 +84,15 @@ skip_log_compression=false
 original_args=( "$@" )
 yb_compiler_type_arg=""
 verbose=false
+stop_at_failure=false
 
 while [[ $# -gt 0 ]]; do
   if [[ ${#positional_args[@]} -eq 0 ]] && is_valid_build_type "$1"; then
     build_type=$1
     shift
     continue
   fi
-  case "$1" in
+  case ${1//_/-} in
     -h|--help)
       show_usage >&2
       exit 1
@@ -115,7 +108,7 @@ while [[ $# -gt 0 ]]; do
       parallelism=$2
       shift
     ;;
-    --log_dir)
+    --log-dir)
       # Used internally for parallel execution
       log_dir="$2"
       if [[ ! -d $log_dir ]]; then
@@ -153,6 +146,9 @@ while [[ $# -gt 0 ]]; do
       fi
       yb_compiler_type_arg="clang"
     ;;
+    --stop-at-failure)
+      stop_at_failure=true
+    ;;
     *)
       positional_args+=( "$1" )
     ;;
@@ -202,21 +198,28 @@ if [[ $rel_test_binary == $abs_test_binary_path ]]; then
         "BUILD_ROOT ('$BUILD_ROOT')"
 fi
 
+timestamp=$( get_timestamp_for_filenames )
 if [[ -z $log_dir ]]; then
-  log_dir=$HOME/logs/$script_name_no_ext/$test_binary_name/$test_filter/$(
-    get_timestamp_for_filenames
-  )
+  log_dir=$HOME/logs/$script_name_no_ext/$test_binary_name/$test_filter/$timestamp
   mkdir -p "$log_dir"
 fi
 
+# We create this file when the first failure happens.
+failure_flag_file_path="$log_dir/failure_flag"
+
 if [[ $iteration -gt 0 ]]; then
+  if "$stop_at_failure" && [[ -f $failure_flag_file_path ]]; then
+    exit
+  fi
   # One iteration with a specific "id" ($iteration).
   test_log_path_prefix=$log_dir/$iteration
   raw_test_log_path=${test_log_path_prefix}__raw.log
   test_log_path=$test_log_path_prefix.log
 
   set +e
-  export TEST_TMPDIR=/tmp/yb__${0##*/}__$RANDOM.$RANDOM.$RANDOM.$$
+  current_timestamp=$( get_timestamp_for_filenames )
+  export TEST_TMPDIR=/tmp/yb__${script_name_no_ext}_${build_type}_${current_timestamp}_\
+$RANDOM.$RANDOM.$RANDOM.$$
   mkdir -p "$TEST_TMPDIR"
   set_expected_core_dir "$TEST_TMPDIR"
   determine_test_timeout
@@ -228,6 +231,7 @@ if [[ $iteration -gt 0 ]]; then
     "$BUILD_ROOT"/bin/run-with-timeout $(( $timeout_sec + 1 )) "${test_cmd_line[@]}"
   )
 
+  declare -i start_time_sec=$( date +%s )
   (
     cd "$TEST_TMPDIR"
     if "$verbose"; then
@@ -237,7 +241,12 @@ if [[ $iteration -gt 0 ]]; then
     ( set -x; "${test_wrapper_cmd_line[@]}" ) &>"$raw_test_log_path"
   )
   exit_code=$?
+  declare -i end_time_sec=$( date +%s )
+  declare -i elapsed_time_sec=$(( $end_time_sec - $start_time_sec ))
   set -e
+  comment=""
+  keep_log=$keep_all_logs
+  pass_or_fail="PASSED"
   if ! did_test_succeed "$exit_code" "$raw_test_log_path"; then
     postprocess_test_log
     process_core_file
@@ -246,18 +255,28 @@ if [[ $iteration -gt 0 ]]; then
          egrep '\bWebserver: Could not start on address\b' "$test_log_path" >/dev/null ); then
       # TODO: perhaps we should not skip some types of errors that did_test_succeed finds in the
       # logs (ASAN/TSAN, check failures, etc.), even if we see "address already in use".
-      echo "PASSED: iteration $iteration (assuming \"Address already in use\" is a false positive)"
-      rm -f "$test_log_path"
+      comment=" [assuming \"Address already in use\" is a false positive]"
     else
-      store_log_file_and_report_result "FAILED"
+      pass_or_fail="FAILED"
+      keep_log=true
     fi
-  elif "$keep_all_logs"; then
-    postprocess_test_log
-    store_log_file_and_report_result "PASSED"
+  fi
+  if "$keep_log"; then
+    if ! "$skip_log_compression"; then
+      if [[ -f $test_log_path ]]; then
+        gzip "$test_log_path"
+      else
+        pass_or_fail="FAILED"
+        comment+=" [test log '$test_log_path' not found]"
+      fi
+      test_log_path+=".gz"
+    fi
+    comment+="; test log path: $test_log_path"
   else
-    echo "PASSED: iteration $iteration"
     rm -f "$raw_test_log_path"
   fi
+
+  echo "$pass_or_fail: iteration $iteration, $elapsed_time_sec sec$comment"
 else
   if [[ -n $yb_compiler_type_from_env ]]; then
     log "YB_COMPILER_TYPE env variable was set to '$yb_compiler_type_from_env' by the caller."
@@ -268,7 +287,8 @@ else
   elif "$verbose"; then
     log "YB_EXTRA_GTEST_FLAGS is not set"
   fi
-  # Parallel execution of many iterations
+  # Parallel execution of many iterations.
+  log "Saving repeated test execution logs to: $log_dir"
   seq 1 $num_iter | \
     xargs -P $parallelism -n 1 "$0" "${original_args[@]}" --log_dir "$log_dir" --iteration
 fi

build-support/common-build-env.sh

@@ -1179,7 +1179,7 @@ is_jenkins_master_build() {
 
 # Check if we're using an NFS partition in YugaByte's build environment.
 is_src_root_on_nfs() {
-  if [[ $YB_SRC_ROOT =~ ^/n/ ]]; then
+  if [[ $YB_SRC_ROOT =~ ^/(n|z)/ ]]; then
     return 0
   fi
   return 1

build-support/common-test-env.sh

@@ -277,7 +277,7 @@ Shared library .* loaded at address 0x[0-9a-f]+$" || true ) \
     >"$gtest_list_stderr_path.filtered"
 
   # -s tests if the given file is non-empty
-  if [ -s "$gtest_list_stderr_path.filtered" ]; then
+  if [[ -s "$gtest_list_stderr_path.filtered" ]]; then
     (
       echo
       echo "'$abs_test_binary_path' produced non-empty stderr output when run with" \
@@ -1228,6 +1228,7 @@ fix_cxx_test_name() {
       ;;
       1)
         log "Auto-correcting $cxx_test_name -> ${possible_corrections[0]}"
+        test_binary_name=$cxx_test_name
         cxx_test_name=${possible_corrections[0]}
       ;;
       *)

build-support/ubsan-suppressions.txt

@@ -9,3 +9,8 @@ alignment:snappy::internal::CompressFragment
 alignment:snappy::EmitLiteral
 alignment:snappy::EmitCopyLessThan64
 alignment:snappy::internal::CompressFragment
+
+# TODO: verify if it is OK to ignore these.
+# Tracked here: https://goo.gl/kPaUgS
+signed-integer-overflow:Aws::Utils::HashingUtils::HashString
+bool:Aws::Client::AWSAuthV4Signer::ComputeLongLivedHash