Show the run log's last lines under Details, live

The percentage says an update is alive. It does not say what it is alive
doing, and for the longest stretch of a run there was no way to find out:
an AUR package compiling for a quarter of an hour talks constantly, and
every word of it went into a file nobody was looking at.

So the run log's last five lines now travel with the progress entry and
sit under Details, refreshed every two seconds for as long as the update
lasts. Polled rather than followed, for the same reason the pacman
watcher polls: only the last few lines are ever displayed, so every line
in between would be work nobody sees, and re-reading the tail whole makes
truncation and rotation of the log a non-event.

The job model behind this interface carries exactly two description
fields - descriptionValue1 and 2, there is no third - so one stays with
the package being worked on and the other takes the tail. Newlines inside
a field do render, which is what lets five lines share one of them. They
travel tab separated because the protocol is one instruction per line,
and a tab inside a log line becomes a space first: either renders as
whitespace, but a line split in half renders as nonsense. Five lines
clipped to 120 columns also keeps an instruction well inside PIPE_BUF,
which is what makes the write atomic against the runner sending its own
progress down the same pipe.

README.md

@@ -228,6 +228,14 @@ Two things about how it is put together:
   instead of leaping 30% the moment unpacking starts — and likewise for AUR
   with nothing pending, or a machine with no Flatpaks. The weights only ever
   have to be right about the steps that actually run.
+- **Expanding *Details* shows the run log's last five lines, live.** The
+  percentage says the update is alive; these say what it is alive doing. It
+  matters most where there is nothing to count — an AUR package compiling for
+  a quarter of an hour talks constantly, and all of it used to go into a file
+  nobody was looking at. The job model behind this interface carries exactly
+  two description fields (`descriptionValue1` and `2` — there is no third), so
+  one holds the current package and the other the tail; newlines inside a value
+  do render, which is what makes five lines fit in one field.
 - pacman's output is line-buffered through `stdbuf`. Writing to a log rather
   than a terminal, libc would hand it over in 4 KB blocks instead, and 4 KB of
   `upgrading foo...` is on the order of a hundred and sixty packages arriving

doc/cachy-auto-update.1.scd

@@ -131,6 +131,13 @@ stuck update. On a domestic line the download is then the longest of the three,
 and a bar that called the whole thing "installing" would sit near its beginning
 for minutes at a time looking stuck.
 
+Expanding "Details" shows the last five lines of the run log as they are
+written, alongside the package currently being worked on. The percentage says
+the update is alive; these lines say what it is alive doing, which matters most
+during the stretches that have nothing countable to report - an AUR package
+being compiled, above all. The job interface carries exactly two description
+fields, so those are the two things shown.
+
 A step that turns out to have no work is dropped from the bar instead of being
 handed its share for nothing. Packages already in the cache are never
 announced, so a run with everything already fetched skips the download step

po/cachy-auto-update.pot

@@ -258,6 +258,9 @@ msgstr ""
 msgid "Cleaning up after the update"
 msgstr ""
 
+msgid "Log"
+msgstr ""
+
 msgid "Package"
 msgstr ""
 

po/de.po

@@ -259,6 +259,9 @@ msgstr "AppImages werden aktualisiert"
 msgid "Cleaning up after the update"
 msgstr "Aufräumen nach dem Update"
 
+msgid "Log"
+msgstr "Protokoll"
+
 msgid "Package"
 msgstr "Paket"
 

src/cachy-auto-update-progress

@@ -8,6 +8,7 @@
 #
 #   info<TAB>text          headline, already translated by the caller
 #   detail<TAB>name<TAB>value  a labelled line under "Details"
+#   log<TAB>name<TAB>line<TAB>line...  the run log's last lines, one per field
 #   total<TAB>n            how many items this step has
 #   done<TAB>n             how many of them are finished
 #   percent<TAB>n          overall progress, 0-100
@@ -113,6 +114,16 @@ def main():
             elif cmd == "detail" and len(fields) > 2:
                 job.call("setDescriptionField",
                          GLib.Variant("(uss)", (0, arg, fields[2])))
+            elif cmd == "log" and len(fields) > 2:
+                # Field 1, and there is no field 2: the job model behind this
+                # interface carries exactly two, and anything further is
+                # discarded without complaint at the other end.
+                #
+                # The tail arrives one line per field, because the protocol
+                # itself is one instruction per line. Joined back up with the
+                # newlines the job view does render.
+                job.call("setDescriptionField",
+                         GLib.Variant("(uss)", (1, arg, "\n".join(fields[2:]))))
             elif cmd == "total":
                 job.call("setTotalAmount", GLib.Variant("(ts)", (int(arg), unit)))
             elif cmd == "done":

src/cachy-auto-update-run

@@ -192,6 +192,11 @@ progress_steps=(resolve download repo)
 progress_steps+=(cleanup)
 cau_progress_begin "${progress_steps[@]}"
 
+# And carry the run log's last lines along with it, so "Details" shows what the
+# update is doing during the stretches that have nothing to count - an AUR
+# package building for a quarter of an hour, most of all.
+cau_progress_tail_start "$CAU_RUNLOG"
+
 if ! cau_pacman_update; then
 	failed=1
 fi

src/lib/progress.sh

@@ -367,6 +367,83 @@ cau_progress_detail() {
 	done
 }
 
+# How many lines of the run log the job entry carries, and how wide each one
+# is allowed to be. Both are display limits rather than arbitrary ones: five
+# lines is about what fits under a notification popup before it starts pushing
+# the buttons off the bottom, and a line long enough to be elided anyway is
+# only costing room in the pipe. Together they also keep one instruction well
+# inside PIPE_BUF, which is what makes the write atomic against the runner
+# writing its own progress down the same pipe.
+CAU_PROGRESS_TAIL_LINES=5
+CAU_PROGRESS_TAIL_COLS=120
+CAU_PROGRESS_TAIL_PID=0
+
+# cau_progress_log <label-msgid> <text>
+# The second description field, holding the last few lines of the run log.
+#
+# The protocol is one instruction per line, so the tail travels tab separated
+# and is put back together on the other side. Tabs inside a log line would
+# split it in two on the way, so they become spaces first - the job view
+# renders either as whitespace, and a line broken in half renders as nonsense.
+cau_progress_log() {
+	local label="$1" text="$2" i fd
+
+	(( ${#CAU_PROGRESS_FDS[@]} )) || return 0
+
+	text="${text//$'\t'/ }"
+	text="${text//$'\n'/$'\t'}"
+
+	for i in "${!CAU_PROGRESS_FDS[@]}"; do
+		fd="${CAU_PROGRESS_FDS[$i]}"
+		[[ -n $fd ]] || continue
+		cau_msg_into "${CAU_PROGRESS_LOCALES[$i]}" "$label"
+		printf 'log\t%s\t%s\n' "$CAU_MSG_RESULT" "$text" >&"$fd" 2>/dev/null || true
+	done
+}
+
+# cau_progress_tail_start <logfile> / cau_progress_tail_stop
+# Follows the run log for as long as the update lasts, so expanding "Details"
+# shows what the update is actually doing right now.
+#
+# This is the answer to the part of a run that has no counter and never will:
+# an AUR helper compiling for a quarter of an hour says plenty about what it is
+# up to, none of it countable, and all of it going into a log file nobody is
+# looking at. The percentage says the update is alive; these lines say what it
+# is alive doing.
+#
+# Polled rather than followed with tail -F, for the same reason the pacman
+# watcher polls: only the last few lines are ever displayed, so every line in
+# between is work nobody would see. Re-read whole and compared, which also
+# makes truncation and rotation of the log a non-event.
+cau_progress_tail_start() {
+	local file="$1"
+
+	cau_progress_tail_stop
+	(( ${#CAU_PROGRESS_FDS[@]} )) || return 0
+	cau_have tail || return 0
+
+	{
+		local nap last='' now
+		exec {nap}<> <(:)
+		while :; do
+			read -r -t 2 -u "$nap" _ || true
+			now="$(tail -n "$CAU_PROGRESS_TAIL_LINES" "$file" 2>/dev/null \
+				| cut -c "1-${CAU_PROGRESS_TAIL_COLS}")"
+			[[ -n $now && $now != "$last" ]] || continue
+			last="$now"
+			cau_progress_log "Log" "$now"
+		done
+	} &
+	CAU_PROGRESS_TAIL_PID=$!
+}
+
+cau_progress_tail_stop() {
+	(( CAU_PROGRESS_TAIL_PID )) || return 0
+	kill "$CAU_PROGRESS_TAIL_PID" 2>/dev/null
+	wait "$CAU_PROGRESS_TAIL_PID" 2>/dev/null
+	CAU_PROGRESS_TAIL_PID=0
+}
+
 # cau_progress_end [outcome: ok|failed] [failure-msgid]
 # Closes the entry. Must run on every exit path, including a killed run: an
 # entry whose owner merely vanishes is reported by the desktop as "the
@@ -386,9 +463,11 @@ cau_progress_end() {
 	local outcome="${1:-ok}" msgid="${2:-}"
 	local i fd
 
-	# Before the descriptors go: a ticker still running would be writing into
+	# Before the descriptors go: anything still running in the background holds
-	# a pipe whose reader is about to be waited on.
+	# its own copy of them, so the helper would not see the end of its input
+	# until it exited - and it is about to be waited on.
 	cau_progress_creep_stop
+	cau_progress_tail_stop
 
 	# The last step never consumes its own share - nothing reports items for
 	# the cleanup - so the bar would stop a few percent short of the end and