From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp2 ([2001:41d0:2:4a6f::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms11 with LMTPS id KIRiKJdod18JcgAA0tVLHw (envelope-from ) for ; Fri, 02 Oct 2020 17:51:19 +0000 Received: from aspmx1.migadu.com ([2001:41d0:2:4a6f::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp2 with LMTPS id AEcrJJdod1/AFAAAB5/wlQ (envelope-from ) for ; Fri, 02 Oct 2020 17:51:19 +0000 Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by aspmx1.migadu.com (Postfix) with ESMTPS id 2216C940215 for ; Fri, 2 Oct 2020 17:51:19 +0000 (UTC) Received: from localhost ([::1]:36692 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1kOPDC-0007lV-1M for larch@yhetil.org; Fri, 02 Oct 2020 13:51:18 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:47236) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1kOPC0-00062C-4i for bug-guix@gnu.org; Fri, 02 Oct 2020 13:50:05 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:59167) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1kOPBx-0004bb-NJ for bug-guix@gnu.org; Fri, 02 Oct 2020 13:50:02 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1kOPBx-0001TE-Km for bug-guix@gnu.org; Fri, 02 Oct 2020 13:50:01 -0400 X-Loop: help-debbugs@gnu.org Subject: bug#43518: Guix substitute crash in procedure raise-exception: wrong type agument in position 1: #f Resent-From: Maxim Cournoyer Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Fri, 02 Oct 2020 17:50:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 43518 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: Ludovic =?UTF-8?Q?Court=C3=A8s?= Received: via spool by 43518-submit@debbugs.gnu.org id=B43518.16016609565596 (code B ref 43518); Fri, 02 Oct 2020 17:50:01 +0000 Received: (at 43518) by debbugs.gnu.org; 2 Oct 2020 17:49:16 +0000 Received: from localhost ([127.0.0.1]:42480 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1kOPBD-0001SB-Et for submit@debbugs.gnu.org; Fri, 02 Oct 2020 13:49:15 -0400 Received: from mail-qt1-f176.google.com ([209.85.160.176]:37058) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1kOPAx-0001RS-6u for 43518@debbugs.gnu.org; Fri, 02 Oct 2020 13:49:14 -0400 Received: by mail-qt1-f176.google.com with SMTP id m23so1979057qtq.4 for <43518@debbugs.gnu.org>; Fri, 02 Oct 2020 10:48:59 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:references:date:in-reply-to:message-id :user-agent:mime-version:content-transfer-encoding; bh=4UkqTleUXdnTwzMYFwgVbnwrLHE0OgXU5h4dUtUEEzM=; b=poHQBsrWcesXVo2bRVdl3iedWC9ovc9cFyMpcvE7QdAwAOvnNZWjAqpF3IDFlAKlGk 6rda05NeC+sLg81b9KtiT8dxATNh21sdH52hsxMXi21FRjQEF5BK5uUbo2WoaTfKo4Qt QPHrpZkviyfZzmxmAb02fI6e6YEloyXEkhrErb7BXs+GAygRfg6FoS8I9JLMlwpfXBIr lwrf3FEBHq486M4BcfiRIBjDQ4uH8QgEncy+n40oL1FqY6o73XMzXjkMwImgulqWQ/Bx UV+e9iH6YLsJkPSbkFcLL5bOZ8AbvHtH1uSsIX37IKbDK9SHZbfgWhaX1AShAAK9MEF3 3wfA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:references:date:in-reply-to :message-id:user-agent:mime-version:content-transfer-encoding; bh=4UkqTleUXdnTwzMYFwgVbnwrLHE0OgXU5h4dUtUEEzM=; b=jul8fk34vXYKnxTWNR63RSC7R2Ff0dF7D9bPyc25LZDPzZbfDwdrejqB2EaRIVHA6b FkFUF1eQ4zKRWu+x+pGGIqWBdUqUy6XwEe5CR3pZNbf54i1SET4BIz0WG6C9RD5W6LKA /2g2iOmy07D6ODGb87JXA/AC7FDVFcJYQCMe13hXNqWittr/7Iv3ZqhZ+EZB/4eDhoZh bfLmpdgIVFzqPcbCIFyAG6jrtBZlDJ1o16GJgrhMx1KD89TXcr2GtG40Epa0DijaDTGT yw0hVljJUuAD/IVUznTLHimzEO9pIReSCepSLO1KV2Zxzf7UlieB/5NJ9ilpsk4ZYb2B HVFA== X-Gm-Message-State: AOAM533P+8QYqIcJ3O+LkC76aLKxtSjLwgY1RQXXlXNPJjnqlh2Qiyym K8cMA69LmP8dfPda8cfiJBGRVxlpzz4= X-Google-Smtp-Source: ABdhPJxOoz/98jMMRpzLU/q3skmohqPZY8ksuXkgsqxQyvOGJ9AyaFie1cVEPWXFiwRBDDC73Y6pJA== X-Received: by 2002:ac8:4e31:: with SMTP id d17mr3544250qtw.43.1601660933262; Fri, 02 Oct 2020 10:48:53 -0700 (PDT) Received: from hurd (dsl-10-135-18.b2b2c.ca. [72.10.135.18]) by smtp.gmail.com with ESMTPSA id k22sm1561884qkk.13.2020.10.02.10.48.52 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 02 Oct 2020 10:48:52 -0700 (PDT) From: Maxim Cournoyer References: <87imc9y8hq.fsf@gmail.com> <873630plg1.fsf@gmail.com> <87wo0bxjvd.fsf@gnu.org> Date: Fri, 02 Oct 2020 13:50:33 -0400 In-Reply-To: <87wo0bxjvd.fsf@gnu.org> ("Ludovic =?UTF-8?Q?Court=C3=A8s?="'s message of "Wed, 30 Sep 2020 19:19:34 +0200") Message-ID: <87zh54ms9i.fsf@gmail.com> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.1 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-Spam-Score: 0.0 (/) X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-Spam-Score: -1.0 (-) X-BeenThere: bug-guix@gnu.org List-Id: Bug reports for GNU Guix List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: 43518@debbugs.gnu.org Errors-To: bug-guix-bounces+larch=yhetil.org@gnu.org Sender: "bug-Guix" X-Scanner: scn0 Authentication-Results: aspmx1.migadu.com; dkim=fail (rsa verify failed) header.d=gmail.com header.s=20161025 header.b=poHQBsrW; dmarc=fail reason="SPF not aligned (relaxed)" header.from=gmail.com (policy=none); spf=pass (aspmx1.migadu.com: domain of bug-guix-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=bug-guix-bounces@gnu.org X-Spam-Score: 0.09 X-TUID: B1fEuKefLk+4 Hello! Ludovic Court=C3=A8s writes: > Hi, > > Maxim Cournoyer skribis: > >> downloading from https://ci.guix.gnu.org/nar/6m9zimmw8p6gbc1yfbg454c1r58= 7b7h4-gcc-10.2.0.tar.xz ... > [=E2=80=A6] >> gcc-10.2.0.tar.xz 74.3MiB 1.1MiB/s= 00:25 [####### ] 39.1%Backtrace: > [=E2=80=A6] >> In unknown file: >> 5 (display "@ substituter-succeeded /gnu/store/r06j3ms57z4mzf= pdzfclsi3i9hr4184g-module-imp=E2=80=A6" =E2=80=A6) >> In guix/status.scm: >> 699:16 4 (write! _ _ _) >> 613:6 3 (_ (download-progress "/gnu/store/6m9zimmw8p6gbc1yfbg454c1r= 587b7h4-gcc-10.2.0.tar.xz" # =E2=80=A6) =E2=80=A6) >> In guix/progress.scm: >> 213:14 2 (display-download-progress "6m9zimmw8p6gbc1yfbg454c1r58@" _= #:start-time _ #:transferred _ =E2=80=A6) >> 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 =3D: Wrong type argument in position 1: #f > > If you have a case that=E2=80=99s reproducible, please take advantage of = it and > add =E2=80=98pk=E2=80=99 calls in (guix progress) to see what happens. H= ere it seems > that =E2=80=98transferred=E2=80=99 (in =E2=80=98display-download-progress= =E2=80=99) is #f. > > The #f would come from this clause in (guix status): > > ('download-progress item uri > (=3D string->number size) > (=3D string->number transferred)) ;<- here > > That in turn comes from =E2=80=98progress-reporter/trace=E2=80=99, 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 =E2=80=9C@ > download-progress=E2=80=9D traces, and thus not getting the right =E2=80= =98transferred=E2=80=99 > value. > > Could you try to reproduce it while =E2=80=98guix=E2=80=99 is running und= er strace? > Like: > > strace -o log -s 200 guix build whatever --max-jobs=3D20 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))) =20 + (pk 'display-download-progress 'file=3D file 'size=3D size 'transferred= =3D 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=3D 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 pro= cessed elsewhere." log-port))) (report (let ((report (rate-limited report-progress %progress-interval)= )) (lambda (transferred) + (pk 'progress-reporter/trace 'total=3D total 'transferred= =3D 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=3D to= tal)) 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 aga= inst 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-abbreviati= on)))) + (reporter (pk 'reporter (if print-build-trace? + (progress-reporter/t= race + destination + (uri->string uri) d= l-size + (current-error-port= )) + (progress-reporter/f= ile + (uri->string uri) d= l-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." (=3D string->number transferred)) ;; Print a progress bar, but only if there's only one on-going ;; job--otherwise the output would be intermingled. - (when (=3D 1 (simultaneous-jobs status)) + (pk 'print-build-event:download-progress 'transferred=3D transferred) + (when (=3D 1 (pk 'simultaneous-jobs=3D (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=3D 4980832) = ;;; (simultaneous-jobs=3D 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