build: Add additional logging

This produces a human and machine-readable build log in $OUT so that we can
better understand where failures are occurring.

Change-Id: Ife5382c2218f4fd28efb43213bd13d692b49cac9
diff --git a/Makefile b/Makefile
index 57646c6..9d245fb 100644
--- a/Makefile
+++ b/Makefile
@@ -35,10 +35,37 @@
 # u-boot and kernel build systems, in particular, do not play well together for
 # various odd reasons (duplicate targets such as depcheck, etc.)
 boot-targets:
+	$(LOG) boot-targets started
+	@echo
+	@echo ==============================================================================
+	@echo ==================== u-boot
+	@echo ==============================================================================
+	@echo
 	+make -f $(ROOTDIR)/build/Makefile u-boot
+	@echo
+	@echo ==============================================================================
+	@echo ==================== boot
+	@echo ==============================================================================
+	@echo
 	+make -f $(ROOTDIR)/build/Makefile boot
+	@echo
+	@echo ==============================================================================
+	@echo ==================== partition-table
+	@echo ==============================================================================
+	@echo
 	+make -f $(ROOTDIR)/build/Makefile partition-table
+	@echo
+	@echo ==============================================================================
+	@echo ==================== rootfs
+	@echo ==============================================================================
+	@echo
 	+make -f $(ROOTDIR)/build/Makefile rootfs
+	@echo
+	@echo ==============================================================================
+	@echo ==================== successful build
+	@echo ==============================================================================
+	@echo
+	$(LOG) boot-targets finished
 
 help: targets
 targets::
diff --git a/boot.mk b/boot.mk
index 8027bd2..9d6467c 100644
--- a/boot.mk
+++ b/boot.mk
@@ -21,8 +21,10 @@
 boot: $(PRODUCT_OUT)/boot.img
 
 $(PRODUCT_OUT)/boot.img:
+	$(LOG) boot fallocate
 	fallocate -l $(BOOT_SIZE_MB)M $@
 	mkfs.ext2 -F $@
+	$(LOG) boot finished
 
 targets::
 	@echo "boot - builds the kernel and boot partition"
diff --git a/log.sh b/log.sh
new file mode 100755
index 0000000..00b22da
--- /dev/null
+++ b/log.sh
@@ -0,0 +1,32 @@
+#!/bin/bash
+
+function die
+{
+    echo "board: $@" 1>&2
+    exit 1
+}
+
+function try
+{
+    "$@" || die "$@ failed. Aborting."
+}
+
+function main
+{
+    local target="$1"; shift
+    local state="$1"; shift
+    local message="$@"
+
+    if [[ -z "$BUILDTAB" ]]; then
+        die "\$BUILDTAB is not defined. 'source build/setup.sh' first!"
+    fi
+
+    mkdir -p $PRODUCT_OUT
+    echo -e "$(TZ=UTC date)\t${target}\t${state}\t${message}" >> $BUILDTAB
+}
+
+if [[ "$#" -lt 2 ]]; then
+    die "Usage: log.sh <target-name> <state> [<message...>]"
+fi
+
+main "$@"
diff --git a/packages.mk b/packages.mk
index e734dbe..91f2385 100644
--- a/packages.mk
+++ b/packages.mk
@@ -65,6 +65,7 @@
 	| out-dirs $(ROOTDIR)/cache/base.tgz \
 	$4
 
+	$(LOG) $1 pbuilder
 	$(ROOTDIR)/build/update_packages.sh
 	cd $(ROOTDIR)/$2; git submodule init; git submodule update;
 	rm -rf $(PRODUCT_OUT)/obj/$1
@@ -80,6 +81,8 @@
 
 	sudo cp $(ROOTDIR)/build/99network-settings ~/
 	echo "cp ~/99network-settings /etc/apt/apt.conf.d/" | sudo tee ~/.pbuilderrc
+
+	$(LOG) $1 pbuilder pdebuild
 	cd $(PRODUCT_OUT)/obj/$1; pdebuild \
 		--buildresult $(PRODUCT_OUT)/packages -- \
 		--debbuildopts "--build=$(if $5,$5,full)" \
@@ -87,14 +90,18 @@
 		--configfile $(ROOTDIR)/build/pbuilderrc \
 		--hookdir $(ROOTDIR)/build/pbuilder-hooks \
 		--host-arch arm64 --logfile $(PRODUCT_OUT)/$1.log
+
+	$(LOG) $1 finished
 else
 $(PRODUCT_OUT)/.$1-pbuilder: \
 	| out-dirs \
 	$(PACKAGES_FETCH_ROOT_DIRECTORY)/$(PACKAGES_REVISION)/packages.tgz
+	$(LOG) $1 pbuilder extract
 	tar -C $(PRODUCT_OUT) --wildcards -xf \
 		$(PACKAGES_FETCH_ROOT_DIRECTORY)/$(PACKAGES_REVISION)/packages.tgz \
 		packages/$1*.deb
 	$(ROOTDIR)/build/update_packages.sh
+	$(LOG) $1 finished
 endif
 	touch $(PRODUCT_OUT)/.$1-pbuilder
 .PHONY:: $1
diff --git a/preamble.mk b/preamble.mk
index 77ade50..acfc385 100644
--- a/preamble.mk
+++ b/preamble.mk
@@ -15,6 +15,8 @@
 # Preamble. Don't define any targets in this file! This is effectively just a
 # common header where useful global vars go.
 
+LOG := @$(ROOTDIR)/build/log.sh
+
 ifneq ($(IS_EXTERNAL),)
     DOCKER_FETCH_TARBALL := false
     FETCH_PBUILDER_BASE := false
diff --git a/rootfs.mk b/rootfs.mk
index da59af8..9221d55 100644
--- a/rootfs.mk
+++ b/rootfs.mk
@@ -72,21 +72,30 @@
 endif
 
 rootfs: $(PRODUCT_OUT)/rootfs.img
+	$(LOG) rootfs finished
+
 rootfs_raw: $(ROOTFS_RAW_IMG)
 
 adjustments:
+	$(LOG) rootfs adjustments
 	sudo $(ROOTDIR)/build/fix_permissions.sh -p $(ROOTDIR)/build/permissions.txt -t $(ROOTFS_DIR)
 
 ifeq ($(ROOTFS_FETCH_TARBALL),true)
 $(ROOTFS_RAW_IMG): $(TARBALL_FETCH_ROOT_DIRECTORY)/$(ROOTFS_REVISION)/rootfs.raw.img
+	$(LOG) rootfs raw-fetch
 	mkdir -p $(dir $(ROOTFS_RAW_IMG))
 	cp $< $<.sha256sum $(dir $(ROOTFS_RAW_IMG))
+	$(LOG) rootfs raw-fetch finished
 else ifeq ($(shell test -f $(ROOTDIR)/cache/rootfs.raw.img && echo found),found)
 $(ROOTFS_RAW_IMG): $(ROOTDIR)/cache/rootfs.raw.img
+	$(LOG) rootfs raw-cache
+	mkdir -p $(dir $(ROOTFS_RAW_IMG))
 	cp $(ROOTDIR)/cache/rootfs.raw.img $(ROOTFS_RAW_IMG)
 	sha256sum $(ROOTFS_RAW_IMG) > $(ROOTFS_RAW_IMG).sha256sum
+	$(LOG) rootfs raw-cache finished
 else
 $(ROOTFS_RAW_IMG): $(ROOTDIR)/build/preamble.mk $(ROOTDIR)/build/rootfs.mk /usr/bin/qemu-aarch64-static
+	$(LOG) rootfs raw-build
 	mkdir -p $(ROOTFS_DIR)
 	rm -f $(ROOTFS_RAW_IMG)
 	fallocate -l $(ROOTFS_SIZE_MB)M $(ROOTFS_RAW_IMG)
@@ -97,12 +106,19 @@
 	sudo mount -o loop $(ROOTFS_RAW_IMG) $(ROOTFS_DIR)
 	cp $(ROOTDIR)/build/multistrap.conf $(PRODUCT_OUT)
 	sed -i -e 's/MAIN_PACKAGES/$(PACKAGES_EXTRA)/g' $(PRODUCT_OUT)/multistrap.conf
+
+	$(LOG) rootfs raw-build multistrap
 	sudo multistrap -f $(PRODUCT_OUT)/multistrap.conf -d $(ROOTFS_DIR)
+	$(LOG) rootfs raw-build multistrap finished
 
 	sudo mount -o bind /dev $(ROOTFS_DIR)/dev
 	sudo cp /usr/bin/qemu-aarch64-static $(ROOTFS_DIR)/usr/bin
 	sudo chroot $(ROOTFS_DIR) /var/lib/dpkg/info/dash.preinst install
+
+	$(LOG) rootfs raw-build dpkg-configure
 	sudo DEBIAN_FRONTEND=noninteractive DEBCONF_NONINTERACTIVE_SEEN=true LC_ALL=C LANGUAGE=C LANG=C chroot $(ROOTFS_DIR) dpkg --configure -a
+	$(LOG) rootfs raw-build dpkg-configure finished
+
 	sudo rm -f $(ROOTFS_DIR)/usr/bin/qemu-aarch64-static
 	sudo umount $(ROOTFS_DIR)/dev
 	sudo umount $(ROOTFS_DIR)
@@ -110,6 +126,7 @@
 	sudo sync $(ROOTFS_RAW_IMG)
 	sudo chown ${USER} $(ROOTFS_RAW_IMG)
 	sha256sum $(ROOTFS_RAW_IMG) > $(ROOTFS_RAW_IMG).sha256sum
+	$(LOG) rootfs raw-build finished
 endif
 
 $(ROOTFS_PATCHED_IMG): $(ROOTFS_RAW_IMG) \
@@ -118,6 +135,8 @@
                        $(ROOTDIR)/cache/packages.tgz \
                        | $(PRODUCT_OUT)/boot.img \
                          /usr/bin/qemu-aarch64-static
+	$(LOG) rootfs patch
+
 	cp $(ROOTFS_RAW_IMG) $(ROOTFS_PATCHED_IMG).wip
 	mkdir -p $(ROOTFS_DIR)
 	-sudo umount $(ROOTFS_DIR)/boot
@@ -131,6 +150,7 @@
 
 	sudo cp $(ROOTDIR)/board/fstab.emmc $(ROOTFS_DIR)/etc/fstab
 
+	$(LOG) rootfs patch keyring
 	echo 'nameserver 8.8.8.8' | sudo tee $(ROOTFS_DIR)/etc/resolv.conf
 	echo 'deb [trusted=yes] file:///opt/aiy/packages ./' | sudo tee $(ROOTFS_DIR)/etc/apt/sources.list.d/local.list
 	sudo mkdir -p $(ROOTFS_DIR)/opt/aiy
@@ -139,14 +159,16 @@
 	sudo chroot $(ROOTFS_DIR) bash -c 'apt-get update'
 	sudo chroot $(ROOTFS_DIR) bash -c 'apt-get install aiy-board-keyring'
 	sudo chroot $(ROOTFS_DIR) bash -c 'apt-get update'
+	$(LOG) rootfs patch keyring finished
 
+	$(LOG) rootfs patch bsp
 	sudo chroot $(ROOTFS_DIR) bash -c 'apt-get install --allow-downgrades --no-install-recommends -y $(PRE_INSTALL_PACKAGES)'
-
 	sudo mount -t tmpfs none $(ROOTFS_DIR)/tmp
 	sudo cp $(PRODUCT_OUT)/packages/linux-headers-*-aiy_*_arm64.deb \
 		$(PRODUCT_OUT)/packages/linux-image-*-aiy_*_arm64.deb $(ROOTFS_DIR)/tmp
 	sudo chroot $(ROOTFS_DIR) bash -c 'apt-get install --allow-downgrades --no-install-recommends -y /tmp/*.deb'
 	sudo umount $(ROOTFS_DIR)/tmp
+	$(LOG) rootfs patch bsp finished
 
 	+make -f $(ROOTDIR)/build/rootfs.mk adjustments
 
@@ -158,9 +180,12 @@
 	sudo sync $(ROOTFS_PATCHED_IMG).wip
 	sudo chown ${USER} $(ROOTFS_PATCHED_IMG).wip
 	mv $(ROOTFS_PATCHED_IMG).wip $(ROOTFS_PATCHED_IMG)
+	$(LOG) rootfs patch finished
 
 $(PRODUCT_OUT)/rootfs.img: $(HOST_OUT)/bin/img2simg $(ROOTFS_PATCHED_IMG)
+	$(LOG) rootfs img2simg
 	$(HOST_OUT)/bin/img2simg $(ROOTFS_PATCHED_IMG) $(PRODUCT_OUT)/rootfs.img
+	$(LOG) rootfs img2simg finished
 
 clean::
 	if mount |grep -q $(ROOTFS_DIR); then sudo umount -R $(ROOTFS_DIR); fi
diff --git a/setup.sh b/setup.sh
index 6d7d1c2..0920e18 100755
--- a/setup.sh
+++ b/setup.sh
@@ -47,19 +47,35 @@
 export PRODUCT_OUT="${OUT}/target/product/imx8m_phanbell"
 export HOST_OUT="${OUT}/host/linux-x86"
 export ROOT_OUT="${OUT}/root"
+export BUILDTAB="${OUT}/buildtab"
 
 export PATH="${PATH}:${HOST_OUT}/bin:${ROOTDIR}/build:${ROOTDIR}/board"
 
 function m
 {
+    local target="build"
+
+    if [[ -f /.dockerenv ]]; then
+        target="sub-build"
+    fi
+
     pushd "${ROOTDIR}" >/dev/null
+    log.sh $target started m "$@"
+
     make -f "${ROOTDIR}/build/Makefile" "$@"
+
+    if [[ "$?" != 0 ]]; then
+        log.sh $target failed
+    else
+        log.sh $target finished
+    fi
     popd >/dev/null
 }
 
 function mm
 {
     local module="$1"; shift
+    local target="build"
 
     if [[ -z "${module}" ]]; then
         echo "Usage: mm <modulename> [<target>]"
@@ -74,8 +90,18 @@
         return 1
     fi
 
+    if [[ -f /.dockerenv ]]; then
+        target="sub-build"
+    fi
+
     pushd "${ROOTDIR}" >/dev/null
+    log.sh $target started mm "$@"
     make -f "${ROOTDIR}/build/${module}.mk" "$@"
+    if [[ "$?" != 0 ]]; then
+        log.sh $target failed
+    else
+        log.sh $target finished
+    fi
     popd >/dev/null
 }
 
diff --git a/u-boot.mk b/u-boot.mk
index 00cad1a..9bac91f 100644
--- a/u-boot.mk
+++ b/u-boot.mk
@@ -21,8 +21,10 @@
 u-boot: $(PRODUCT_OUT)/u-boot.imx
 
 $(PRODUCT_OUT)/u-boot.imx: docker-uboot-imx | out-dirs
+	$(LOG) u-boot extract
 	dpkg --fsys-tarfile $(PRODUCT_OUT)/packages/uboot-imx*.deb | \
 	tar --strip-components 2 -C $(PRODUCT_OUT) -xf - ./boot/u-boot.imx
+	$(LOG) u-boot finished
 
 targets::
 	@echo "u-boot - builds the bootloader"
diff --git a/watch.sh b/watch.sh
new file mode 100755
index 0000000..de76061
--- /dev/null
+++ b/watch.sh
@@ -0,0 +1,88 @@
+#!/bin/bash
+
+# Reload the LINES and COLUMNS vars from the terminal -- have to do this in the
+# toplevel due to the weird use of IFS.
+echo -en '\e7\e[r\e[999;999H\e[6n\e8'
+OLDIFS=\$IFS
+IFS='[;'
+read -d R -s esc LINES COLUMNS
+IFS=\$OLDIFS
+
+function die
+{
+    echo "board: $@" >/dev/stderr
+    exit 1
+}
+
+function try
+{
+    "$@" || die "$@ failed. Aborting."
+}
+
+function watch
+{
+    local columns=
+    local timestamp
+    local target
+    local state
+    local message
+    declare -A tasks
+
+    local red=$(tput setaf 1)
+    local green=$(tput setaf 2)
+    local yellow=$(tput setaf 3)
+    local white=$(tput setaf 7)
+
+    IFS=$'\t\n'
+    while read timestamp target state message; do
+        [[ -z $target ]] && continue
+
+        if [[ "${target}" == "build" ]]; then
+            unset tasks
+            declare -A tasks
+        fi
+
+        tasks[$target]="$message ($state - $timestamp)"
+
+        clear
+        for target in "${!tasks[@]}"; do
+            printf "%*s\r" "${COLUMNS}" "${tasks[$target]}"
+
+            case "${tasks[$target]}" in
+                *finished*) printf "$green"  ;;
+                *failed*)   printf "$red"    ;;
+                *)          printf "$yellow" ;;
+            esac
+
+            printf "%s%s\n" "$target" "$white"
+        done
+
+        if [[ "${state}" =~ finished ]]; then
+            unset tasks[$target]
+        fi
+
+        sleep 0.25
+    done
+}
+
+function main
+{
+    if [[ -z "$BUILDTAB" ]]; then
+        die "\$BUILDTAB is not defined. 'source build/setup.sh' first!"
+    fi
+
+    echo -n "Waiting for $BUILDTAB to be available..."
+    while true; do
+          if [[ -f $BUILDTAB ]]; then
+              break
+          fi
+
+          echo -n "."
+          sleep 1
+    done
+    clear
+
+    tail -f $BUILDTAB |watch
+}
+
+main