Subject: bug#30290: guix-daemon slows to a crawl when a substitute server is offline

From: Maxim Cournoyer <[email-masked]>
Date: Wed, 18 Aug 2021 21:54:46 -0400

Hello,

Maxim Cournoyer <[email-masked]> writes:

> Hi,
>
> And sorry for failing to produce a reply earlier :-).
>
> zimoun <[email-masked]> writes:
>
> [...]
>
>>>> From: Maxim Cournoyer <[email-masked]>
>>>> Date: Fri, 18 Dec 2020 22:04:04 -0500 (24 weeks, 4 days, 18 hours ago)
>>>>
>>>> I'm not sure if the recent offloading work that Mathieu did touched that
>>>> topic.  I'd need to test the scenario.  Perhaps a system test would be
>>>> useful.
>>>> ----------
>>>>
>>>> From: Ludovic Courtès <[email-masked]>
>>>> Date: Tue, 22 Dec 2020 16:16:08 +0100
>>>> Date: Tue, 22 Dec 2020 16:16:08 +0100 (24 weeks, 1 day, 6 hours ago)
>>>>
>>>> Is it still a problem?  Commit 4f5234be0378368e6af25925db46612838d25e58
>>>> (Nov. 2019) added a table of unreachable hosts.  That way, a ‘guix
>>>> substitute --query’ process won’t retry connections to an unreachable
>>>> host.
>>>> ----------
>>>>
>>>> From: Efraim Flashner <[email-masked]>
>>>> Date: Mon, 28 Dec 2020 14:19:02 +0200
>>>> Date: Mon, 28 Dec 2020 14:19:02 +0200 (23 weeks, 2 days, 9 hours ago)
>>>>
>>>> Occasionally my internet drops itself, and I find I'm left forever
>>>> waiting for a timeout to see what sources I have cached locally.
>>>> ----------
>>>
>>> What is the current stats of this bug?   Is it still happening with the
>>> recent improvements of Cuirass?
>>
>> After reading all this, I think this bug can be closed.  WDYT?
>
> Were you able to replay a scenario in which a substitute server is made
> unreachable?  That's the information that I'd like to have/see before
> closing.  I don't come across unreachable substitute servers often, and
> can't think of a way to easily test this.
>
> I could make it hang by dropping the input/output connections with
> iptables to a remote guix publish server, but then SSH also hangs, so
> perhaps that's expected.
>
> I'll try to configure a couple local machines to act as publish servers,
> and disconnect them from the network to see what happens.
>
> Thanks,
>
> Maxim

I managed to get some problematic behavior from guix substitute:

My test protocole was roughly like this:

1. Setup a 2nd machine (machine B) to act as a substitute server, and
guix pull to the same commit as that of my main machine (machine A).

2. Run guix build -m manifest.scm on machine B (IP: 192.168.10.172).

3. On the machine A, run the command below, explicitly listing machine A
as a substitute URL, along ci.guix.gnu.org.  During a download from A,
break the connection (I pulled the wifi USB dongle out):

$ guix build -m ~/stow/guix/manifest.scm --substitute-urls='http://192.168.10.172 https://ci.guix.gnu.org' --no-offload
substitute: updating substitutes from 'http://192.168.10.172:80'... 100.0%
substitute: updating substitutes from 'http://192.168.10.172'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
The following derivations will be built:
   /gnu/store/lxm7brkbrkkv58c4kzlw1lh3wc0bm8wz-gimp-2.10.24.drv
   /gnu/store/ddv8jyzwk92nsg1dkv9n3scf6f7w83g5-keepassxc-2.6.6.drv
   /gnu/store/xky1y32mccplxsb448ziq68by2mvkdaz-ruby-asciidoctor-2.0.10.drv
   /gnu/store/0ph0sjib0d13n2fsl8w9prnky8g5fkvf-ruby-haml-5.0.4.drv
   /gnu/store/4dfwfj9qinw4vs6290gdy5qbnqbczm2v-ruby-temple-0.8.2.drv
   /gnu/store/b12krypa196yg6gzk2bvrh35i1fg5c7x-ruby-tilt-2.0.10.drv
   /gnu/store/131d8193hi1485ylnb9w8jm3jnlv3iyx-ruby-slim-4.1.0.drv
   /gnu/store/489nq0jqjby92kv3c6nwrdfqg45l40nw-ruby-sinatra-2.0.8.1.drv
   /gnu/store/yay3sa8nnq4j0ixwhp3bxfg5vfisfmf1-sflvault-client-0.9.2-1.8de3902.drv
   /gnu/store/2n1xyy0y3nnkrp3mpdifn8r7wf6pzpb0-sflvault-0.9.2-1.8de3902-checkout.drv
   /gnu/store/jsyhy4vxzr9yyg66kzk7w28xffyx050c-python-keyring-1.6.1.drv
   /gnu/store/kiwn3x2la23f1pa3a5ypsihhc6ja19y5-python-keyring-1.6.1-checkout.drv
The following files will be downloaded:
   /gnu/store/2qphwngpvawl6f06d33b2jr18vk1hyc9-module-import-compiled
   /gnu/store/r7vsb0vl4y66jbq7b56zmrm60q2507zl-wireshark-3.4.7
   /gnu/store/wnzx9anjdkmbnkcg5qdd3j77q1w2j1bd-yelp-3.32.2
   /gnu/store/vcxwcwlwhvhxj15ma8ik8lghmz8sb2vq-vinagre-3.22.0
   /gnu/store/yg8r6kz95p8v03gz0rglpwzrj21npzzw-spacefm-1.0.6
   /gnu/store/bn35x60w72ad59a5pd7gmvxgjwgkqvag-youtube-dl-2021.06.06
   /gnu/store/xkn540dzpz75hr9cx19xgd3b1r7vgswi-mpv-0.33.1
   /gnu/store/6abwn23grk710qvzvvg1384bs3kc2f8i-linphone-desktop-4.2.5-debug
   /gnu/store/4h8ixlh5by2l09vv3rvknmlxv2gm9d6s-linphone-desktop-4.2.5
   /gnu/store/f10an83xvya46ndh61y59qaw5vvs5f7n-libreoffice-7.1.4.2
   /gnu/store/zczjaxs118155n3mx8w91c24izhx0h0f-ruby-asciimath-2.0.1
   /gnu/store/zll4p79a29hw95d2gsh4vjdvd856ry4s-ruby-cucumber-html-formatter-7.0.0
[...]
   /gnu/store/sa6hvh9bnw73mpplasbjb3idlv71rvcb-gnome-boxes-3.36.6
   /gnu/store/6gy957mhm07zaa001avzkv2d8zhjdl5h-poppler-data-0.4.10
   /gnu/store/7kwgmhlsy6qal56h3z19anxmw4c7pf35-diffoscope-177
   /gnu/store/hxvlcb4wgw0fpyi9ssc4x6f8w3hlng55-gst-plugins-good-1.18.2
   /gnu/store/7bqpzvzanmvb4g1g6gqb1jmrw2j8gv3d-gst-plugins-bad-1.18.2
   /gnu/store/f8hzmmnp8cm4yqq0y9cf7rgxl05hf423-cheese-3.38.0
substituting /gnu/store/7kwgmhlsy6qal56h3z19anxmw4c7pf35-diffoscope-177...
substituting /gnu/store/ns4n01xgbk6ccvd2z127v71d806rnr6f-inkscape-1.1...
substituting /gnu/store/f10an83xvya46ndh61y59qaw5vvs5f7n-libreoffice-7.1.4.2...
substituting /gnu/store/4h8ixlh5by2l09vv3rvknmlxv2gm9d6s-linphone-desktop-4.2.5...
downloading from http://192.168.10.172/nar/zstd/7kwgmhlsy6qal56h3z19anxmw4c7pf35-diffoscope-177 ...
 diffoscope-177                                                       10.5MiB/s 00:00 | 128KiB transferreddownloading from http://192.168.10.172/nar/zstd/ns4n01xgbk6ccvd2z127v71d806rnr6f-inkscape-1.1 ...
downloading from http://192.168.10.172/nar/zstd/f10an83xvya46ndh61y59qaw5vvs5f7n-libreoffice-7.1.4.2 ...
downloading from http://192.168.10.172/nar/zstd/4h8ixlh5by2l09vv3rvknmlxv2gm9d6s-linphone-desktop-4.2.5 ...

substitution of /gnu/store/4h8ixlh5by2l09vv3rvknmlxv2gm9d6s-linphone-desktop-4.2.5 complete
substituting /gnu/store/7bqpzvzanmvb4g1g6gqb1jmrw2j8gv3d-gst-plugins-bad-1.18.2...
downloading from http://192.168.10.172/nar/zstd/7bqpzvzanmvb4g1g6gqb1jmrw2j8gv3d-gst-plugins-bad-1.18.2 ...

substitution of /gnu/store/7kwgmhlsy6qal56h3z19anxmw4c7pf35-diffoscope-177 complete
substituting /gnu/store/hxvlcb4wgw0fpyi9ssc4x6f8w3hlng55-gst-plugins-good-1.18.2...
downloading from http://192.168.10.172/nar/zstd/hxvlcb4wgw0fpyi9ssc4x6f8w3hlng55-gst-plugins-good-1.18.2 ...

^ It hung up there, waiting indefinitely.

What I would have expected instead, would have been to find out about
the network failure, and retry from the other available substitute URL,
else build locally.

At that time, all the 'substitute' processes are blocked on a read(2)
call, while one of the guix-daemon is also, and 2 others are blocked on
select.

That's not the same as the original report though; let's try to
reproduce that one by running the same command again, while the
substitute server B is still disconnected:

--8<---------------cut here---------------start------------->8---
$ time guix build -m ~/stow/guix/manifest.scm --substitute-urls='http://192.168.10.172 https://ci.guix.gnu.org' --no-offload
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%guix substitute: warning: 192.168.10.172: connection failed: No route to host
substitute: 
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
The following derivations will be built:
   /gnu/store/lxm7brkbrkkv58c4kzlw1lh3wc0bm8wz-gimp-2.10.24.drv
   /gnu/store/ddv8jyzwk92nsg1dkv9n3scf6f7w83g5-keepassxc-2.6.6.drv
   /gnu/store/xky1y32mccplxsb448ziq68by2mvkdaz-ruby-asciidoctor-2.0.10.drv
   /gnu/store/0ph0sjib0d13n2fsl8w9prnky8g5fkvf-ruby-haml-5.0.4.drv
   /gnu/store/4dfwfj9qinw4vs6290gdy5qbnqbczm2v-ruby-temple-0.8.2.drv
   /gnu/store/b12krypa196yg6gzk2bvrh35i1fg5c7x-ruby-tilt-2.0.10.drv
   /gnu/store/131d8193hi1485ylnb9w8jm3jnlv3iyx-ruby-slim-4.1.0.drv
   /gnu/store/489nq0jqjby92kv3c6nwrdfqg45l40nw-ruby-sinatra-2.0.8.1.drv
   /gnu/store/yay3sa8nnq4j0ixwhp3bxfg5vfisfmf1-sflvault-client-0.9.2-1.8de3902.drv
   /gnu/store/2n1xyy0y3nnkrp3mpdifn8r7wf6pzpb0-sflvault-0.9.2-1.8de3902-checkout.drv
   /gnu/store/jsyhy4vxzr9yyg66kzk7w28xffyx050c-python-keyring-1.6.1.drv
   /gnu/store/kiwn3x2la23f1pa3a5ypsihhc6ja19y5-python-keyring-1.6.1-checkout.drv
The following files will be downloaded:
   /gnu/store/2qphwngpvawl6f06d33b2jr18vk1hyc9-module-import-compiled
   /gnu/store/r7vsb0vl4y66jbq7b56zmrm60q2507zl-wireshark-3.4.7
   /gnu/store/wnzx9anjdkmbnkcg5qdd3j77q1w2j1bd-yelp-3.32.2
   /gnu/store/vcxwcwlwhvhxj15ma8ik8lghmz8sb2vq-vinagre-3.22.0
   /gnu/store/yg8r6kz95p8v03gz0rglpwzrj21npzzw-spacefm-1.0.6

[...]

   /gnu/store/zvnnafb7hmiklj8wpvn9qdc85w8rdprl-gnucash-4.2-doc
   /gnu/store/rp2ai59zvx5m0k6db0cnkx6nn9n41qjd-gnucash-4.2
   /gnu/store/hmy026sjdl489sy3i25r2kz9f70h3awm-gnucash-4.2-python
   /gnu/store/1bspzx0103mr17mxhgw0d9zdlgca2psq-spice-gtk-0.37
   /gnu/store/bribnmf6djvh1d3rjr2vs5y97141ad97-osinfo-db-20201218
   /gnu/store/r1a25sizf07nmh388ri4qybshzlcxbqd-libosinfo-1.7.1
   /gnu/store/2z7p7ynamiarxkx4hnk8dk377xqgm3zl-tracker-2.3.5
   /gnu/store/458bw9h0f0ybjdqwg4zm5gjjsmfxbalx-webkitgtk-2.32.3
   /gnu/store/sa6hvh9bnw73mpplasbjb3idlv71rvcb-gnome-boxes-3.36.6
   /gnu/store/6gy957mhm07zaa001avzkv2d8zhjdl5h-poppler-data-0.4.10
   /gnu/store/hxvlcb4wgw0fpyi9ssc4x6f8w3hlng55-gst-plugins-good-1.18.2
   /gnu/store/7bqpzvzanmvb4g1g6gqb1jmrw2j8gv3d-gst-plugins-bad-1.18.2
   /gnu/store/f8hzmmnp8cm4yqq0y9cf7rgxl05hf423-cheese-3.38.0
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substituting /gnu/store/ns4n01xgbk6ccvd2z127v71d806rnr6f-inkscape-1.1...
substituting /gnu/store/f10an83xvya46ndh61y59qaw5vvs5f7n-libreoffice-7.1.4.2...
substituting /gnu/store/6abwn23grk710qvzvvg1384bs3kc2f8i-linphone-desktop-4.2.5-debug...
substituting /gnu/store/bribnmf6djvh1d3rjr2vs5y97141ad97-osinfo-db-20201218...
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
guix substitute: error: connect*: No route to host
guix substitute: error: connect*: No route to host
guix substitute: error: connect*: No route to host
guix substitute: warning: 192.168.10.172: connection failed: No route to host
downloading from https://ci.guix.gnu.org/nar/lzip/bribnmf6djvh1d3rjr2vs5y97141ad97-osinfo-db-20201218 ...
 osinfo-db-20201218  88KiB                                      5.9MiB/s 00:00 [#############     ]  73.1%substitution of /gnu/store/ns4n01xgbk6ccvd2z127v71d806rnr6f-inkscape-1.1 failed
substitution of /gnu/store/f10an83xvya46ndh61y59qaw5vvs5f7n-libreoffice-7.1.4.2 failed
substitution of /gnu/store/6abwn23grk710qvzvvg1384bs3kc2f8i-linphone-desktop-4.2.5-debug failed
guix build: error: corrupt input while restoring archive from #<closed: file 7f16de01c230>

real    1m13.549s
user    0m25.348s
sys     0m0.721s
--8<---------------cut here---------------end--------------->8---

Hmm.

Let's try again,

--8<---------------cut here---------------start------------->8---
$ time guix build -m ~/stow/guix/manifest.scm --substitute-urls='http://192.168.10.172 https://ci.guix.gnu.org' --no-offload
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%guix substitute: warning: 192.168.10.172: connection failed: No route to host
substitute: 
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
The following derivations will be built:
   /gnu/store/lxm7brkbrkkv58c4kzlw1lh3wc0bm8wz-gimp-2.10.24.drv
   /gnu/store/ddv8jyzwk92nsg1dkv9n3scf6f7w83g5-keepassxc-2.6.6.drv
   /gnu/store/xky1y32mccplxsb448ziq68by2mvkdaz-ruby-asciidoctor-2.0.10.drv
   /gnu/store/0ph0sjib0d13n2fsl8w9prnky8g5fkvf-ruby-haml-5.0.4.drv
   /gnu/store/4dfwfj9qinw4vs6290gdy5qbnqbczm2v-ruby-temple-0.8.2.drv
   /gnu/store/b12krypa196yg6gzk2bvrh35i1fg5c7x-ruby-tilt-2.0.10.drv
   /gnu/store/131d8193hi1485ylnb9w8jm3jnlv3iyx-ruby-slim-4.1.0.drv
   /gnu/store/489nq0jqjby92kv3c6nwrdfqg45l40nw-ruby-sinatra-2.0.8.1.drv
   /gnu/store/yay3sa8nnq4j0ixwhp3bxfg5vfisfmf1-sflvault-client-0.9.2-1.8de3902.drv
   /gnu/store/2n1xyy0y3nnkrp3mpdifn8r7wf6pzpb0-sflvault-0.9.2-1.8de3902-checkout.drv
   /gnu/store/jsyhy4vxzr9yyg66kzk7w28xffyx050c-python-keyring-1.6.1.drv
   /gnu/store/kiwn3x2la23f1pa3a5ypsihhc6ja19y5-python-keyring-1.6.1-checkout.drv
The following files will be downloaded:
   /gnu/store/2qphwngpvawl6f06d33b2jr18vk1hyc9-module-import-compiled
   /gnu/store/r7vsb0vl4y66jbq7b56zmrm60q2507zl-wireshark-3.4.7
   /gnu/store/wnzx9anjdkmbnkcg5qdd3j77q1w2j1bd-yelp-3.32.2

[...]

   /gnu/store/sa6hvh9bnw73mpplasbjb3idlv71rvcb-gnome-boxes-3.36.6
   /gnu/store/6gy957mhm07zaa001avzkv2d8zhjdl5h-poppler-data-0.4.10
   /gnu/store/hxvlcb4wgw0fpyi9ssc4x6f8w3hlng55-gst-plugins-good-1.18.2
   /gnu/store/7bqpzvzanmvb4g1g6gqb1jmrw2j8gv3d-gst-plugins-bad-1.18.2
   /gnu/store/f8hzmmnp8cm4yqq0y9cf7rgxl05hf423-cheese-3.38.0
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
 
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
substituting /gnu/store/ns4n01xgbk6ccvd2z127v71d806rnr6f-inkscape-1.1...
substituting /gnu/store/f10an83xvya46ndh61y59qaw5vvs5f7n-libreoffice-7.1.4.2...
substituting /gnu/store/6abwn23grk710qvzvvg1384bs3kc2f8i-linphone-desktop-4.2.5-debug...
substituting /gnu/store/bribnmf6djvh1d3rjr2vs5y97141ad97-osinfo-db-20201218...
substitute: updating substitutes from 'http://192.168.10.172:80'...   0.0%
substitute: updating substitutes from 'http://192.168.10.172'...   0.0%
guix substitute: error: connect*: No route to host
guix substitute: error: connect*: No route to host
guix substitute: error: connect*: No route to host
guix substitute: warning: 192.168.10.172: connection failed: No route to host
downloading from https://ci.guix.gnu.org/nar/lzip/bribnmf6djvh1d3rjr2vs5y97141ad97-osinfo-db-20201218 ...
 osinfo-db-20201218  88KiB                                      6.0MiB/s 00:00 [#############     ]  73.1%substitution of /gnu/store/ns4n01xgbk6ccvd2z127v71d806rnr6f-inkscape-1.1 failed
substitution of /gnu/store/f10an83xvya46ndh61y59qaw5vvs5f7n-libreoffice-7.1.4.2 failed
substitution of /gnu/store/6abwn23grk710qvzvvg1384bs3kc2f8i-linphone-desktop-4.2.5-debug failed
guix build: error: corrupt input while restoring archive from #<closed: file 7f1471840230>

real    1m15.216s
user    0m24.963s
sys     0m0.702s
--8<---------------cut here---------------end--------------->8---

Same thing, the daemon is still trying really hard to get something from
that dead substitute server, slowing things down.

That corrupted archive failure is curious, I wonder if it may be
related.

We'll have to keep this bug open I'm afraid :-/.

Thanks,

Maxim