Merge pull request #2849 from cevich/timestamps

Cirrus: timestamp all output script output

8 files changed, 55 insertions, 67 deletions

diff --git a/.cirrus.yml b/.cirrus.yml
index 6ab8beda3..0745b1e7b 100644
--- a/.cirrus.yml
+++ b/.cirrus.yml
@@ -23,6 +23,9 @@ env:
     SCRIPT_BASE: "./contrib/cirrus"
     PACKER_BASE: "./contrib/cirrus/packer"
     CIRRUS_CLONE_DEPTH: 200
+    # Command to prefix every output line with a timestamp
+    # (can't do inline awk script, Cirrus-CI or YAML mangles quoting)
+    TIMESTAMP: "awk --file ${CIRRUS_WORKING_DIR}/${SCRIPT_BASE}/timestamp.awk"
 
     ####
     #### Cache-image names to test with
@@ -121,21 +124,24 @@ gating_task:
 
     gate_script:
         # N/B: entrypoint.sh resets $GOSRC (same as make clean)
-        - '/usr/local/bin/entrypoint.sh install.tools'
-        - '/usr/local/bin/entrypoint.sh validate'
-        - '/usr/local/bin/entrypoint.sh lint'
-        - '${CIRRUS_WORKING_DIR}/${SCRIPT_BASE}/test/test_dot_cirrus_yaml.py'
+        - '/usr/local/bin/entrypoint.sh install.tools |& ${TIMESTAMP}'
+        - '/usr/local/bin/entrypoint.sh validate |& ${TIMESTAMP}'
+        - '/usr/local/bin/entrypoint.sh lint |& ${TIMESTAMP}'
+        - '${CIRRUS_WORKING_DIR}/${SCRIPT_BASE}/test/test_dot_cirrus_yaml.py |& ${TIMESTAMP}'
 
     # This task builds Podman with different buildtags to ensure the build does
     # not break.  It also verifies all sub-commands have man pages.
     build_script:
-        - '/usr/local/bin/entrypoint.sh podman'
-        - 'cd $GOSRC && ./hack/podman-commands.sh'
+        - '/usr/local/bin/entrypoint.sh podman |& ${TIMESTAMP}'
+        - 'cd $GOSRC && ./hack/podman-commands.sh |& ${TIMESTAMP}'
         # N/B: need 'clean' so some commited files are re-generated.
-        - '/usr/local/bin/entrypoint.sh clean podman-remote'
-        - '/usr/local/bin/entrypoint.sh clean podman BUILDTAGS="exclude_graphdriver_devicemapper selinux seccomp"'
-        - '/usr/local/bin/entrypoint.sh podman-remote-darwin'
-        - '/usr/local/bin/entrypoint.sh podman-remote-windows'
+        - '/usr/local/bin/entrypoint.sh clean podman-remote |& ${TIMESTAMP}'
+        - '/usr/local/bin/entrypoint.sh clean podman BUILDTAGS="exclude_graphdriver_devicemapper selinux seccomp" |& ${TIMESTAMP}'
+        - '/usr/local/bin/entrypoint.sh podman-remote-darwin |& ${TIMESTAMP}'
+        - '/usr/local/bin/entrypoint.sh podman-remote-windows |& ${TIMESTAMP}'
+
+    # Verify expected bash environment (-o pipefail)
+    pipefail_enabledscript: 'if /bin/false | /bin/true; then echo "pipefail fault" && exit 72; fi'
 
     on_failure:
         failed_master_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_master_failure.sh'
@@ -162,12 +168,12 @@ vendor_task:
     timeout_in: 30m
 
     vendor_script:
-        - '/usr/local/bin/entrypoint.sh .install.vndr'
-        - '/usr/local/bin/entrypoint.sh vendor'
-        - 'cd /go/src/github.com/containers/libpod && ./hack/tree_status.sh'
+        - '/usr/local/bin/entrypoint.sh .install.vndr |& ${TIMESTAMP}'
+        - '/usr/local/bin/entrypoint.sh vendor |& ${TIMESTAMP}'
+        - 'cd /go/src/github.com/containers/libpod && ./hack/tree_status.sh |& ${TIMESTAMP}'
 
     on_failure:
-        failed_master_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_master_failure.sh'
+        failed_master_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_master_failure.sh |& ${TIMESTAMP}'
 
 
 build_each_commit_task:
@@ -188,10 +194,10 @@ build_each_commit_task:
 
     timeout_in: 30m
 
-    setup_environment_script: '$SCRIPT_BASE/setup_environment.sh'
+    setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}'
     build_each_commit_script:
-        - 'git fetch --depth $CIRRUS_CLONE_DEPTH origin $CIRRUS_BASE_BRANCH'
-        - 'env GOPATH=/var/tmp/go/ make build-all-new-commits GIT_BASE_BRANCH=origin/$CIRRUS_BASE_BRANCH'
+        - 'git fetch --depth $CIRRUS_CLONE_DEPTH origin $CIRRUS_BASE_BRANCH |& ${TIMESTAMP}'
+        - 'env GOPATH=/var/tmp/go/ make build-all-new-commits GIT_BASE_BRANCH=origin/$CIRRUS_BASE_BRANCH |& ${TIMESTAMP}'
 
     on_failure:
         failed_master_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_master_failure.sh'
@@ -218,7 +224,7 @@ meta_task:
         GCPPROJECT: ENCRYPTED[7c80e728e046b1c76147afd156a32c1c57d4a1ac1eab93b7e68e718c61ca8564fc61fef815952b8ae0a64e7034b8fe4f]
         CIRRUS_CLONE_DEPTH: 1  # source not used
 
-    script: '/usr/local/bin/entrypoint.sh'
+    script: '/usr/local/bin/entrypoint.sh |& ${TIMESTAMP}'
 
 
 # This task does the unit and integration testing for every platform
@@ -251,9 +257,9 @@ testing_task:
 
     # Every *_script runs in sequence, for each task. The name prefix is for
     # WebUI reference.  The values may be strings...
-    setup_environment_script: '$SCRIPT_BASE/setup_environment.sh'
-    unit_test_script: '$SCRIPT_BASE/unit_test.sh'
-    integration_test_script: '$SCRIPT_BASE/integration_test.sh'
+    setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}'
+    unit_test_script: '$SCRIPT_BASE/unit_test.sh |& ${TIMESTAMP}'
+    integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP}'
     audit_log_script: 'cat /var/log/audit/audit.log || cat /var/log/kern.log'
     journalctl_b_script: 'journalctl -b'
 
@@ -287,8 +293,8 @@ special_testing_task:
 
     timeout_in: 120m
 
-    setup_environment_script: '$SCRIPT_BASE/setup_environment.sh'
-    integration_test_script: '$SCRIPT_BASE/integration_test.sh'
+    setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}'
+    integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP}'
     audit_log_script: 'cat /var/log/audit/audit.log || cat /var/log/kern.log'
     journalctl_b_script: 'journalctl -b'
 
@@ -323,8 +329,8 @@ optional_testing_task:
 
     timeout_in: 60m
 
-    setup_environment_script: '$SCRIPT_BASE/setup_environment.sh'
-    system_test_script: '$SCRIPT_BASE/system_test.sh'
+    setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}'
+    system_test_script: '$SCRIPT_BASE/system_test.sh |& ${TIMESTAMP}'
 
 
 # Build new cache-images for future PR testing, but only after a PR merge.
@@ -357,8 +363,8 @@ cache_images_task:
         scopes:
             - compute
             - devstorage.full_control
-    environment_script: '$SCRIPT_BASE/setup_environment.sh'
-    build_vm_images_script: '$SCRIPT_BASE/build_vm_images.sh'
+    environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}'
+    build_vm_images_script: '$SCRIPT_BASE/build_vm_images.sh |& ${TIMESTAMP}'
 
     # TODO,Continuous Delivery: Automatically open a libpod PR after using 'sed' to replace
     #                           the image_names with the new (just build) images.  That will
@@ -372,7 +378,7 @@ cache_images_task:
     #   - commit_and_create_upstream_pr.sh
 
     on_failure:
-        failed_master_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_master_failure.sh'
+        failed_master_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_master_failure.sh |& ${TIMESTAMP}'
 
 
 # Post message to IRC if everything passed
@@ -395,4 +401,4 @@ success_task:
         cpu: 1
         memory: 1
 
-    success_script: '$SCRIPT_BASE/success.sh'
+    success_script: '$SCRIPT_BASE/success.sh |& ${TIMESTAMP}'
diff --git a/contrib/cirrus/build_vm_images.sh b/contrib/cirrus/build_vm_images.sh
index fc8cbb404..43eb3c057 100755
--- a/contrib/cirrus/build_vm_images.sh
+++ b/contrib/cirrus/build_vm_images.sh
@@ -5,8 +5,6 @@ source $(dirname $0)/lib.sh
 
 req_env_var CNI_COMMIT CRIO_COMMIT RUNC_COMMIT PACKER_BUILDS BUILT_IMAGE_SUFFIX CENTOS_BASE_IMAGE UBUNTU_BASE_IMAGE FEDORA_BASE_IMAGE FAH_BASE_IMAGE RHEL_BASE_IMAGE RHSM_COMMAND SERVICE_ACCOUNT GCE_SSH_USERNAME GCP_PROJECT_ID PACKER_VER SCRIPT_BASE PACKER_BASE
 
-record_timestamp "cache-image build start"
-
 show_env_vars
 
 # Everything here is running on the 'image-builder-image' GCE image
@@ -43,8 +41,6 @@ make libpod_images \
     POST_MERGE_BUCKET_SUFFIX=$POST_MERGE_BUCKET_SUFFIX \
     BUILT_IMAGE_SUFFIX=$BUILT_IMAGE_SUFFIX
 
-record_timestamp "cache-image build end"
-
 # When successful, upload manifest of produced images using a filename unique
 # to this build.
 URI="gs://packer-import${POST_MERGE_BUCKET_SUFFIX}/manifest${BUILT_IMAGE_SUFFIX}.json"
diff --git a/contrib/cirrus/integration_test.sh b/contrib/cirrus/integration_test.sh
index 71223803c..5b73f0c6c 100755
--- a/contrib/cirrus/integration_test.sh
+++ b/contrib/cirrus/integration_test.sh
@@ -5,14 +5,6 @@ source $(dirname $0)/lib.sh
 
 req_env_var GOSRC SCRIPT_BASE OS_RELEASE_ID OS_RELEASE_VER CONTAINER_RUNTIME
 
-exit_handler() {
-    set +ex
-    record_timestamp "integration test end"
-}
-trap exit_handler EXIT
-
-record_timestamp "integration test start"
-
 cd "$GOSRC"
 
 if [[ "$SPECIALMODE" == "in_podman" ]]
diff --git a/contrib/cirrus/lib.sh b/contrib/cirrus/lib.sh
index 1c459ebc7..f422fe935 100644
--- a/contrib/cirrus/lib.sh
+++ b/contrib/cirrus/lib.sh
@@ -17,7 +17,6 @@ PACKER_BASE=${PACKER_BASE:-./contrib/cirrus/packer}
 CIRRUS_BUILD_ID=${CIRRUS_BUILD_ID:-DEADBEEF}  # a human
 CIRRUS_BASE_SHA=${CIRRUS_BASE_SHA:-HEAD}
 CIRRUS_CHANGE_IN_REPO=${CIRRUS_CHANGE_IN_REPO:-FETCH_HEAD}
-TIMESTAMPS_FILEPATH="${TIMESTAMPS_FILEPATH:-/var/tmp/timestamps}"
 SPECIALMODE="${SPECIALMODE:-none}"
 export CONTAINER_RUNTIME=${CONTAINER_RUNTIME:-podman}
 
@@ -153,16 +152,6 @@ ircmsg() {
     set -e
 }
 
-record_timestamp() {
-    set +x  # sometimes it's turned on
-    req_env_var TIMESTAMPS_FILEPATH
-    echo "."  # cirrus webui strips blank-lines
-    STAMPMSG="The $1 time at the tone will be:"
-    echo -e "$STAMPMSG\t$(date --iso-8601=seconds)" | \
-        tee -a $TIMESTAMPS_FILEPATH
-    echo -e "BLEEEEEEEEEEP!\n."
-}
-
 setup_rootless() {
     req_env_var ROOTLESS_USER GOSRC ENVLIB
 
@@ -203,9 +192,6 @@ setup_rootless() {
         echo "${ROOTLESS_USER}:$[ROOTLESS_UID * 100]:65536" | \
             tee -a /etc/subuid >> /etc/subgid
 
-    echo "Setting permissions on automation files"
-    chmod 666 "$TIMESTAMPS_FILEPATH"
-
     echo "Copying $HOME/$ENVLIB"
     install -o $ROOTLESS_USER -g $ROOTLESS_USER -m 0700 \
         "$HOME/$ENVLIB" "/home/$ROOTLESS_USER/$ENVLIB"
diff --git a/contrib/cirrus/rootless_test.sh b/contrib/cirrus/rootless_test.sh
index 2803d4318..8351214f3 100755
--- a/contrib/cirrus/rootless_test.sh
+++ b/contrib/cirrus/rootless_test.sh
@@ -19,13 +19,9 @@ export PODMAN_VARLINK_ADDRESS=unix:/tmp/podman-$(id -u)
 echo "."
 echo "Hello, my name is $USER and I live in $PWD can I be your friend?"
 
-record_timestamp "rootless test start"
-
 cd "$GOSRC"
 make
 make varlink_generate
 make test-binaries
 make ginkgo
 make ginkgo-remote
-
-record_timestamp "rootless test end"
diff --git a/contrib/cirrus/setup_environment.sh b/contrib/cirrus/setup_environment.sh
index 3bc6c2290..2f9b1d796 100755
--- a/contrib/cirrus/setup_environment.sh
+++ b/contrib/cirrus/setup_environment.sh
@@ -4,8 +4,6 @@ set -e
 
 source $(dirname $0)/lib.sh
 
-record_timestamp "env. setup start"
-
 req_env_var USER HOME ENVLIB SCRIPT_BASE CIRRUS_BUILD_ID
 
 [[ "$SHELL" =~ "bash" ]] || chsh -s /bin/bash
@@ -86,5 +84,3 @@ then
 fi
 
 show_env_vars
-
-record_timestamp "env. setup end"
diff --git a/contrib/cirrus/timestamp.awk b/contrib/cirrus/timestamp.awk
new file mode 100644
index 000000000..95b312e51
--- /dev/null
+++ b/contrib/cirrus/timestamp.awk
@@ -0,0 +1,20 @@
+
+
+# This script is intended to be piped into by automation, in order to
+# mark output lines with timing information.  For example:
+#      /path/to/command |& awk --file timestamp.awk
+
+BEGIN {
+    STARTTIME=systime()
+    printf "[%s] START", strftime("%T")
+    printf " - All [+xxxx] lines that follow are relative to right now.\n"
+}
+
+{
+    printf "[%+05ds] %s\n", systime()-STARTTIME, $0
+}
+
+END {
+    printf "[%s] END", strftime("%T")
+    printf " - [%+05ds] total duration since START\n", systime()-STARTTIME
+}
diff --git a/contrib/cirrus/unit_test.sh b/contrib/cirrus/unit_test.sh
index a0964061f..0e8c9e2e2 100755
--- a/contrib/cirrus/unit_test.sh
+++ b/contrib/cirrus/unit_test.sh
@@ -5,8 +5,6 @@ source $(dirname $0)/lib.sh
 
 req_env_var GOSRC OS_RELEASE_ID OS_RELEASE_VER
 
-record_timestamp "unit test start"
-
 clean_env
 
 set -x
@@ -14,5 +12,3 @@ cd "$GOSRC"
 make install.tools
 make localunit
 make
-
-record_timestamp "unit test end"