bug#55360: [Installer] ‘guix system init’ displays dots instead of progress bars

bug#55360: [Installer] ‘guix system init’ displays dots instead of progress bars

[Ludovic Courtès]

Hi!

I’ve used an installer built from this commit:

--8<---------------cut here---------------start------------->8---
Generation 214	May 02 2022 21:44:14	(current)
  guix 6b588da
    repository URL: https://git.savannah.gnu.org/git/guix.git
    branch: master
    commit: 6b588da368c77cde82ea2f22ca315116228777ad
--8<---------------cut here---------------end--------------->8---

During installation, ‘guix system init’ displays dots instead of
progress bars for downloads and such.

This suggests that ‘display-download-progress’ gets #:tty? #f.  This may
be a side effect of running it in a pipe in
‘run-external-command-with-handler’.

Thoughts?

Ludo’.

bug#55360: [Installer] ‘guix system init’ displays dots instead of progress bars

[Ludovic Courtès]

Hi!

Ludovic Courtès <ludo@gnu.org> skribis:

> During installation, ‘guix system init’ displays dots instead of
> progress bars for downloads and such.
>
> This suggests that ‘display-download-progress’ gets #:tty? #f.  This may
> be a side effect of running it in a pipe in
> ‘run-external-command-with-handler’.

This was introduced by:

  commit 0b9fbbb4dd24f227c9a708561ba291f6169ad2e6
  Date:   Sat Jan 15 14:50:00 2022 +0100

      installer: Capture external commands output.

      * gnu/installer/utils.scm (run-external-command-with-handler,
      run-external-command-with-line-hooks): New variables.
      (run-command): Use run-external-command-with-line-hooks.

According to <https://issues.guix.gnu.org/53063#0-lineno9>, the goal was
(unsurprisingly) to log standard output of commands.

I’m not sure it’s a good idea for ‘guix system init’: we’d be logging
mostly progress bars, package names, and the likes to syslog—not super
useful.  So I’d suggest not capturing stdout of ‘guix system init’.

However, I wouldn’t mind factorizing the syslog facilities from
2cf65e1d543407bc7db43e7c7d39a215907efebc into, say, (guix syslog), and
have (guix scripts system) use it to log important events.

Thoughts?

What about using ‘run-external-command-with-line-hooks’ for other
commands though?  IIUC, the primary use case is file system tools.

My gut feeling is that the cost/benefit ratio isn’t worth it (the cost
here is complexity and maintenance burden of
‘run-external-command-with-handler’ & co.; the benefit is improved
logging).

WDYT?

I can hopefully dedicate a bit of time to this, but I need your
guidance, comrades.  :-)

Ludo’.

bug#55360: bug#58375: Installer does not show what is being downloaded

[Mathieu Othacehe]

Hey Ludo!

> I’m not sure it’s a good idea for ‘guix system init’: we’d be logging
> mostly progress bars, package names, and the likes to syslog—not super
> useful.  So I’d suggest not capturing stdout of ‘guix system init’.

In the bug report https://issues.guix.gnu.org/57983 capturing the 'guix
system init' output highlighted a "guix substitute" crash. So it does
seem like a useful mechanism, especially while 56005 is still open.

Now the current situation is also not really acceptable. What about
hiding the "guix system init" output completely and display a progress
bar page instead?

Thanks,

Mathieu

bug#55360: bug#58375: Installer does not show what is being downloaded

[Ludovic Courtès]

Hi!

Mathieu Othacehe <othacehe@gnu.org> skribis:

>> I’m not sure it’s a good idea for ‘guix system init’: we’d be logging
>> mostly progress bars, package names, and the likes to syslog—not super
>> useful.  So I’d suggest not capturing stdout of ‘guix system init’.
>
> In the bug report https://issues.guix.gnu.org/57983 capturing the 'guix
> system init' output highlighted a "guix substitute" crash. So it does
> seem like a useful mechanism, especially while 56005 is still open.

Hmm right.  <https://issues.guix.gnu.org/56005> is not
installer-specific, so it’s annoying that we have to prepare for that,
but we can’t deny such bugs exist and prevent installation.

If we really want to capture the output of ‘guix system init’, then we
need to open a pseudo-terminal with ‘openpty’ & co. instead of ‘pipe’ in
‘run-external-command-with-handler’.  That may be relatively easy
actually.

But then I think this should be used sparsely, maybe only for ‘guix
system init’.

> Now the current situation is also not really acceptable.

Nope.  :-)

> What about hiding the "guix system init" output completely and display
> a progress bar page instead?

I don’t think we can do that (with grafts, only part of the build plan
is known upfront so we don’t even know beforehand how many items will be
built/downloaded).

Also, I think there are two strategies: either we run ‘guix system
init’, in which case we let its output through, or we integrate ‘guix
system init’ functionality in the installer so we have more fine-grain
control over the process, in which case we could also have more
graphical output or something.

That second solution is a lot of work, though.

Thanks,
Ludo’.

bug#58375: Installer does not show what is being downloaded

[Mathieu Othacehe]

[-- Attachment #1: Type: text/plain, Size: 1222 bytes --]


Hey,

> If we really want to capture the output of ‘guix system init’, then we
> need to open a pseudo-terminal with ‘openpty’ & co. instead of ‘pipe’ in
> ‘run-external-command-with-handler’.  That may be relatively easy
> actually.

So I implemented your proposal. It seems to be working quite well. As
discussed on #guix, we could avoid to dump the download bars to the
syslog if the "guix system init" command succeeds. However, it seems
quite tricky in the current implementation where the syslog dumping is
actually a hook (%syslog-line-hook).

Fixing this issue, I also realized that when the "guix system init"
command fails, the user is only offered to resume the installation or
restart it.

In cases where "guix system init" failed because of a network issue, or
because a partition was too small, restarting/resuming seems like the
right thing to do.

However, when the installer failed because "guix system init" crashed or
segfaulted, restarting/resuming won't probably help, and dumping the
crash is probably the best way to get help. That's why I added in a
second patch, a new button "Report the failure" to the
"run-install-failed-page".

Thanks,

Mathieu

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-installer-Run-the-guix-system-init-command-in-a-PTY.patch --]
[-- Type: text/x-patch, Size: 5054 bytes --]

From c6286404e9c4c0dc302c3d398a8f27b050cf4ce0 Mon Sep 17 00:00:00 2001
From: Mathieu Othacehe <othacehe@gnu.org>
Date: Fri, 14 Oct 2022 17:28:27 +0200
Subject: [PATCH 1/2] installer: Run the "guix system init" command in a PTY.

Fixes: <https://issues.guix.gnu.org/55360>

* gnu/installer/utils.scm (run-external-command-with-handler/tty): New
procedure.
(run-external-command-with-line-hooks, run-command): Add a TTY? argument.
* gnu/installer/final.scm (install-system): Call run-command with TTY?
argument set to #true.
---
 gnu/installer/final.scm |  2 +-
 gnu/installer/utils.scm | 50 +++++++++++++++++++++++++++++++++--------
 2 files changed, 42 insertions(+), 10 deletions(-)

diff --git a/gnu/installer/final.scm b/gnu/installer/final.scm
index 3f6dacc490..044f79372b 100644
--- a/gnu/installer/final.scm
+++ b/gnu/installer/final.scm
@@ -211,7 +211,7 @@ (define (assert-exit x)
 
              (setenv "PATH" "/run/current-system/profile/bin/")
 
-             (set! ret (run-command install-command)))
+             (set! ret (run-command install-command #:tty? #t)))
            (lambda ()
              ;; Restart guix-daemon so that it does no keep the MNT namespace
              ;; alive.
diff --git a/gnu/installer/utils.scm b/gnu/installer/utils.scm
index 5fd2e2d425..061493e6a7 100644
--- a/gnu/installer/utils.scm
+++ b/gnu/installer/utils.scm
@@ -20,6 +20,7 @@
 (define-module (gnu installer utils)
   #:use-module (gnu services herd)
   #:use-module (guix utils)
+  #:use-module ((guix build syscalls) #:select (openpty login-tty))
   #:use-module (guix build utils)
   #:use-module (guix i18n)
   #:use-module (srfi srfi-1)
@@ -45,6 +46,7 @@ (define-module (gnu installer utils)
             nearest-exact-integer
             read-percentage
             run-external-command-with-handler
+            run-external-command-with-handler/tty
             run-external-command-with-line-hooks
             run-command
             run-command-in-installer
@@ -124,10 +126,37 @@ (define dummy-pipe
     (close-port input)
     (close-pipe dummy-pipe)))
 
-(define (run-external-command-with-line-hooks line-hooks command)
+(define (run-external-command-with-handler/tty handler command)
+  "Run command specified by the list COMMAND in a child operating in a
+pseudoterminal with output handler HANDLER.  HANDLER is a procedure taking an
+input port, to which the command will write its standard output and error.
+Returns the integer status value of the child process as returned by waitpid."
+  (define-values (controller inferior)
+    (openpty))
+
+  (match (primitive-fork)
+    (0
+     (catch #t
+       (lambda ()
+         (close-fdes controller)
+         (login-tty inferior)
+         (apply execlp (car command) command))
+       (lambda _
+         (primitive-exit 127))))
+    (pid
+     (close-fdes inferior)
+     (let* ((port (fdopen controller "r0"))
+            (result (false-if-exception
+                     (handler port))))
+       (close-port port)
+       (cdr (waitpid pid))))))
+
+(define* (run-external-command-with-line-hooks line-hooks command
+                                               #:key (tty? #false))
   "Run command specified by the list COMMAND in a child, processing each
-output line with the procedures in LINE-HOOKS.  Returns the integer status
-value of the child process as returned by waitpid."
+output line with the procedures in LINE-HOOKS.  If TTY is set to #true, the
+COMMAND will be run in a pseudoterminal.  Returns the integer status value of
+the child process as returned by waitpid."
   (define (handler input)
     (and
      (and=> (get-line input)
@@ -136,14 +165,17 @@ (define (handler input)
                   #f
                   (begin (for-each (lambda (f) (f line))
                                    (append line-hooks
-                                       %default-installer-line-hooks))
+                                           %default-installer-line-hooks))
                          #t))))
      (handler input)))
-  (run-external-command-with-handler handler command))
+  (if tty?
+      (run-external-command-with-handler/tty handler command)
+      (run-external-command-with-handler handler command)))
 
-(define* (run-command command)
+(define* (run-command command #:key (tty? #f))
   "Run COMMAND, a list of strings.  Return true if COMMAND exited
-successfully, #f otherwise."
+successfully, #f otherwise.  If TTY is set to #true, the COMMAND will be run
+in a pseudoterminal."
   (define (pause)
     (format #t (G_ "Press Enter to continue.~%"))
     (send-to-clients '(pause))
@@ -154,8 +186,8 @@ (define (pause)
 
   (installer-log-line "running command ~s" command)
   (define result (run-external-command-with-line-hooks
-                  (list %display-line-hook)
-                  command))
+                  (list %display-line-hook) command
+                  #:tty? tty?))
   (define exit-val (status:exit-val result))
   (define term-sig (status:term-sig result))
   (define stop-sig (status:stop-sig result))
-- 
2.37.3


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #3: 0002-installer-Propose-the-user-to-report-a-guix-system-i.patch --]
[-- Type: text/x-patch, Size: 1426 bytes --]

From 159b82a013cad8c3c698031cce9ee07956153da3 Mon Sep 17 00:00:00 2001
From: Mathieu Othacehe <othacehe@gnu.org>
Date: Fri, 14 Oct 2022 17:33:28 +0200
Subject: [PATCH 2/2] installer: Propose the user to report a "guix system
 init" failure.

* gnu/installer/newt/final.scm (run-install-failed-page): Add a "Report the
failure" button.
---
 gnu/installer/newt/final.scm | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/gnu/installer/newt/final.scm b/gnu/installer/newt/final.scm
index 7c3f73ee82..6e55be5067 100644
--- a/gnu/installer/newt/final.scm
+++ b/gnu/installer/newt/final.scm
@@ -80,16 +80,21 @@ (define (run-install-success-page)
 (define (run-install-failed-page)
   (match (current-clients)
     (()
-     (match (choice-window
+     (match (ternary-window
              (G_ "Installation failed")
              (G_ "Resume")
              (G_ "Restart the installer")
+             (G_ "Report the failure")
              (G_ "The final system installation step failed.  You can resume from \
 a specific step, or restart the installer."))
        (1 (abort-to-prompt 'installer-step 'abort))
        (2
         ;; Keep going, the installer will be restarted later on.
-        #t)))
+        #t)
+       (3 (raise
+           (condition
+            (&message
+             (message "User abort.")))))))
     (_
      (send-to-clients '(installation-failure))
      #t)))
-- 
2.37.3

bug#58375: Installer does not show what is being downloaded

[Ludovic Courtès]

Hi Mathieu,

Mathieu Othacehe <othacehe@gnu.org> skribis:

> So I implemented your proposal. It seems to be working quite well. As
> discussed on #guix, we could avoid to dump the download bars to the
> syslog if the "guix system init" command succeeds. However, it seems
> quite tricky in the current implementation where the syslog dumping is
> actually a hook (%syslog-line-hook).

Yes.

I haven’t actually tested the patch but it LGTM.  One thing to check is
whether ‘terminal-window-size’ returns something sensible for the
pseudo-terminal; it could be that we need an extra ioctl so the
pseudo-terminal has the same size as the actual terminal.

> Fixing this issue, I also realized that when the "guix system init"
> command fails, the user is only offered to resume the installation or
> restart it.
>
> In cases where "guix system init" failed because of a network issue, or
> because a partition was too small, restarting/resuming seems like the
> right thing to do.
>
> However, when the installer failed because "guix system init" crashed or
> segfaulted, restarting/resuming won't probably help, and dumping the
> crash is probably the best way to get help. That's why I added in a
> second patch, a new button "Report the failure" to the
> "run-install-failed-page".

Neat!

> From c6286404e9c4c0dc302c3d398a8f27b050cf4ce0 Mon Sep 17 00:00:00 2001
> From: Mathieu Othacehe <othacehe@gnu.org>
> Date: Fri, 14 Oct 2022 17:28:27 +0200
> Subject: [PATCH 1/2] installer: Run the "guix system init" command in a PTY.
>
> Fixes: <https://issues.guix.gnu.org/55360>
>
> * gnu/installer/utils.scm (run-external-command-with-handler/tty): New
> procedure.
> (run-external-command-with-line-hooks, run-command): Add a TTY? argument.
> * gnu/installer/final.scm (install-system): Call run-command with TTY?
> argument set to #true.

LGTM, modulo the terminal size issue mentioned above.

> From 159b82a013cad8c3c698031cce9ee07956153da3 Mon Sep 17 00:00:00 2001
> From: Mathieu Othacehe <othacehe@gnu.org>
> Date: Fri, 14 Oct 2022 17:33:28 +0200
> Subject: [PATCH 2/2] installer: Propose the user to report a "guix system
>  init" failure.
>
> * gnu/installer/newt/final.scm (run-install-failed-page): Add a "Report the
> failure" button.

LGTM.

Thank you!

Ludo’.

bug#55360: bug#58375: Installer does not show what is being downloaded

[Mathieu Othacehe]

Hey,

Thanks for having a look!

> I haven’t actually tested the patch but it LGTM.  One thing to check is
> whether ‘terminal-window-size’ returns something sensible for the
> pseudo-terminal; it could be that we need an extra ioctl so the
> pseudo-terminal has the same size as the actual terminal.

Well it returns 0 for all fields, but I tested on several screen sizes
and everything seems fine so I went ahead.

While testing I noticed two new issues though:

1. When the disk is GPT partitionned there is no confirmation page in
  "run-label-page". Something I missed in #57232.

2. When there is an exception in run-external-command-with-handler/tty
    for instance, the backtrace page is displayed in the PTY and the
    keyboard shortcuts do not work anymore.

I'll address point 1 shortly but could use some advice for point 2.

Thanks,

Mathieu

bug#58375: Installer does not show what is being downloaded

[Julien Lepiller]

[-- Attachment #1: Type: text/plain, Size: 513 bytes --]

I installed Guix on a new drive, so I tried the installer from the latest image. After reviewing the system config, the installer goes to a black screen where guix output is shown. Although I can see messages about substitutes being updated, and how much will be downloaded, all download lines are replaced with a seemingly random number of dots:

substitute: mise à jour des substituts depuis «…»... 100.0 %
4.5 Mo seront téléchargés.
.
...
.
.
......

Maybe this is related to the translation?

[-- Attachment #2: Type: text/html, Size: 574 bytes --]

bug#58375: Installer does not show what is being downloaded

[Josselin Poiret via Bug reports for GNU Guix]

Hi Julien,

Julien Lepiller <julien@lepiller.eu> writes:
> I installed Guix on a new drive, so I tried the installer from the latest image. After reviewing the system config, the installer goes to a black screen where guix output is shown. Although I can see messages about substitutes being updated, and how much will be downloaded, all download lines are replaced with a seemingly random number of dots:
>
> substitute: mise à jour des substituts depuis «…»... 100.0 %
> 4.5 Mo seront téléchargés.
> .
> ...
> .
> .
> ......
>
> Maybe this is related to the translation?

I agree that this does look pretty bad, but this is because we capture
the guix command output to a log file so that we're able to include it
in the installer dump if anything goes wrong.  Guix detects it's not
talking directly to a terminal and so doesn't try to use terminal
specific escape codes to display the download progress.  I don't know
how we could improve on that front though, since in general capturing
the guix command output helps with debugging issues.

Best,
-- 
Josselin Poiret

bug#58375: Installer does not show what is being downloaded

[Ludovic Courtès]

Hello!

Josselin Poiret <dev@jpoiret.xyz> skribis:

> Julien Lepiller <julien@lepiller.eu> writes:
>> I installed Guix on a new drive, so I tried the installer from the latest image. After reviewing the system config, the installer goes to a black screen where guix output is shown. Although I can see messages about substitutes being updated, and how much will be downloaded, all download lines are replaced with a seemingly random number of dots:
>>
>> substitute: mise à jour des substituts depuis «…»... 100.0 %
>> 4.5 Mo seront téléchargés.
>> .
>> ...
>> .
>> .
>> ......
>>
>> Maybe this is related to the translation?
>
> I agree that this does look pretty bad, but this is because we capture
> the guix command output to a log file so that we're able to include it
> in the installer dump if anything goes wrong.  Guix detects it's not
> talking directly to a terminal and so doesn't try to use terminal
> specific escape codes to display the download progress.  I don't know
> how we could improve on that front though, since in general capturing
> the guix command output helps with debugging issues.

This is a duplicate of <https://issues.guix.gnu.org/55360>, marked as
important.

I think capturing all the output as-is is overkill; one option I
suggested in the bug report above is to syslog specific events of
interest during ‘guix system init’.

Thoughts?

Ludo’.