GNU bug report logs - #32895
file progress reporter crashes on small files

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 32895 in the body.
You can then email your comments to 32895 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
To: <bug-guix <at> gnu.org>
Subject: file progress reporter crashes on small files
Date: Mon, 1 Oct 2018 16:16:31 +0200

Downloading small files (such as cabal revisions) sometimes fails with a
backtrace like this:

--8<---------------cut here---------------start------------->8---
Starting download of /gnu/store/plr3hf9gjdcg2qhi3x4k2wjm8zajqibc-ghc-cryptohash-md5-0.11.100.1-2.cabal
From https://hackage.haskell.org/package/cryptohash-md5-0.11.100.1/revision/2.cabal...
downloading from https://hackage.haskell.org/package/cryptohash-md5-0.11.100.1/revision/2.cabal...
Backtrace:                                                     7.6MiB/s 00:00 | 3KiB transferred
In ice-9/boot-9.scm:
    829:9 19 (catch _ _ #<procedure 7f8718d34458 at guix/ui.scm:615â¦> â¦)
    829:9 18 (catch _ _ #<procedure 7f8718d34470 at guix/ui.scm:733â¦> â¦)
In guix/scripts/build.scm:
   749:24 17 (_)
In ice-9/boot-9.scm:
    829:9 16 (catch _ _ #<procedure 2a53440 at ice-9/boot-9.scm:104â¦> â¦)
In guix/ui.scm:
    409:6 15 (_)
In guix/scripts/build.scm:
    675:5 14 (_)
In srfi/srfi-1.scm:
   679:15 13 (append-map _ _ . _)
   592:17 12 (map1 (#<package ngless <at> 0.9.1 gnu/packages/bioinformatâ¦>))
In guix/scripts/build.scm:
   680:31 11 (_ _)
In guix/packages.scm:
   881:14 10 (cache! #<weak-table 782/883> #<package ngless <at> 0.9.1 gâ¦> â¦)
In unknown file:
           9 (_ #<procedure thunk ()> #<procedure list _> #<undefined>)
In guix/grafts.scm:
    303:4  8 (graft-derivation #<build-daemon 256.98 2a54f50> #<derâ¦> â¦)
    181:4  7 (references-oracle #<build-daemon 256.98 2a54f50> #<derâ¦>)
   190:20  6 (_ _ _)
In guix/store.scm:
  1087:15  5 (_ #<build-daemon 256.98 2a54f50> _ _)
   661:13  4 (process-stderr _ _)
In unknown file:
           3 (display "@ download-progress /gnu/store/plr3hf9gjdcg2â¦" â¦)
In guix/status.scm:
   457:13  2 (write! _ _ 186)
    421:6  1 (_ (download-progress "/gnu/store/plr3hf9gjdcg2qhi3â¦" â¦) â¦)
In guix/progress.scm:
   214:25  0 (display-download-progress "2.cabal" #f #:start-time _ # â¦)

guix/progress.scm:214:25: In procedure display-download-progress:
In procedure /: Wrong type argument in position 1: #f
--8<---------------cut here---------------end--------------->8---

This happens because “transferred” in the “else” branch of (@ (guix
progress) display-download-progress) is #f instead of a number.  This
could be the result of running string->number on an invalid string in
“print-build-event”.


--
Ricardo

Message #8 received at 32895 <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
Cc: 32895 <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Tue, 02 Oct 2018 14:34:50 +0200

Hello,

Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de> skribis:

> guix/progress.scm:214:25: In procedure display-download-progress:
> In procedure /: Wrong type argument in position 1: #f
>
> This happens because “transferred” in the “else” branch of (@ (guix
> progress) display-download-progress) is #f instead of a number.  This
> could be the result of running string->number on an invalid string in
> “print-build-event”.

Indeed, that seems to be the case.  This would mean we’re emitting an
incorrect build trace.

Do you have the exact command to reproduce it?

Thanks,
Ludo’.

Message #11 received at 32895 <at> debbugs.gnu.org (full text, mbox):

From: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 32895 <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Tue, 2 Oct 2018 16:27:08 +0200

Ludovic Courtès <ludo <at> gnu.org> writes:

> Hello,
>
> Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de> skribis:
>
>> guix/progress.scm:214:25: In procedure display-download-progress:
>> In procedure /: Wrong type argument in position 1: #f
>>
>> This happens because “transferred” in the “else” branch of (@ (guix
>> progress) display-download-progress) is #f instead of a number.  This
>> could be the result of running string->number on an invalid string in
>> “print-build-event”.
>
> Indeed, that seems to be the case.  This would mean we’re emitting an
> incorrect build trace.
>
> Do you have the exact command to reproduce it?

Unfortunately, I don’t.  It’s hard to reproduce this when all these
cabal revisions have already been downloaded.  This also depends a lot
on the actual download speed.

I only got this for cabal revisions, so locally building any of the
ghc-* packages with #:cabal-revision arguments might be sufficient to
trigger the bug.

--
Ricardo

Message #16 received at 32895 <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
Cc: 32895 <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Wed, 03 Oct 2018 23:08:54 +0200

Hello,

Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de> skribis:

> Ludovic Courtès <ludo <at> gnu.org> writes:
>
>> Hello,
>>
>> Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de> skribis:
>>
>>> guix/progress.scm:214:25: In procedure display-download-progress:
>>> In procedure /: Wrong type argument in position 1: #f
>>>
>>> This happens because “transferred” in the “else” branch of (@ (guix
>>> progress) display-download-progress) is #f instead of a number.  This
>>> could be the result of running string->number on an invalid string in
>>> “print-build-event”.
>>
>> Indeed, that seems to be the case.  This would mean we’re emitting an
>> incorrect build trace.
>>
>> Do you have the exact command to reproduce it?
>
> Unfortunately, I don’t.

Or do you have the log around?  If you run, say:

  grep -r "download-progress .*#f" /var/log/guix/drvs

?

Looking at the code, I think only ‘progress-reporter/trace’ emits those
traces and only through calls to ‘dump-port*’, and I don’t see where
this #f could come from.

TIA,
Ludo’.

Message #21 received at 32895-done <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
Cc: 32895-done <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Thu, 04 Oct 2018 10:31:07 +0200

Hi,

ludo <at> gnu.org (Ludovic Courtès) skribis:

> Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de> skribis:
>
>> Ludovic Courtès <ludo <at> gnu.org> writes:
>>
>>> Hello,
>>>
>>> Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de> skribis:
>>>
>>>> guix/progress.scm:214:25: In procedure display-download-progress:
>>>> In procedure /: Wrong type argument in position 1: #f
>>>>
>>>> This happens because “transferred” in the “else” branch of (@ (guix
>>>> progress) display-download-progress) is #f instead of a number.  This
>>>> could be the result of running string->number on an invalid string in
>>>> “print-build-event”.
>>>
>>> Indeed, that seems to be the case.  This would mean we’re emitting an
>>> incorrect build trace.
>>>
>>> Do you have the exact command to reproduce it?
>>
>> Unfortunately, I don’t.
>
> Or do you have the log around?  If you run, say:
>
>   grep -r "download-progress .*#f" /var/log/guix/drvs
>
> ?

Turns out I stumbled upon this bug by change.  The traces I was getting
were:

--8<---------------cut here---------------start------------->8---
@ download-progress /gnu/store/2chkmisij4373sb8sf07by0zkcikl4ki-opencv-extra-3.4.3.zip https://codeload.github.com/opencv/opencv_extra/zip/3.4.3 - 472383488
@ download-progress /gnu/store/2chkmisij4373sb8sf07by0zkcikl4ki-opencv-extra-3.4.3.zip https://codeload.github.com/opencv/opencv_extra/zip/3.4.3 - 478478336
@ download-progress /gnu/store/2chkmisij4373sb8sf07by0zkcikl4ki-opencv-extra-3.4.3.zip https://codeload.github.com/opencv/opencv_extra/zip/3.4.3 - 484704256
@ download-progress /gnu/store/2chkmisij4373sb8sf07by0zkcikl4ki-opencv-extra-3.4.3.zip https://codeload.github.com/opencv/opencv_extra/zip/3.4.3 - #f
@ download-succeeded /gnu/store/2chkmisij4373sb8sf07by0zkcikl4ki-opencv-extra-3.4.3.zip https://codeload.github.com/opencv/opencv_extra/zip/3.4.3 487641438
--8<---------------cut here---------------end--------------->8---

The next-to-last one was incorrect.

This is fixed in 1d0be47ab680db938ac8da1ee65e1de91e198f67.  I’ll push an
update of the ‘guix’ package so we get an updated daemon with the fix
(for the “builtin:download” derivations.)

Thanks,
Ludo’.

Message #24 received at 32895 <at> debbugs.gnu.org (full text, mbox):

From: Mark H Weaver <mhw <at> netris.org>
To: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
Cc: 32895 <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Thu, 04 Oct 2018 05:58:20 -0400

Hi Ricardo,

Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de> writes:

> Downloading small files (such as cabal revisions) sometimes fails with a
> backtrace like this:
>
> Starting download of /gnu/store/plr3hf9gjdcg2qhi3x4k2wjm8zajqibc-ghc-cryptohash-md5-0.11.100.1-2.cabal
> From https://hackage.haskell.org/package/cryptohash-md5-0.11.100.1/revision/2.cabal...
> downloading from https://hackage.haskell.org/package/cryptohash-md5-0.11.100.1/revision/2.cabal...
> Backtrace:                                                     7.6MiB/s 00:00 | 3KiB transferred
> In ice-9/boot-9.scm:
>     829:9 19 (catch _ _ #<procedure 7f8718d34458 at guix/ui.scm:615â¦> â¦)
>     829:9 18 (catch _ _ #<procedure 7f8718d34470 at guix/ui.scm:733â¦> â¦)
> In guix/scripts/build.scm:
>    749:24 17 (_)
> In ice-9/boot-9.scm:
>     829:9 16 (catch _ _ #<procedure 2a53440 at ice-9/boot-9.scm:104â¦> â¦)
> In guix/ui.scm:
>     409:6 15 (_)
> In guix/scripts/build.scm:
>     675:5 14 (_)
> In srfi/srfi-1.scm:
>    679:15 13 (append-map _ _ . _)
>    592:17 12 (map1 (#<package ngless <at> 0.9.1 gnu/packages/bioinformatâ¦>))
> In guix/scripts/build.scm:
>    680:31 11 (_ _)
> In guix/packages.scm:
>    881:14 10 (cache! #<weak-table 782/883> #<package ngless <at> 0.9.1 gâ¦> â¦)
> In unknown file:
>            9 (_ #<procedure thunk ()> #<procedure list _> #<undefined>)
> In guix/grafts.scm:
>     303:4  8 (graft-derivation #<build-daemon 256.98 2a54f50> #<derâ¦> â¦)
>     181:4  7 (references-oracle #<build-daemon 256.98 2a54f50> #<derâ¦>)
>    190:20  6 (_ _ _)
> In guix/store.scm:
>   1087:15  5 (_ #<build-daemon 256.98 2a54f50> _ _)
>    661:13  4 (process-stderr _ _)
> In unknown file:
>            3 (display "@ download-progress /gnu/store/plr3hf9gjdcg2â¦" â¦)
> In guix/status.scm:
>    457:13  2 (write! _ _ 186)
>     421:6  1 (_ (download-progress "/gnu/store/plr3hf9gjdcg2qhi3â¦" â¦) â¦)
> In guix/progress.scm:
>    214:25  0 (display-download-progress "2.cabal" #f #:start-time _ # â¦)
>
> guix/progress.scm:214:25: In procedure display-download-progress:
> In procedure /: Wrong type argument in position 1: #f

I'm hitting this same bug repeatedly while trying to build 'idris'.
Previous to this build attempt, I did not have any GHC-related packages
on my system, so this build involves downloading and building many
GHC-related packages.  In this scenario, the bug is quite easy to
trigger.

> This happens because “transferred” in the “else” branch of (@ (guix
> progress) display-download-progress) is #f instead of a number.  This
> could be the result of running string->number on an invalid string in
> “print-build-event”.

Indeed, the string in the 'transferred' slot of the event is actually
"#f".  Here's the entire event, i.e. the first argument passed to
'print-build-event':

(download-progress "/gnu/store/k0z5nlg4gi02zx64l49aail3nb8zzi7x-ghc-vector-0.12.0.1-3.cabal" "https://hackage.haskell.org/package/vector-0.12.0.1/revision/3.cabal" "-" "#f")

So far, I've traced it back to the underlying download derivation.  Here
are the contents of the raw build log as found in /var/log/guix/drvs/,
/var/log/guix/drvs/c2/9v4wx8k3gzg2lryyn1v6ki1hc7wcll-ghc-vector-0.12.0.1-3.cabal.drv.bz2:

--8<---------------cut here---------------start------------->8---

Starting download of /gnu/store/k0z5nlg4gi02zx64l49aail3nb8zzi7x-ghc-vector-0.12.0.1-3.cabal
From https://hackage.haskell.org/package/vector-0.12.0.1/revision/3.cabal...
@ download-started /gnu/store/k0z5nlg4gi02zx64l49aail3nb8zzi7x-ghc-vector-0.12.0.1-3.cabal https://hackage.haskell.org/package/vector-0.12.0.1/revision/3.cabal -
@ download-progress /gnu/store/k0z5nlg4gi02zx64l49aail3nb8zzi7x-ghc-vector-0.12.0.1-3.cabal https://hackage.haskell.org/package/vector-0.12.0.1/revision/3.cabal - 7073
@ download-progress /gnu/store/k0z5nlg4gi02zx64l49aail3nb8zzi7x-ghc-vector-0.12.0.1-3.cabal https://hackage.haskell.org/package/vector-0.12.0.1/revision/3.cabal - #f
@ download-succeeded /gnu/store/k0z5nlg4gi02zx64l49aail3nb8zzi7x-ghc-vector-0.12.0.1-3.cabal https://hackage.haskell.org/package/vector-0.12.0.1/revision/3.cabal 7073

--8<---------------cut here---------------end--------------->8---

Notice that the last field of the final 'download-progress' line is "#f"
instead of a number.

To be continued...

     Mark

Message #27 received at 32895 <at> debbugs.gnu.org (full text, mbox):

From: Mark H Weaver <mhw <at> netris.org>
To: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
Cc: 32895 <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Thu, 04 Oct 2018 19:19:53 -0400

And now I'm running into the same bug repeatedly while trying to test
build security updates for IceCat, which involve downloading a great
many small patches from Mozilla.

Bah.  Something is very broken here, and now it's interfering with my
attempts to deploy critical security updates.  I'm thinking it might be
time to start reverting some of the recent commits that seem related to
this.

       Mark

Message #30 received at 32895 <at> debbugs.gnu.org (full text, mbox):

From: Mark H Weaver <mhw <at> netris.org>
To: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
Cc: 32895 <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Thu, 04 Oct 2018 19:28:21 -0400

I've applied the following temporary workaround to my private branch, to
enable me to work on the IceCat security update.

       Mark


--8<---------------cut here---------------start------------->8---
diff --git a/guix/status.scm b/guix/status.scm
index c6956066f..8c6045a7d 100644
--- a/guix/status.scm
+++ b/guix/status.scm
@@ -359,10 +359,11 @@ addition to build events."
           (let ((uri (if (string-contains uri "/nar/")
                          (nar-uri-abbreviation uri)
                          (basename uri))))
-            (display-download-progress uri size
-                                       #:start-time
-                                       (download-start download)
-                                       #:transferred transferred))))))
+            (when transferred  ; FIXME XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
+              (display-download-progress uri size
+                                         #:start-time
+                                         (download-start download)
+                                         #:transferred transferred)))))))
     (('substituter-succeeded item _ ...)
      ;; If there are no jobs running, we already reported download completion
      ;; so there's nothing left to do.
--8<---------------cut here---------------end--------------->8---

Message #33 received at 32895 <at> debbugs.gnu.org (full text, mbox):

From: Mark H Weaver <mhw <at> netris.org>
To: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>
Cc: 32895 <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Thu, 04 Oct 2018 19:35:25 -0400

I see now that this bug was already fixed while I sent several new
messages about it.  Oops.  I should really make sure I've fetched email
before responding.  Sorry for the noise.

      Mark

Message #36 received at 32895 <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: Mark H Weaver <mhw <at> netris.org>
Cc: Ricardo Wurmus <ricardo.wurmus <at> mdc-berlin.de>, 32895 <at> debbugs.gnu.org
Subject: Re: bug#32895: file progress reporter crashes on small files
Date: Mon, 08 Oct 2018 14:23:12 +0200

Mark H Weaver <mhw <at> netris.org> skribis:

> I see now that this bug was already fixed while I sent several new
> messages about it.  Oops.  I should really make sure I've fetched email
> before responding.  Sorry for the noise.

No problem, sorry for messing with this in the first place.

Ludo’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.