=== modified file 'bin/mount-image-callback'
--- bin/mount-image-callback	2018-01-03 15:44:47 +0000
+++ bin/mount-image-callback	2018-01-03 21:15:16 +0000
@@ -53,6 +53,7 @@
 #  this is useful to unmount a chroot that had sys, proc ... mounted
 umount_r() {
 	local p
+	msg "umount_r $*"
 	for p in "$@"; do
 		[ -n "$p" ] || continue
 		tac /proc/mounts | sh -c '
@@ -61,7 +62,9 @@
 			while read s mp t opt a b ; do
 				[ "${mp}" = "${p}" -o "${mp#${p}/}" != "${mp}" ] ||
 					continue
+				logger --tag=mic "start umount $mp"
 				umount "$mp" || exit 1
+				logger --tag=mic "done umount $mp"
 				didumount=1
 			done
 			[ $didumount -eq 1 ] || exit 1
@@ -72,6 +75,10 @@
 
 bad_Usage() { Usage 1>&2; [ $# -eq 0 ] || error "$@"; exit 1; }
 
+msg() {
+	logger --tag=mic "$*"
+}
+
 disconnect_qemu() {
 	[ -n "$QEMU_DISCONNECT" ] || return 0
 	local out="" nbd="$QEMU_DISCONNECT"
@@ -80,12 +87,15 @@
 	{ read pid < "$pfile" ; } >/dev/null 2>&1
 	[ -n "$pid" -a ! -d "/proc/$pid" ] && 
 		error "qemu-nbd process seems to have died. was '$pid'"
+	msg "start qemu-nbd --disconnect $nbd"
 	out=$(qemu-nbd --disconnect "$nbd" 2>&1) &&
 		QEMU_DISCONNECT="" || {
+			msg "done qemu-nbd --disconnect [failed]"
 			error "failed to disconnect $nbd";
 			error "$out"
 			return 1;
 	}
+	msg "done qemu-nbd --disconnect"
 }
 
 do_umounts() {
@@ -207,10 +217,12 @@
 	for fstype in overlay overlayfs; do
 		cmd=( mount -t "$fstype" -o "$olayopts" "$lower" "$upper" )
 		debug 2 "attempting '$fstype' mount with: ${cmd[*]}"
+		msg "start mount overlay $lower $upper"
 		out=$("${cmd[@]}" 2>&1)
 		ret=$?
 		if [ $ret -eq 0 ]; then
 			debug 1 "mounted '$fstype' via $fstype: ${cmd[*]}"
+			msg "done mount overlay $lower $upper"
 			return 0
 		fi
 		_ERR="${_ERR}Failed [$ret]: ${cmd[*]}:${CR}"
@@ -345,9 +357,12 @@
 	assert_nbd_support || return
 	connect_nbd "$img" "$fmt" "$ptnum" "$rwmode" || return
 	local ptnum="$_RET_PT" mdev="$_RET_DEV" nbd="$_RET_NBD"
+	msg "start mount $mdev $img_mp"
 	if ( set -f; mount -o "$rwmode" $opts "$mdev" "$img_mp" ); then
+		msg "done mount $mdev $img_mp"
 		debug 1 "mounted $mdev via qemu-nbd $nbd at $img_mp"
 	else
+		msg "fail mount $mdev $img_mp"
 		error "failed to mount $mdev"
 		return 1
 	fi
@@ -464,7 +479,9 @@
 			UMOUNTS[${#UMOUNTS[@]}]="$mp"
 		fi
 	elif [ "$ptnum" = "auto" -o "$ptnum" = "0" ] &&
+		msg "start mount loop $img $img_mp" &&
 		out=$(set -f; mount -o "loop,$rwmode" $opts "$img" "$img_mp" 2>&1); then
+		msg "done mount loop $img $img_mp"
 		debug 1 "mounted simple fs image $rwmode in '$img_in' at $img_mp"
 		UMOUNTS[${UMOUNT[@]}]="$img_mp"
 	else

=== modified file 'test/test-mic'
--- test/test-mic	2018-01-03 16:34:51 +0000
+++ test/test-mic	2018-01-03 21:15:35 +0000
@@ -14,9 +14,11 @@
    local out="${TEMP_D}/out"
 	"$@" > "$out" 2>&1 || { error "FAILED [$?]:" "$@"; cat "$out"; return 1; }
 }
-fail() { echo "$@" 1>&2; exit 1; }
+fail() { msg "$@" 1>&2; exit 1; }
 error() { echo "$@" 1>&2; }
-msg() { error "$@"; }
+msg() {
+    logger --tag=test-mic "$*"
+}
 
 do_pt_test() {
 	local img="$1" pt="$2" data="$3" info="$4" premsg="$5" out=""
@@ -27,6 +29,7 @@
 			return 1;
 		}
 	local ret="" expected=$(printf "%s\n%s\n" "$info" "$data")
+	msg "${premsg}wrote data to $pt"
 	out=$(mount-image-callback --read-only --cd "--part=$pt" "$img" -- \
 		sh -c '
 		    r=0; for f in "$@"; do
@@ -87,10 +90,12 @@
 mount-image-callback "$pt1" -- cp -r "$pt1_d/"* _MOUNTPOINT_ ||
 	fail "copying file to pt1 mount failed"
 
+msg "reading info.txt from partition 1 image"
 out=$(mount-image-callback --read-only "$pt1" --cd -- cat info.txt) &&
 	[ "$out" = "partition 1" ] ||
 	fail "failed verification of pt1 contents"
 
+msg "reading file1.txt from partition 1 image"
 out=$(mount-image-callback --read-only --cd "$pt1" -- cat file1.txt)
 [ "$out" = "file 1" ] ||
 	fail "found unexpected contents in file1.txt on pt1: $out"
@@ -99,6 +104,7 @@
 mount-image-callback "$pt2" -- cp -r "$pt2_d/"* _MOUNTPOINT_ ||
 	fail "copying file to pt2 mount failed"
 
+msg "reading info.txt from partition 2 image"
 out=$(mount-image-callback --read-only "$pt2" --cd -- cat info.txt) &&
 	[ "$out" = "partition 2" ] ||
 	fail "failed verification of pt2 contents"
@@ -106,6 +112,7 @@
 ## Stage 1.6: Mount with overlay
 copy_out="${TEMP_D}/copy-out"
 mkdir -p "$TEMP_D/copy-out"
+msg "testing overlay"
 mount-image-callback --overlay --cd "$pt1" -- \
 	sh -ec 't="$1";
 	        echo hi > new-file.txt; echo xxx > file1.txt;
@@ -121,7 +128,8 @@
 	fail "unexpected contents in new-file.txt from overlay: $found."
 
 ## verify the overlay mount changes did not change partition
-out=$(mount-image-callback --cd "$pt1" -- cat file1.txt)
+msg "verify overlay mount did not change partition"
+out=$(mount-image-callback --read-only --cd "$pt1" -- cat file1.txt)
 [ "$out" = "file 1" ] ||
 	fail "found unexpected contents in pt1:file1.txt after overlay: $out"
 
@@ -147,6 +155,7 @@
 	echo "hi again" > mnt/mnt2/second-file-on-tmpfs' ||
 		fail "testing unexpected mounts failed."
 
+msg "verifying file does not exist."
 # verify the file is not there.
 mount-image-callback --read-only --cd -- "$pt1" sh -c '
 	fail() { echo "$@" 1>&2; exit 1; }
@@ -185,10 +194,13 @@
 ) > "$sfdisk_in"
 
 msg "partitioning MBR disk image ${img_mbr}"
-(echo "label: dos"; cat "$sfdisk_in"; ) | rq sfdisk "${img_mbr}"
+(echo "label: dos"; cat "$sfdisk_in"; ) | rq sfdisk --no-reread --no-tell-kernel "${img_mbr}"
 
 msg "partitioning GPT disk image ${img_gpt}"
-(echo "label: gpt"; cat "$sfdisk_in"; ) | rq sfdisk "${img_gpt}"
+(echo "label: gpt"; cat "$sfdisk_in"; ) | rq sfdisk --no-reread --no-tell-kernel "${img_gpt}"
+
+cp "${img_mbr}" /tmp/my.mbr.img
+cp "${img_gpt}" /tmp/my.gpt.img
 
 ## Stage 2.5
 ## Verify we can mount each partition with '--part=N'