Merge pull request #314 from marcov/silent-logs

tests: reduce the amount of log displayed

.ci/run.sh

@@ -12,4 +12,4 @@ export GOPATH="${GOPATH:-/tmp/go}"
 
 script_dir="$(dirname $(readlink -f $0))"
 
-sudo -E PATH="$PATH" bash -x "${script_dir}/../tests/test_images.sh"
+sudo -E PATH="$PATH" bash "${script_dir}/../tests/test_images.sh"

Makefile

@@ -14,7 +14,8 @@ DISTRO                ?= centos
 ROOTFS_BUILD_DEST     := $(PWD)
 IMAGES_BUILD_DEST     := $(PWD)
 DISTRO_ROOTFS         := $(ROOTFS_BUILD_DEST)/$(DISTRO)_rootfs
-DISTRO_ROOTFS_MARKER  := $(ROOTFS_BUILD_DEST)/.$(DISTRO)_rootfs.done
+ROOTFS_MARKER_SUFFIX   := _rootfs.done
+DISTRO_ROOTFS_MARKER  := $(ROOTFS_BUILD_DEST)/.$(DISTRO)$(ROOTFS_MARKER_SUFFIX)
 DISTRO_IMAGE          := $(IMAGES_BUILD_DEST)/kata-containers.img
 DISTRO_INITRD         := $(IMAGES_BUILD_DEST)/kata-containers-initrd.img
 
@@ -24,15 +25,34 @@ COMMIT_NO      := $(shell git rev-parse HEAD 2> /dev/null || true)
 COMMIT         := $(if $(shell git status --porcelain --untracked-files=no),${COMMIT_NO}-dirty,${COMMIT_NO})
 VERSION_COMMIT := $(if $(COMMIT),$(VERSION)-$(COMMIT),$(VERSION))
 
+# Set the variable to silent logs using chronic
+OSBUILDER_USE_CHRONIC :=
+
+# silent_run allows running make recipes using the chronic wrapper, so logs are
+# muted if the recipe command succeeds.
+# Arguments:
+# - Message
+# - Command to run
+ifeq (,$(OSBUILDER_USE_CHRONIC))
+  define silent_run
+    @echo $(1)
+    $(2)
+  endef
+else
+  define silent_run
+    @echo $(1) with command: $(2)
+    @chronic $(2)
+  endef
+endif
+
 ################################################################################
 
-rootfs-%: $(ROOTFS_BUILD_DEST)/.%_rootfs.done
+rootfs-%: $(ROOTFS_BUILD_DEST)/.%$(ROOTFS_MARKER_SUFFIX)
 	@ # DONT remove. This is not cancellation rule.
 
-.PRECIOUS: $(ROOTFS_BUILD_DEST)/.%_rootfs.done
+.PRECIOUS: $(ROOTFS_BUILD_DEST)/.%$(ROOTFS_MARKER_SUFFIX)
-$(ROOTFS_BUILD_DEST)/.%_rootfs.done:: rootfs-builder/%
+$(ROOTFS_BUILD_DEST)/.%$(ROOTFS_MARKER_SUFFIX):: rootfs-builder/%
-	@echo Creating rootfs for "$*"
+	$(call silent_run,Creating rootfs for "$*",$(ROOTFS_BUILDER) -o $(VERSION_COMMIT) -r $(ROOTFS_BUILD_DEST)/$*_rootfs $*)
-	$(ROOTFS_BUILDER) -o $(VERSION_COMMIT) -r $(ROOTFS_BUILD_DEST)/$*_rootfs $*
 	touch $@
 
 image-%: $(IMAGES_BUILD_DEST)/kata-containers-image-%.img
@@ -40,16 +60,14 @@ image-%: $(IMAGES_BUILD_DEST)/kata-containers-image-%.img
 
 .PRECIOUS: $(IMAGES_BUILD_DEST)/kata-containers-image-%.img
 $(IMAGES_BUILD_DEST)/kata-containers-image-%.img: rootfs-%
-	@echo Creating image based on $^
+	$(call silent_run,Creating image based on $^,$(IMAGE_BUILDER) -o $@ $(ROOTFS_BUILD_DEST)/$*_rootfs)
-	$(IMAGE_BUILDER) -o $@ $(ROOTFS_BUILD_DEST)/$*_rootfs
 
 initrd-%: $(IMAGES_BUILD_DEST)/kata-containers-initrd-%.img
 	@ # DONT remove. This is not cancellation rule.
 
 .PRECIOUS: $(IMAGES_BUILD_DEST)/kata-containers-initrd-%.img
 $(IMAGES_BUILD_DEST)/kata-containers-initrd-%.img: rootfs-%
-	@echo Creating initrd image for $*
+	$(call silent_run,Creating initrd image for $*,$(INITRD_BUILDER) -o $@ $(ROOTFS_BUILD_DEST)/$*_rootfs)
-	$(INITRD_BUILDER) -o $@ $(ROOTFS_BUILD_DEST)/$*_rootfs
 
 .PHONY: all
 all: image initrd
@@ -61,15 +79,13 @@ rootfs: $(DISTRO_ROOTFS_MARKER)
 image: $(DISTRO_IMAGE)
 
 $(DISTRO_IMAGE): $(DISTRO_ROOTFS_MARKER)
-	@echo Creating image based on "$(DISTRO_ROOTFS)"
+	$(call silent_run,Creating image based on "$(DISTRO_ROOTFS)",$(IMAGE_BUILDER) "$(DISTRO_ROOTFS)")
-	$(IMAGE_BUILDER) "$(DISTRO_ROOTFS)"
 
 .PHONY: initrd
 initrd: $(DISTRO_INITRD)
 
 $(DISTRO_INITRD): $(DISTRO_ROOTFS_MARKER)
-	@echo Creating initrd image based on "$(DISTRO_ROOTFS)"
+	$(call silent_run,Creating initrd image based on "$(DISTRO_ROOTFS)",$(INITRD_BUILDER) "$(DISTRO_ROOTFS)")
-	$(INITRD_BUILDER) "$(DISTRO_ROOTFS)"
 
 .PHONY: test
 test:
@@ -125,3 +141,12 @@ install-scripts:
 .PHONY: clean
 clean:
 	rm -rf $(DISTRO_ROOTFS_MARKER) $(DISTRO_ROOTFS) $(DISTRO_IMAGE) $(DISTRO_INITRD)
+
+# Prints the name of the variable passed as suffix to the print- target,
+# E.g., if Makefile contains:
+# MY_MAKE_VAR := foobar
+# Then:
+# $ make printf-MY_MAKE_VAR
+# Will print "foobar"
+print-%:
+	@echo $($*)

tests/test_images.sh

@@ -42,6 +42,10 @@ source ${test_config}
 typeset -A built_images
 typeset -A built_initrds
 
+# If set, show the reason why a container using the built images/initrds could
+# not be started. Needed only after all images/initrd built successfully
+typeset -A showKataRunFailure=
+
 usage()
 {
 	cat <<EOT
@@ -148,7 +152,7 @@ exit_handler()
 		rm -rf "${tmp_dir}"
 
 		# Restore the default image in config file
-		[ -n "${TRAVIS:-}" ] || chronic $mgr configure-image
+		[ -n "${TRAVIS:-}" ] || silent_run $mgr configure-image
 
 		return
 	fi
@@ -174,8 +178,7 @@ exit_handler()
 		return
 	fi
 
-	# Travis tests do not install kata
+	[ -z "${showKataRunFailure}" ] && return
-	[ -n "${TRAVIS:-}" ] && return
 
 	info "local runtime config:"
 	cat /etc/kata-containers/configuration.toml >&2
@@ -190,7 +193,7 @@ exit_handler()
 	sudo -E ps -efwww | egrep "docker|kata" >&2
 
 	# Restore the default image in config file
-	chronic $mgr configure-image
+	silent_run $mgr configure-image
 }
 
 die()
@@ -203,7 +206,7 @@ die()
 info()
 {
 	s="$*"
-	echo -e "INFO: $s\n" >&2
+	echo -en "INFO: $s\n" >&2
 }
 
 debug()
@@ -213,6 +216,15 @@ debug()
 	echo -e "DBG: $s" >&2
 }
 
+# Run a command in silent mode using chronic.
+# The command output is printed only if the command fails
+silent_run()
+{
+	typeset -a commandLine=("$@")
+	info "running: ${commandLine[@]}"
+	chronic "${commandLine[@]}"
+}
+
 
 set_runtime()
 {
@@ -268,7 +280,7 @@ setup()
 		[ -n "$cfgRuntime" ] || die "${RUNTIME} is not a configured runtime for docker"
 		[ -x "$cfgRuntime" ] || die "docker ${RUNTIME} is linked to an invalid executable: $cfgRuntime"
 	fi
-	chronic $mgr enable-debug
+	silent_run $mgr enable-debug
 
 	# Ensure "docker build" works
 	set_runtime "${docker_build_runtime}"
@@ -352,9 +364,11 @@ install_image_create_container()
 	# Travis doesn't support VT-x
 	[ -n "${TRAVIS:-}" ] && return
 
-	chronic $mgr reset-config
+	showKataRunFailure=1
-	chronic $mgr configure-image "$file"
+	silent_run $mgr reset-config
+	silent_run $mgr configure-image "$file"
 	create_container
+	showKataRunFailure=
 }
 
 install_initrd_create_container()
@@ -367,9 +381,11 @@ install_initrd_create_container()
 	# Travis doesn't support VT-x
 	[ -n "${TRAVIS:-}" ] && return
 
-	chronic $mgr reset-config
+	showKataRunFailure=1
-	chronic $mgr configure-initrd "$file"
+	silent_run $mgr reset-config
+	silent_run $mgr configure-initrd "$file"
 	create_container
+	showKataRunFailure=
 }
 
 # Displays a list of distros which can be tested
@@ -403,6 +419,12 @@ call_make() {
 	  ((makeJobs=$(nproc) / 2))
 	fi
 
+	# When calling make, do not use the silent_run wrapper, pass the
+	# OSBUILDER_USE_CHRONIC instead.
+	# In this way running make in parallel mode will, in case of failure, just
+	# show the print out of the single target failing.
+	makeVars+=(OSBUILDER_USE_CHRONIC=1)
+
 	info "Starting make with \n\
 	# of // jobs:  ${makeJobs:-[unlimited]} \n\
 	targets:       ${makeTargets[@]} \n\
@@ -437,7 +459,6 @@ show_rootfs_metadata() {
 	[ $# -ne 1 ] && die "show_rootfs_metadata: wrong number of arguments"
 	local rootfs_path=$1
 	local osbuilder_file_fullpath="${rootfs_path}/${osbuilder_file}"
-	echo -e "$separator"
 	yamllint "${osbuilder_file_fullpath}"
 
 	info "osbuilder metadata file for $d:"
@@ -458,15 +479,12 @@ test_distros()
 {
 	local distro="$1"
 	get_distros_config "$distro"
-	local separator="~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n"
 	local commonMakeVars=( \
 		USE_DOCKER=true \
 		ROOTFS_BUILD_DEST="$tmp_rootfs" \
 		IMAGES_BUILD_DEST="$images_dir" \
 		DEBUG=1 )
 
-	echo -e "$separator"
-
 	# If a distro was specified, filter out the distro list to only include that distro
 	if [ -n "$distro" ]; then
 		pattern="\<$distro\>"
@@ -514,7 +532,21 @@ test_distros()
 
 	# Check for build failures (`wait` remembers up to CHILD_MAX bg processes exit status)
 	for j in ${bgJobs[@]}; do
-		wait $j || die "Background build job failed"
+		if ! wait $j; then
+			info "Background rootfs build job failed:"
+			#find completed an uncompleted jobs checking for the rootfs marker
+			local marker=$(make print-ROOTFS_MARKER_SUFFIX)
+			[ -z "$marker" ] &&  die "Invalid rootfs marker"
+			typeset -a completed=($(find ${tmp_rootfs} -name ".*${marker}" -exec basename {} \; | sed -E "s/\.(.+)${marker}/\1/"))
+			for d in "${distrosSystemd[@]} ${distrosAgent[@]}"; do
+				if [[ "${completed[@]}" =~ $d ]]; then
+					info "- $d : completed"
+				else
+					info "- $d : failed"
+				fi
+			done
+			die "rootfs build failed"
+		fi
 	done
 
 	# TODO: once support for rootfs images with kata-agent as init is in place,
@@ -533,12 +565,10 @@ test_distros()
 		fi
 
 		show_rootfs_metadata "$rootfs_path"
-		echo -e "$separator"
 		info "Making rootfs image for ${d}"
 		make_image ${commonMakeVars[@]} $d
 		local image_size=$(stat -c "%s" "${image_path}")
 
-		echo -e "$separator"
 		built_images["${d}"]="${rootfs_size}:${image_size}"
 		info "Creating container for ${d}"
 		install_image_create_container $image_path
@@ -558,22 +588,17 @@ test_distros()
 
 
 		if [ "$KATA_HYPERVISOR" != "firecracker" ]; then
-			echo -e "$separator"
 			info "Making initrd image for ${d}"
 			make_initrd ${commonMakeVars[@]} AGENT_INIT=yes $d
 			local initrd_size=$(stat -c "%s" "${initrd_path}")
 
-			echo -e "$separator"
 			built_initrds["${d}"]="${rootfs_size}:${initrd_size}"
 			info "Creating container for ${d}"
 			install_initrd_create_container $initrd_path
 		fi
 	done
 
-	echo -e "$separator"
 	show_stats
-
-	echo -e "$separator"
 }
 
 main()