Subject: Re: bug#43518: Guix substitute crash in procedure raise-exception: wrong type agument in position 1: #f

From: Maxim Cournoyer <[email-masked]>
Date: Fri, 02 Oct 2020 13:50:33 -0400

Hello!

Ludovic Courtès <[email-masked]> writes:

> Hi,
>
> Maxim Cournoyer <[email-masked]> skribis:
>
>> downloading from https://ci.guix.gnu.org/nar/6m9zimmw8p6gbc1yfbg454c1r587b7h4-gcc-10.2.0.tar.xz ...
> […]
>>  gcc-10.2.0.tar.xz  74.3MiB                                     1.1MiB/s 00:25 [#######           ]  39.1%Backtrace:
> […]
>> In unknown file:
>>            5 (display "@ substituter-succeeded /gnu/store/r06j3ms57z4mzfpdzfclsi3i9hr4184g-module-imp…" …)
>> In guix/status.scm:
>>    699:16  4 (write! _ _ _)
>>     613:6  3 (_ (download-progress "/gnu/store/6m9zimmw8p6gbc1yfbg454c1r587b7h4-gcc-10.2.0.tar.xz" # …) …)
>> In guix/progress.scm:
>>    213:14  2 (display-download-progress "6m9zimmw8p6gbc1yfbg454c1r58@" _ #:start-time _ #:transferred _ …)
>> In ice-9/boot-9.scm:
>>   1669:16  1 (raise-exception _ #:continuable? _)
>>   1669:16  0 (raise-exception _ #:continuable? _)
>>
>> ice-9/boot-9.scm:1669:16: In procedure raise-exception:
>> In procedure =: Wrong type argument in position 1: #f
>
> If you have a case that’s reproducible, please take advantage of it and
> add ‘pk’ calls in (guix progress) to see what happens.  Here it seems
> that ‘transferred’ (in ‘display-download-progress’) is #f.
>
> The #f would come from this clause in (guix status):
>
>      ('download-progress item uri
>                          (= string->number size)
>                          (= string->number transferred))  ;<- here
>
> That in turn comes from ‘progress-reporter/trace’, called from (guix
> scripts substitute).

It's a bit difficult for me to follow the calls here :-).  I thought
it'd have to be in 'progress-reporter/file' because that's the only one
that ends up calling display-download-progress.  The line 213 of (guix
progress) is:

      (unless (zero? transferred)

and if transferred is #f that would indeed fail with the error message
shown in the backtrace, so it seems you are correct in your analysis.

> It looks like this issue happens when max-jobs is (noticeably) greater
> than 1, as if the client was receiving intermingled “@
> download-progress” traces, and thus not getting the right ‘transferred’
> value.
>
> Could you try to reproduce it while ‘guix’ is running under strace?
> Like:
>
>   strace -o log -s 200 guix build whatever --max-jobs=20

I've reconfigured my offload machine to support 20 jobs, and
instrumented my local checkouts with the following pk calls:

--8<---------------cut here---------------start------------->8---
3 files changed, 18 insertions(+), 11 deletions(-)
guix/progress.scm           |  7 ++++++-
guix/scripts/substitute.scm | 19 ++++++++++---------
guix/status.scm             |  3 ++-

modified   guix/progress.scm
@@ -194,6 +194,7 @@ throughput."
      (time-difference (current-time (time-type start-time))
                       start-time)))
 
+  (pk 'display-download-progress 'file= file 'size= size 'transferred= transferred)
   (if (and (number? size) (not (zero? size)))
       (let* ((%  (* 100.0 (/ transferred size)))
              (throughput (/ transferred elapsed))
@@ -247,7 +248,10 @@ ABBREVIATION used to shorten FILE for display."
      (report
       (let ((rate-limited-render (rate-limited render %progress-interval)))
         (lambda (value)
+          (pk 'called-render/transferred= transferred)
+          (pk 'file: file 'size: size)
           (set! transferred value)
+          (pk 'transferred-set-to value)
           (rate-limited-render))))
      ;; Don't miss the last report.
      (stop render))))
@@ -307,6 +311,7 @@ progress reports, write \"build trace\" lines to be processed elsewhere."
                      log-port)))
    (report (let ((report (rate-limited report-progress %progress-interval)))
              (lambda (transferred)
+               (pk 'progress-reporter/trace 'total= total 'transferred= transferred)
                (set! total transferred)
                (report transferred))))
    (stop (lambda ()
@@ -348,7 +353,7 @@ REPORTER, which should be a <progress-reporter> object."
                                 ((? eof-object?) 0)
                                 (x x))))
                        (set! total (+ total n))
-                       (report total)
+                       (report (pk 'progress-report-port:read!:total= total))
                        n))))
        (start)
        (make-custom-binary-input-port "progress-port-proc"
modified   guix/scripts/substitute.scm
@@ -991,15 +991,16 @@ DESTINATION as a nar file.  Verify the substitute against ACL."
                    (let* ((dl-size  (or download-size
                                         (and (equal? compression "none")
                                              (narinfo-size narinfo))))
-                          (reporter (if print-build-trace?
-                                        (progress-reporter/trace
-                                         destination
-                                         (uri->string uri) dl-size
-                                         (current-error-port))
-                                        (progress-reporter/file
-                                         (uri->string uri) dl-size
-                                         (current-error-port)
-                                         #:abbreviation nar-uri-abbreviation))))
+                          (reporter (pk 'reporter (if print-build-trace?
+                                                      (progress-reporter/trace
+                                                       destination
+                                                       (uri->string uri) dl-size
+                                                       (current-error-port))
+                                                      (progress-reporter/file
+                                                       (uri->string uri) dl-size
+                                                       (current-error-port)
+                                                       #:abbreviation nar-uri-abbreviation)))))
+                     (error 'quit)
                      (progress-report-port reporter raw)))
                   ((input pids)
                    ;; NOTE: This 'progress' port of current process will be
modified   guix/status.scm
@@ -532,7 +532,8 @@ addition to build events."
                          (= string->number transferred))
      ;; Print a progress bar, but only if there's only one on-going
      ;; job--otherwise the output would be intermingled.
-     (when (= 1 (simultaneous-jobs status))
+     (pk 'print-build-event:download-progress 'transferred= transferred)
+     (when (= 1 (pk 'simultaneous-jobs= (simultaneous-jobs status)))
        (match (find (matching-download item)
                     (build-status-downloading status))
          (#f #f)                                  ;shouldn't happen!
--8<---------------cut here---------------end--------------->8---

It seems that the only pk messages I see are the ones I put in (guix
status).  Perhaps the other modules are not taken from the client but
from the daemon?  I'm confused :-).

--8<---------------cut here---------------start------------->8---
;;; (print-build-event:download-progress transferred= 4980832)                                                       ;;; (simultaneous-jobs= 3)
--8<---------------cut here---------------end--------------->8---

But so far haven't been able to reproduce the error.  I'll keep
recording strace log when building things in the hope of catching the
bug!

To be continued...

Thanks for the help!

Maxim