Hello! Ludovic Courtès writes: > Hi, > > Maxim Cournoyer 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 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