Backtrace with `guix pull --debug=2`

  • Open
  • quality assurance status badge
Details
3 participants
  • Ludovic Courtès
  • Maxime Devos
  • Oskar Berndal
Owner
unassigned
Submitted by
Oskar Berndal
Severity
normal
O
O
Oskar Berndal wrote on 5 Jan 2022 16:19
(address . bug-guix@gnu.org)
CA+ARPV+6hF-7ZLQb+2r_Apv2xKPGvnOyy7YPhbPwH80QRaH-dA@mail.gmail.com
I tried running `guix pull` with the `--debug=2` flag. However, it led
a backtrace, that I include at the bottom. I tried the command twice
with the same backtrace, and then I tried without the debug flag,
simply running `guix pull`. This worked without error. Trying to run
with the debug flag again also worked immediately after that.

Prior to all of this, I made a system reconfiguration where I changed
the uid but not the name of a user. I needed to manually change the
ownership of some files to the new user id so that guix wouldn't trip
at some point. Maybe that's a clue, that it is due to some other files
being of wrong ownership (but not producing an error message I can
understand this time).

Other info:
- guix 1.3.0
- Installed on WSL

These are all things I can think of to add at the moment, please let
me know if there is something else that might be helpful if I can
provide.
Cheers,
Oskar

```
$ guix pull --debug=2
...
building path(s)
`/gnu/store/z0i0wwc7wvch9a8n0gd47gkay9lj1qb0-module-import-compiled'
| @ build-started
/gnu/store/5m4pr3gskpzgshza09ashiysz4a3pd4v-module-import-compiled.drv
- x86_64-linux /var/log/guix/drvs/5m//4pr3gskpzgshza09ashiysz4a3pd4v-module-import-compiled.drv.bz2
3102
Backtrace:
In guix/channels.scm:
890:2 19 (_ _)
In ./guix/monads.scm:
471:9 18 (_ _)
In guix/store.scm:
1956:8 17 (_ _)
In guix/channels.scm:
641:14 16 (_ #<store-connection 256.99 7efc327c44b0>)
In guix/store.scm:
2119:24 15 (run-with-store #<store-connection 256.99 7efc327c44b0> …)
1320:8 14 (call-with-build-handler _ _)
1320:8 13 (call-with-build-handler #<procedure 7efc32b9d6d0 at g…> …)
In guix/channels.scm:
656:14 12 (_)
In guix/store.scm:
2119:24 11 (run-with-store #<store-connection 256.99 7efc327c44b0> …)
In unknown file:
10 (_ #<procedure 7efc1b421000 at ice-9/eval.scm:330:13 ()> …)
In guix/store.scm:
1991:38 9 (_ #<store-connection 256.99 7efc2761b820>)
1417:15 8 (_ #<store-connection 256.99 7efc2761b820> _ _)
759:13 7 (process-stderr _ _)
In unknown file:
6 (display "@ build-log 3102 39\n[ 1/78] Loading './gcry…" …)
In guix/status.scm:
745:19 5 (write! _ _ _)
In srfi/srfi-1.scm:
460:18 4 (fold #<procedure 7efc3281ac40 at guix/status.scm:635:…> …)
In guix/status.scm:
636:15 3 (_ (build-log 3102 "[ 1/78] Loading './gcrypt/hash.s…") #)
179:23 2 (update-build #<<build-status> building: () downloadin…> …)
In ice-9/boot-9.scm:
1685:16 1 (raise-exception _ #:continuable? _)
1685:16 0 (raise-exception _ #:continuable? _)

ice-9/boot-9.scm:1685:16: In procedure raise-exception:
In procedure struct-vtable: Wrong type argument in position 1
(expecting struct): #f
```
M
M
Maxime Devos wrote on 5 Jan 2022 22:20
c16adb228bba9c176e010cc09de17754504626c6.camel@telenet.be
Oskar Berndal schreef op wo 05-01-2022 om 16:19 [+0100]:
I tried running `guix pull` with the `--debug=2` flag. However, it led
a backtrace, that I include at the bottom. I tried the command twice
with the same backtrace, and then I tried without the debug flag,
simply running `guix pull`. This worked without error. Trying to run
with the debug flag again also worked immediately after that. [...]

I can reproduce. Tip: setting COLUMN to a huge number prevents these _
in backtraces, making the backtrace more informative:

$ COLUMNS=9000 guix pull --debug=2

Anyway, here's extra debug information, to be investigated:

10,6 MB zal binnengehaald worden
fetching path `/gnu/store/4y4qxga7yflgkdh0qgfj034q3das0ir4-guix-manual'...
guix-manual 4.3MiB/s 00:02 | 7.6MiB transferred
fetching path `/gnu/store/3d9cyp999jsxamz018hiz20av600syrf-guix-extra'...
guix-extra 2.9MiB 2.5MiB/s 00:01 [##################] 100.0%
fetching path `/gnu/store/zxb0iiva4878ajkh1xq82mmm2csbwqk2-guix-locale-guix'...
guix-locale-guix 306KiB 515.0MiB/s 00:00 [##################] 100.0%
building path(s) `/gnu/store/xxhjcnw24vqhsh7zngz19drkpr24p933-config.scm'
| @ build-started /gnu/store/w7y0m9g09wqnzlwzzdf1kw6ayq42a54g-config.scm.drv - x86_64-linux /var/log/guix/drvs/w7//y0m9g09wqnzlwzzdf1kw6ayq42a54g-config.scm.drv.bz2 26258
scanning for references inside `/gnu/store/xxhjcnw24vqhsh7zngz19drkpr24p933-config.scm'
building path(s) `/gnu/store/a57mqs7dgpmgkrbsif4fg340x3r9g5r7-guix-extra-modules'
| @ build-started /gnu/store/y4plqs9vq1zbqsgassk1j3qznjkfnj65-guix-extra-modules.drv - x86_64-linux /var/log/guix/drvs/y4//plqs9vq1zbqsgassk1j3qznjkfnj65-guix-extra-modules.drv.bz2 26269
scanning for references inside `/gnu/store/a57mqs7dgpmgkrbsif4fg340x3r9g5r7-guix-extra-modules'
building path(s) `/gnu/store/v6pwv3gpb8gphn0smw2fr3zn1d4a2689-guix-config-source'
| @ build-started /gnu/store/px2f4syh8hh2152a9bsff07a1hk07rb5-guix-config-source.drv - x86_64-linux /var/log/guix/drvs/px//2f4syh8hh2152a9bsff07a1hk07rb5-guix-config-source.drv.bz2 26280
scanning for references inside `/gnu/store/v6pwv3gpb8gphn0smw2fr3zn1d4a2689-guix-config-source'
building path(s) `/gnu/store/nqn5f7pj69hbkdbpw5y9phny3badpbjk-guix-packages-base'
| @ build-started /gnu/store/88bx7pj1czzhbnhsb0x2kn9zv6ny83ap-guix-packages-base.drv - x86_64-linux /var/log/guix/drvs/88//bx7pj1czzhbnhsb0x2kn9zv6ny83ap-guix-packages-base.drv.bz2 26293
Backtrace:
In guix/store.scm:
658:37 19 (thunk)
In guix/status.scm:
802:4 18 (call-with-status-report _ _)
In guix/store.scm:
1343:3 17 (_)
1320:8 16 (call-with-build-handler _ _)
1320:8 15 (call-with-build-handler #<procedure 7fc90f307060 at guix/ui.scm:1156:2 (continue store things mode)> _)
In guix/build/syscalls.scm:
1423:3 14 (_)
1390:4 13 (call-with-file-lock/no-wait _ _ _)
In guix/store.scm:
2123:24 12 (run-with-store #<store-connection 256.99 7fc90f2b8190> _ #:guile-for-build _ #:system _ #:target _)
In guix/scripts/pull.scm:
428:4 11 (_ _)
In guix/store.scm:
1995:38 10 (_ #<store-connection 256.99 7fc8fdc73c30>)
In guix/scripts/package.scm:
166:13 9 (build-and-use-profile #<store-connection 256.99 7fc8fdc73c30> "/var/guix/profiles/per-user/regulator/current-guix" #<<manifest> entries: (#<<manifest-entry> name: "guix" version: "f5da992" output: "out" item: #<derivation /gnu/store/jh87xsvgykf67am1l61llqfmbnpwxqa2-guix-f5da992b1.drv => /gnu/store/1m0cganbbvk1kwpppli9gm3mnxrr1h9v-guix-f5da992b1 7fc9023d5050> dependencies: () search-paths: () parent: #<promise #<procedure 7fc90f64c0f0 at guix/channels.scm:879:6 ()>> properties: ((source (repository (version 0) (url "https://git.savannah.gnu.org/git/guix.git")(branch "master") (commit "f5da992b16591b6dc358aa5224fa095738471585") (name guix) (introduction (channel-introduction (version 0) (commit "9edb3f66fd807b096b48283debdcddccfea34bad") (signer "BBB0 2DDF 2CEA F6A8 0D1D E643 A2A0 6DF2 A33A 54FA")))))) ) #:hooks _ #:allow-collisions? _ #:bootstrap? _)
In guix/store.scm:
1421:15 8 (_ #<store-connection 256.99 7fc8fdc73c30> _ _)
759:13 7 (process-stderr _ _)
In unknown file:
6 (display "@ build-log 26293 41\n\r[ 0/654] loading...\t 0.0% of 327 files" #<output: string 7fc90f2ed700>)
In guix/status.scm:
747:19 5 (write! _ _ _)
In srfi/srfi-1.scm:
460:18 4 (fold #<procedure 7fc90f30ed40 at guix/status.scm:637:2 (event status)> #<<build-status> building: () downloading: () builds-completed: () downloads-completed: (#<<download> item: "/gnu/store/zxb0iiva4878ajkh1xq82mmm2csbwqk2-guix-locale-guix" uri: "https://ci.guix.gnu.org/nar/zstd/zxb0iiva4878ajkh1xq82mmm2csbwqk2-guix-locale-guix"size: 313201 start: # time type: time-monotonic nanosecond: 652962000 second: 1641417239 end: # time type: time-monotonic nanosecond: 653772000 second: 1641417239 transferred: 313201 # download item: "/gnu/store/3d9cyp999jsxamz018hiz20av600syrf-guix-extra" uri: "https://ci.guix.gnu.org/nar/zstd/3d9cyp999jsxamz018hiz20av600syrf-guix-extra" size: 3035344 start: # time type: time-monotonic nanosecond: 217310000 second: 1641417238 end: # time type: time-monotonic nanosecond: 373795000 second: 1641417239 transferred: 3035344 # download item: "/gnu/store/4y4qxga7yflgkdh0qgfj034q3das0ir4-guix-manual" uri: "https://ci.guix.gnu.org/nar/lzip/4y4qxga7yflgkdh0qgfj034q3das0ir4-guix-manual" size: 7944251 start: # time type: time-monotonic nanosecond: 149866000 second: 1641417236 end: # time type: time-monotonic nanosecond: 895408000 second: 1641417237 transferred: 7944251 ) ((build-log 26293 "\r[ 0/654] loading...\t 0.0% of 327 files")))
In guix/status.scm:
638:15 3 (_ (build-log 26293 "\r[ 0/654] loading...\t 0.0% of 327 files") #<<build-status> building: () downloading: () builds-completed: () downloads-completed: (#<<download> item: "/gnu/store/zxb0iiva4878ajkh1xq82mmm2csbwqk2-guix-locale-guix" uri: "https://ci.guix.gnu.org/nar/zstd/zxb0iiva4878ajkh1xq82mmm2csbwqk2-guix-locale-guix"size: 313201 start: # time type: time-monotonic nanosecond: 652962000 second: 1641417239 end: # time type: time-monotonic nanosecond: 653772000 second: 1641417239 transferred: 313201 # download item: "/gnu/store/3d9cyp999jsxamz018hiz20av600syrf-guix-extra" uri: "https://ci.guix.gnu.org/nar/zstd/3d9cyp999jsxamz018hiz20av600syrf-guix-extra" size: 3035344 start: # time type: time-monotonic nanosecond: 217310000 second: 1641417238 end: # time type: time-monotonic nanosecond: 373795000 second: 1641417239 transferred: 3035344 # download item: "/gnu/store/4y4qxga7yflgkdh0qgfj034q3das0ir4-guix-manual" uri: "https://ci.guix.gnu.org/nar/lzip/4y4qxga7yflgkdh0qgfj034q3das0ir4-guix-manual" size: 7944251 start: # time type: time-monotonic nanosecond: 149866000 second: 1641417236 end: # time type: time-monotonic nanosecond: 895408000 second: 1641417237 transferred: 7944251 ) )
179:23 2 (update-build #<<build-status> building: () downloading: () builds-completed: () downloads-completed: (#<<download> item: "/gnu/store/zxb0iiva4878ajkh1xq82mmm2csbwqk2-guix-locale-guix" uri: "https://ci.guix.gnu.org/nar/zstd/zxb0iiva4878ajkh1xq82mmm2csbwqk2-guix-locale-guix"size: 313201 start: # time type: time-monotonic nanosecond: 652962000 second: 1641417239 end: # time type: time-monotonic nanosecond: 653772000 second: 1641417239 transferred: 313201 # download item: "/gnu/store/3d9cyp999jsxamz018hiz20av600syrf-guix-extra" uri: "https://ci.guix.gnu.org/nar/zstd/3d9cyp999jsxamz018hiz20av600syrf-guix-extra" size: 3035344 start: # time type: time-monotonic nanosecond: 217310000 second: 1641417238 end: # time type: time-monotonic nanosecond: 373795000 second: 1641417239 transferred: 3035344 # download item: "/gnu/store/4y4qxga7yflgkdh0qgfj034q3das0ir4-guix-manual" uri: "https://ci.guix.gnu.org/nar/lzip/4y4qxga7yflgkdh0qgfj034q3das0ir4-guix-manual" size: 7944251 start: # time type: time-monotonic nanosecond: 149866000 second: 1641417236 end: # time type: time-monotonic nanosecond: 895408000 second: 1641417237 transferred: 7944251 ) _ _)
In ice-9/boot-9.scm:
1685:16 1 (raise-exception _ #:continuable? _)
1685:16 0 (raise-exception _ #:continuable? _)

ice-9/boot-9.scm:1685:16: In procedure raise-exception:
In procedure struct-vtable: Wrong type argument in position 1 (expecting struct): #f
-----BEGIN PGP SIGNATURE-----

iI0EABYKADUWIQTB8z7iDFKP233XAR9J4+4iGRcl7gUCYdYLjBccbWF4aW1lZGV2
b3NAdGVsZW5ldC5iZQAKCRBJ4+4iGRcl7stZAQDn/heUzEle4IIPIYL7XuHjJMhz
nWWDm81GWSGK6I8Z1wEAlIu80jegxfTv2ahv7fU4SJ/8bFf9QUj6uVbv2o+hbQE=
=nwni
-----END PGP SIGNATURE-----


M
M
Maxime Devos wrote on 5 Jan 2022 22:29
22c4605a4992a24f39fbec8a17865f0749e612e1.camel@telenet.be
Oskar Berndal schreef op wo 05-01-2022 om 16:19 [+0100]:
Toggle quote (9 lines)
>    179:23  2 (update-build #<<build-status> building: () downloadin…> …)
> In ice-9/boot-9.scm:
>   1685:16  1 (raise-exception _ #:continuable? _)
>   1685:16  0 (raise-exception _ #:continuable? _)
>
> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
> In procedure struct-vtable: Wrong type argument in position 1
> (expecting struct): #f

Seems like the issue is that 'find-build' returns #false
and 'update' doesn't expect that. So apparently a progress spinner
appears for a build that (guix status) doesn't know about?
I don't know how that can happen.

It's easy to address though (do nothing when no build was found),
but possibly that would only paper over the real issue.

Greetings,
Maxime.
-----BEGIN PGP SIGNATURE-----

iI0EABYKADUWIQTB8z7iDFKP233XAR9J4+4iGRcl7gUCYdYNvxccbWF4aW1lZGV2
b3NAdGVsZW5ldC5iZQAKCRBJ4+4iGRcl7rn0AP40lr3v+VnXum9js42VZGysovlm
Pk9FPsXSpE5+PYm2+QD+Pli8Q7oiVCy5ZrjyXl8YcyWSApVbW4HUaBGozVcevwg=
=6JNx
-----END PGP SIGNATURE-----


O
O
Oskar Berndal wrote on 5 Jan 2022 22:46
(name . Maxime Devos)(address . maximedevos@telenet.be)(address . 53027@debbugs.gnu.org)
CA+ARPVKa+x9SAqF5fDanHQkEMBRGT4RwRgfupzr1ihmFc_Sgiw@mail.gmail.com
Wow, you were able to reproduce. I feared that this would just be lost
to the sands, but apparently not. Nicely done!!! :-D
L
L
Ludovic Courtès wrote on 6 Jan 2022 17:44
(name . Maxime Devos)(address . maximedevos@telenet.be)
87v8ywddao.fsf@gnu.org
Hi,

Maxime Devos <maximedevos@telenet.be> skribis:

Toggle quote (18 lines)
> Oskar Berndal schreef op wo 05-01-2022 om 16:19 [+0100]:
>>    179:23  2 (update-build #<<build-status> building: () downloadin…> …)
>> In ice-9/boot-9.scm:
>>   1685:16  1 (raise-exception _ #:continuable? _)
>>   1685:16  0 (raise-exception _ #:continuable? _)
>>
>> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
>> In procedure struct-vtable: Wrong type argument in position 1
>> (expecting struct): #f
>
> Seems like the issue is that 'find-build' returns #false
> and 'update' doesn't expect that. So apparently a progress spinner
> appears for a build that (guix status) doesn't know about?
> I don't know how that can happen.
>
> It's easy to address though (do nothing when no build was found),
> but possibly that would only paper over the real issue.

Yeah. This looks like https://issues.guix.gnu.org/43518.

Ludo’.
?