BK: Make logs less noisy and add timestamps (#2317)

- Add timestamps to acceptance test output to better understand their performance.
- Better log collection on CI

.buildkite/common.sh

@@ -21,3 +21,4 @@ echo "  SCION_IMG: $REGISTRY/scion_ci:${BUILDKITE_BUILD_NUMBER}"
 echo "  ARTIFACTS: buildkite.${BUILDKITE_ORGANIZATION_SLUG}.${TARGET}.${BUILD}"
 echo "  BASE: $BASE"
 echo "  REGISTRY: $REGISTRY"
+echo "  STEP_LOG: artifacts.out/step.log"

.buildkite/run_step

@@ -1,24 +1,21 @@
 #!/bin/bash
 
-$BASE/scripts/clean_env
-echo "Running: ${1:?}"
+. $BASE/steps/common.sh
 
-# Pull CI image and start it
-$BASE/scripts/registry_login
-docker pull $SCION_IMG &>/dev/null
-mkdir -p $SCION_MOUNT
-./docker.sh start
+log "Prepare environment: Start"
+prepare
+log "Prepare environment: Done"
+
+# Start runner container
+./docker.sh start &>> "$STEP_LOG"
 
 # Run test
+log "Running: ${1:?}"
 ./tools/ci/"$@"
 res=$?
 
-# Pack logs and stop everything
-$BASE/scripts/pack_logs
-res=$((res+$?))
-./docker.sh stop
-res=$((res+$?))
-$BASE/scripts/clean_env
+log "Cleanup environment: Start"
+cleanup
 res=$((res+$?))
-rm -r $SCION_MOUNT
+log "Cleanup environment: Done"
 exit $res

.buildkite/scripts/all_images

@@ -1,15 +1,18 @@
 #!/bin/bash
 
+. $BASE/steps/common.sh
+
 set -eu
 
 TAG="$BUILDKITE_BUILD_NUMBER"
 
-$BASE/scripts/registry_login
+$BASE/scripts/registry_login &>/dev/null
 
 images="border dispatcher sig beacon_py cert cert_py path path_py sciond sciond_py tester sig_acceptance"
 
 if [ "${1:?}" == "push" ]; then
     # Tag local apps and push to remote
+    log "Push images"
     for app in $images; do
         local_img="scion_$app"
         remote_img="$REGISTRY/$app"
@@ -19,6 +22,7 @@ if [ "${1:?}" == "push" ]; then
 fi
 if [ "$1" == "pull" ]; then
     # Pull images
+    log "Pull images"
     for app in $images; do
         local_img="scion_$app"
         remote_img="$REGISTRY/$app"

.buildkite/steps/common.sh

@@ -0,0 +1,22 @@
+log() {
+    echo "$(date -u +"%F %T.%6N%z") $@"
+}
+
+prepare() {
+    mkdir -p "artifacts.out"
+    $BASE/scripts/clean_env &>> "$STEP_LOG"
+    $BASE/scripts/registry_login &>> "$STEP_LOG"
+    docker pull $SCION_IMG &>/dev/null
+    mkdir -p $SCION_MOUNT
+}
+
+cleanup() {
+    $BASE/scripts/pack_logs &>> "$STEP_LOG"
+    local res=$?
+    ./docker.sh stop &>> "$STEP_LOG"
+    res=$((res+$?))
+    $BASE/scripts/clean_env &>> "$STEP_LOG"
+    res=$((res+$?))
+    rm -r $SCION_MOUNT
+    return $res
+}

.buildkite/steps/host_acceptance

@@ -1,42 +1,43 @@
 #!/bin/bash
 
+. $BASE/steps/common.sh
+
 run_wrapper() {
     PHASE=${1:?}
     shift
-    if $@; then
-        echo "$PHASE successful"
+    log "Start $PHASE"
+    "$@" &>> "$STEP_LOG"
+    if [ $? -eq 0 ]; then
+        log "$PHASE successful"
         return 0
     else
-        echo "$PHASE failed"
+        log "$PHASE failed"
         return 1
     fi
 }
 
-$BASE/scripts/clean_env
-echo "Running: ${1:?}"
+log "Prepare environment: Start"
+prepare
+log "Prepare environment: Done"
 
-# Pull CI image and start it
-docker pull $SCION_IMG &>/dev/null
-mkdir -p $SCION_MOUNT
+# Start runner container
 mkdir -p $ACCEPTANCE_ARTIFACTS
-./docker.sh start
+./docker.sh start &>> "$STEP_LOG"
 
 # Run test
-run_wrapper "SETUP" "$1/test setup &>> $ACCEPTANCE_ARTIFACTS/setup.out"
+log "Starting ${1:?}"
+run_wrapper SETUP $1/test setup
 res=$?
-run_wrapper "RUN" "./docker.sh exec $1/test run &>> \$ACCEPTANCE_ARTIFACTS/run.out"
+run_wrapper RUN ./docker.sh exec $1/test run '&>>' \$ACCEPTANCE_ARTIFACTS/run.out
 res=$((res+$?))
-run_wrapper "TEARDOWN" "$1/test teardown &>> $ACCEPTANCE_ARTIFACTS/teardown.out"
+run_wrapper TEARDOWN $1/test teardown
 res=$((res+$?))
+log "Finished: $1"
 
-# Pack logs and stop everything
+log "Cleanup environment: Start"
 cp -r logs "$SCION_MOUNT"
 res=$((res+$?))
-$BASE/scripts/pack_logs
-res=$((res+$?))
-./docker.sh stop
-res=$((res+$?))
-$BASE/scripts/clean_env
+cleanup
 res=$((res+$?))
-rm -r $SCION_MOUNT
+log "Cleanup environment: Done"
 exit $res

acceptance/brutil/common.sh

@@ -13,7 +13,7 @@ test_setup() {
     sudo -p "Setup docker containers and virtual interfaces - [sudo] password for %p: " true
     # Bring up the dispatcher container and add new veth interfaces
     # This approach currently works because the dispatcher binds to 0.0.0.0 address.
-    docker-compose -f ${BRUTIL:?}/docker-compose.yml up --detach dispatcher
+    docker-compose -f ${BRUTIL:?}/docker-compose.yml --no-ansi up --detach dispatcher
 
     set_docker_ns_link
 
@@ -25,7 +25,7 @@ test_setup() {
     sed -i "s/ID = .*$/ID = \"${BRID}\"/g" "$TEST_ARTIFACTS_DIR/conf/brconfig.toml"
     sed -i "s/Path = .*$/Path = \"\/share\/logs\/${BRID}.log\"/g" "$TEST_ARTIFACTS_DIR/conf/brconfig.toml"
 
-    docker-compose -f $BRUTIL/docker-compose.yml up --detach $BRID
+    docker-compose -f $BRUTIL/docker-compose.yml --no-ansi up --detach $BRID
 }
 
 test_run() {
@@ -40,7 +40,7 @@ test_teardown() {
     del_veths
     rm -f $DEVINFO_FN
     rm_docker_ns_link
-    docker-compose -f $BRUTIL/docker-compose.yml down
+    docker-compose -f $BRUTIL/docker-compose.yml --no-ansi down
 }
 
 print_help() {

tools/ci/integration

@@ -54,7 +54,7 @@ if [ -n "$DOCKER_BE" ]; then
     ./docker.sh exec "set -eo pipefail; ./tools/dc start tester* |& tee -a logs/integration.run"
 fi
 
-sleep 15
+sleep 20
 
 COMMAND="$1"
 shift