Merge branch 'sg/progress-fix'

Regression fix for progress output.

* sg/progress-fix:
  Test the progress display
  Revert "progress: use term_clear_line()"

7 files changed, 421 insertions, 16 deletions

diff --git a/Makefile b/Makefile
index 0f68836bb1..8c37e5412d 100644
--- a/Makefile
+++ b/Makefile
@@ -729,6 +729,7 @@ TEST_BUILTINS_OBJS += test-parse-options.o
 TEST_BUILTINS_OBJS += test-path-utils.o
 TEST_BUILTINS_OBJS += test-pkt-line.o
 TEST_BUILTINS_OBJS += test-prio-queue.o
+TEST_BUILTINS_OBJS += test-progress.o
 TEST_BUILTINS_OBJS += test-reach.o
 TEST_BUILTINS_OBJS += test-read-cache.o
 TEST_BUILTINS_OBJS += test-read-midx.o
diff --git a/progress.c b/progress.c
index 277db8afa2..0063559aab 100644
--- a/progress.c
+++ b/progress.c
@@ -45,6 +45,19 @@ struct progress {
 
 static volatile sig_atomic_t progress_update;
 
+/*
+ * These are only intended for testing the progress output, i.e. exclusively
+ * for 'test-tool progress'.
+ */
+int progress_testing;
+uint64_t progress_test_ns = 0;
+void progress_test_force_update(void); /* To silence -Wmissing-prototypes */
+void progress_test_force_update(void)
+{
+	progress_update = 1;
+}
+
+
 static void progress_interval(int signum)
 {
 	progress_update = 1;
@@ -55,6 +68,9 @@ static void set_progress_signal(void)
 	struct sigaction sa;
 	struct itimerval v;
 
+	if (progress_testing)
+		return;
+
 	progress_update = 0;
 
 	memset(&sa, 0, sizeof(sa));
@@ -72,6 +88,10 @@ static void set_progress_signal(void)
 static void clear_progress_signal(void)
 {
 	struct itimerval v = {{0,},};
+
+	if (progress_testing)
+		return;
+
 	setitimer(ITIMER_REAL, &v, NULL);
 	signal(SIGALRM, SIG_IGN);
 	progress_update = 0;
@@ -88,6 +108,7 @@ static void display(struct progress *progress, uint64_t n, const char *done)
 	const char *tp;
 	struct strbuf *counters_sb = &progress->counters_sb;
 	int show_update = 0;
+	int last_count_len = counters_sb->len;
 
 	if (progress->delay && (!progress_update || --progress->delay))
 		return;
@@ -115,21 +136,27 @@ static void display(struct progress *progress, uint64_t n, const char *done)
 	if (show_update) {
 		if (is_foreground_fd(fileno(stderr)) || done) {
 			const char *eol = done ? done : "\r";
+			size_t clear_len = counters_sb->len < last_count_len ?
+					last_count_len - counters_sb->len + 1 :
+					0;
+			/* The "+ 2" accounts for the ": ". */
+			size_t progress_line_len = progress->title_len +
+						counters_sb->len + 2;
+			int cols = term_columns();
 
-			term_clear_line();
 			if (progress->split) {
-				fprintf(stderr, "  %s%s", counters_sb->buf,
-					eol);
-			} else if (!done &&
-				   /* The "+ 2" accounts for the ": ". */
-				   term_columns() < progress->title_len +
-						    counters_sb->len + 2) {
-				fprintf(stderr, "%s:\n  %s%s",
-					progress->title, counters_sb->buf, eol);
+				fprintf(stderr, "  %s%*s", counters_sb->buf,
+					(int) clear_len, eol);
+			} else if (!done && cols < progress_line_len) {
+				clear_len = progress->title_len + 1 < cols ?
+					    cols - progress->title_len - 1 : 0;
+				fprintf(stderr, "%s:%*s\n  %s%s",
+					progress->title, (int) clear_len, "",
+					counters_sb->buf, eol);
 				progress->split = 1;
 			} else {
-				fprintf(stderr, "%s: %s%s", progress->title,
-					counters_sb->buf, eol);
+				fprintf(stderr, "%s: %s%*s", progress->title,
+					counters_sb->buf, (int) clear_len, eol);
 			}
 			fflush(stderr);
 		}
@@ -147,6 +174,14 @@ static void throughput_string(struct strbuf *buf, uint64_t total,
 	strbuf_humanise_rate(buf, rate * 1024);
 }
 
+static uint64_t progress_getnanotime(struct progress *progress)
+{
+	if (progress_testing)
+		return progress->start_ns + progress_test_ns;
+	else
+		return getnanotime();
+}
+
 void display_throughput(struct progress *progress, uint64_t total)
 {
 	struct throughput *tp;
@@ -157,7 +192,7 @@ void display_throughput(struct progress *progress, uint64_t total)
 		return;
 	tp = progress->throughput;
 
-	now_ns = getnanotime();
+	now_ns = progress_getnanotime(progress);
 
 	if (!tp) {
 		progress->throughput = tp = xcalloc(1, sizeof(*tp));
@@ -289,7 +324,7 @@ void stop_progress_msg(struct progress **p_progress, const char *msg)
 		struct throughput *tp = progress->throughput;
 
 		if (tp) {
-			uint64_t now_ns = getnanotime();
+			uint64_t now_ns = progress_getnanotime(progress);
 			unsigned int misecs, rate;
 			misecs = ((now_ns - progress->start_ns) * 4398) >> 32;
 			rate = tp->curr_total / (misecs ? misecs : 1);
diff --git a/t/helper/test-progress.c b/t/helper/test-progress.c
new file mode 100644
index 0000000000..4e9f7fafdf
--- /dev/null
+++ b/t/helper/test-progress.c
@@ -0,0 +1,81 @@
+/*
+ * A test helper to exercise the progress display.
+ *
+ * Reads instructions from standard input, one instruction per line:
+ *
+ *   "progress <items>" - Call display_progress() with the given item count
+ *                        as parameter.
+ *   "throughput <bytes> <millis> - Call display_throughput() with the given
+ *                                  byte count as parameter.  The 'millis'
+ *                                  specify the time elapsed since the
+ *                                  start_progress() call.
+ *   "update" - Set the 'progress_update' flag.
+ *
+ * See 't0500-progress-display.sh' for examples.
+ */
+#include "test-tool.h"
+#include "gettext.h"
+#include "parse-options.h"
+#include "progress.h"
+#include "strbuf.h"
+
+/*
+ * These are defined in 'progress.c', but are not exposed in 'progress.h',
+ * because they are exclusively for testing.
+ */
+extern int progress_testing;
+extern uint64_t progress_test_ns;
+void progress_test_force_update(void);
+
+int cmd__progress(int argc, const char **argv)
+{
+	uint64_t total = 0;
+	const char *title;
+	struct strbuf line = STRBUF_INIT;
+	struct progress *progress;
+
+	const char *usage[] = {
+		"test-tool progress [--total=<n>] <progress-title>",
+		NULL
+	};
+	struct option options[] = {
+		OPT_INTEGER(0, "total", &total, "total number of items"),
+		OPT_END(),
+	};
+
+	argc = parse_options(argc, argv, NULL, options, usage, 0);
+	if (argc != 1)
+		die("need a title for the progress output");
+	title = argv[0];
+
+	progress_testing = 1;
+	progress = start_progress(title, total);
+	while (strbuf_getline(&line, stdin) != EOF) {
+		char *end;
+
+		if (skip_prefix(line.buf, "progress ", (const char **) &end)) {
+			uint64_t item_count = strtoull(end, &end, 10);
+			if (*end != '\0')
+				die("invalid input: '%s'\n", line.buf);
+			display_progress(progress, item_count);
+		} else if (skip_prefix(line.buf, "throughput ",
+				       (const char **) &end)) {
+			uint64_t byte_count, test_ms;
+
+			byte_count = strtoull(end, &end, 10);
+			if (*end != ' ')
+				die("invalid input: '%s'\n", line.buf);
+			test_ms = strtoull(end + 1, &end, 10);
+			if (*end != '\0')
+				die("invalid input: '%s'\n", line.buf);
+			progress_test_ns = test_ms * 1000 * 1000;
+			display_throughput(progress, byte_count);
+		} else if (!strcmp(line.buf, "update"))
+			progress_test_force_update();
+		else
+			die("invalid input: '%s'\n", line.buf);
+	}
+	stop_progress(&progress);
+
+	return 0;
+}
diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
index ce7e89028c..19ee26d931 100644
--- a/t/helper/test-tool.c
+++ b/t/helper/test-tool.c
@@ -42,6 +42,7 @@ static struct test_cmd cmds[] = {
 	{ "path-utils", cmd__path_utils },
 	{ "pkt-line", cmd__pkt_line },
 	{ "prio-queue", cmd__prio_queue },
+	{ "progress", cmd__progress },
 	{ "reach", cmd__reach },
 	{ "read-cache", cmd__read_cache },
 	{ "read-midx", cmd__read_midx },
diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h
index f805bb39ae..c2aa56ef50 100644
--- a/t/helper/test-tool.h
+++ b/t/helper/test-tool.h
@@ -32,6 +32,7 @@ int cmd__parse_options(int argc, const char **argv);
 int cmd__path_utils(int argc, const char **argv);
 int cmd__pkt_line(int argc, const char **argv);
 int cmd__prio_queue(int argc, const char **argv);
+int cmd__progress(int argc, const char **argv);
 int cmd__reach(int argc, const char **argv);
 int cmd__read_cache(int argc, const char **argv);
 int cmd__read_midx(int argc, const char **argv);
diff --git a/t/t0500-progress-display.sh b/t/t0500-progress-display.sh
new file mode 100755
index 0000000000..24ccbd8d3b
--- /dev/null
+++ b/t/t0500-progress-display.sh
@@ -0,0 +1,286 @@
+#!/bin/sh
+
+test_description='progress display'
+
+. ./test-lib.sh
+
+show_cr () {
+	tr '\015' Q | sed -e "s/Q/<CR>\\$LF/g"
+}
+
+test_expect_success 'simple progress display' '
+	cat >expect <<-\EOF &&
+	Working hard: 1<CR>
+	Working hard: 2<CR>
+	Working hard: 5<CR>
+	Working hard: 5, done.
+	EOF
+
+	cat >in <<-\EOF &&
+	update
+	progress 1
+	update
+	progress 2
+	progress 3
+	progress 4
+	update
+	progress 5
+	EOF
+	test-tool progress "Working hard" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display with total' '
+	cat >expect <<-\EOF &&
+	Working hard:  33% (1/3)<CR>
+	Working hard:  66% (2/3)<CR>
+	Working hard: 100% (3/3)<CR>
+	Working hard: 100% (3/3), done.
+	EOF
+
+	cat >in <<-\EOF &&
+	progress 1
+	progress 2
+	progress 3
+	EOF
+	test-tool progress --total=3 "Working hard" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display breaks long lines #1' '
+	sed -e "s/Z$//" >expect <<\EOF &&
+Working hard.......2.........3.........4.........5.........6:   0% (100/100000)<CR>
+Working hard.......2.........3.........4.........5.........6:   1% (1000/100000)<CR>
+Working hard.......2.........3.........4.........5.........6:                   Z
+   10% (10000/100000)<CR>
+  100% (100000/100000)<CR>
+  100% (100000/100000), done.
+EOF
+
+	cat >in <<-\EOF &&
+	progress 100
+	progress 1000
+	progress 10000
+	progress 100000
+	EOF
+	test-tool progress --total=100000 \
+		"Working hard.......2.........3.........4.........5.........6" \
+		<in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display breaks long lines #2' '
+	# Note: we dont need that many spaces after the title to cover up
+	# the last line before breaking the progress line.
+	sed -e "s/Z$//" >expect <<\EOF &&
+Working hard.......2.........3.........4.........5.........6:   0% (1/100000)<CR>
+Working hard.......2.........3.........4.........5.........6:   0% (2/100000)<CR>
+Working hard.......2.........3.........4.........5.........6:                   Z
+   10% (10000/100000)<CR>
+  100% (100000/100000)<CR>
+  100% (100000/100000), done.
+EOF
+
+	cat >in <<-\EOF &&
+	update
+	progress 1
+	update
+	progress 2
+	progress 10000
+	progress 100000
+	EOF
+	test-tool progress --total=100000 \
+		"Working hard.......2.........3.........4.........5.........6" \
+		<in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display breaks long lines #3 - even the first is too long' '
+	# Note: we dont actually need any spaces at the end of the title
+	# line, because there is no previous progress line to cover up.
+	sed -e "s/Z$//" >expect <<\EOF &&
+Working hard.......2.........3.........4.........5.........6:                   Z
+   25% (25000/100000)<CR>
+   50% (50000/100000)<CR>
+   75% (75000/100000)<CR>
+  100% (100000/100000)<CR>
+  100% (100000/100000), done.
+EOF
+
+	cat >in <<-\EOF &&
+	progress 25000
+	progress 50000
+	progress 75000
+	progress 100000
+	EOF
+	test-tool progress --total=100000 \
+		"Working hard.......2.........3.........4.........5.........6" \
+		<in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display breaks long lines #4 - title line matches terminal width' '
+	cat >expect <<\EOF &&
+Working hard.......2.........3.........4.........5.........6.........7.........:
+   25% (25000/100000)<CR>
+   50% (50000/100000)<CR>
+   75% (75000/100000)<CR>
+  100% (100000/100000)<CR>
+  100% (100000/100000), done.
+EOF
+
+	cat >in <<-\EOF &&
+	progress 25000
+	progress 50000
+	progress 75000
+	progress 100000
+	EOF
+	test-tool progress --total=100000 \
+		"Working hard.......2.........3.........4.........5.........6.........7........." \
+		<in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+# Progress counter goes backwards, this should not happen in practice.
+test_expect_success 'progress shortens - crazy caller' '
+	cat >expect <<-\EOF &&
+	Working hard:  10% (100/1000)<CR>
+	Working hard:  20% (200/1000)<CR>
+	Working hard:   0% (1/1000)  <CR>
+	Working hard: 100% (1000/1000)<CR>
+	Working hard: 100% (1000/1000), done.
+	EOF
+
+	cat >in <<-\EOF &&
+	progress 100
+	progress 200
+	progress 1
+	progress 1000
+	EOF
+	test-tool progress --total=1000 "Working hard" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display with throughput' '
+	cat >expect <<-\EOF &&
+	Working hard: 10<CR>
+	Working hard: 20, 200.00 KiB | 100.00 KiB/s<CR>
+	Working hard: 30, 300.00 KiB | 100.00 KiB/s<CR>
+	Working hard: 40, 400.00 KiB | 100.00 KiB/s<CR>
+	Working hard: 40, 400.00 KiB | 100.00 KiB/s, done.
+	EOF
+
+	cat >in <<-\EOF &&
+	throughput 102400 1000
+	update
+	progress 10
+	throughput 204800 2000
+	update
+	progress 20
+	throughput 307200 3000
+	update
+	progress 30
+	throughput 409600 4000
+	update
+	progress 40
+	EOF
+	test-tool progress "Working hard" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display with throughput and total' '
+	cat >expect <<-\EOF &&
+	Working hard:  25% (10/40)<CR>
+	Working hard:  50% (20/40), 200.00 KiB | 100.00 KiB/s<CR>
+	Working hard:  75% (30/40), 300.00 KiB | 100.00 KiB/s<CR>
+	Working hard: 100% (40/40), 400.00 KiB | 100.00 KiB/s<CR>
+	Working hard: 100% (40/40), 400.00 KiB | 100.00 KiB/s, done.
+	EOF
+
+	cat >in <<-\EOF &&
+	throughput 102400 1000
+	progress 10
+	throughput 204800 2000
+	progress 20
+	throughput 307200 3000
+	progress 30
+	throughput 409600 4000
+	progress 40
+	EOF
+	test-tool progress --total=40 "Working hard" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'cover up after throughput shortens' '
+	cat >expect <<-\EOF &&
+	Working hard: 1<CR>
+	Working hard: 2, 800.00 KiB | 400.00 KiB/s<CR>
+	Working hard: 3, 1.17 MiB | 400.00 KiB/s  <CR>
+	Working hard: 4, 1.56 MiB | 400.00 KiB/s<CR>
+	Working hard: 4, 1.56 MiB | 400.00 KiB/s, done.
+	EOF
+
+	cat >in <<-\EOF &&
+	throughput 409600 1000
+	update
+	progress 1
+	throughput 819200 2000
+	update
+	progress 2
+	throughput 1228800 3000
+	update
+	progress 3
+	throughput 1638400 4000
+	update
+	progress 4
+	EOF
+	test-tool progress "Working hard" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'cover up after throughput shortens a lot' '
+	cat >expect <<-\EOF &&
+	Working hard: 1<CR>
+	Working hard: 2, 1000.00 KiB | 1000.00 KiB/s<CR>
+	Working hard: 3, 3.00 MiB | 1.50 MiB/s      <CR>
+	Working hard: 3, 3.00 MiB | 1024.00 KiB/s, done.
+	EOF
+
+	cat >in <<-\EOF &&
+	throughput 1 1000
+	update
+	progress 1
+	throughput 1024000 2000
+	update
+	progress 2
+	throughput 3145728 3000
+	update
+	progress 3
+	EOF
+	test-tool progress "Working hard" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_done
diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index b86ddb60f2..92bac43257 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -262,7 +262,7 @@ test_expect_success TTY 'push shows progress when stderr is a tty' '
 	cd "$ROOT_PATH"/test_repo_clone &&
 	test_commit noisy &&
 	test_terminal git push >output 2>&1 &&
-	test_i18ngrep "Writing objects" output
+	test_i18ngrep "^Writing objects" output
 '
 
 test_expect_success TTY 'push --quiet silences status and progress' '
@@ -277,7 +277,7 @@ test_expect_success TTY 'push --no-progress silences progress but not status' '
 	test_commit no-progress &&
 	test_terminal git push --no-progress >output 2>&1 &&
 	test_i18ngrep "^To http" output &&
-	test_i18ngrep ! "Writing objects" output
+	test_i18ngrep ! "^Writing objects" output
 '
 
 test_expect_success 'push --progress shows progress to non-tty' '
@@ -285,7 +285,7 @@ test_expect_success 'push --progress shows progress to non-tty' '
 	test_commit progress &&
 	git push --progress >output 2>&1 &&
 	test_i18ngrep "^To http" output &&
-	test_i18ngrep "Writing objects" output
+	test_i18ngrep "^Writing objects" output
 '
 
 test_expect_success 'http push gives sane defaults to reflog' '