Installer image consistently fails to run system init due to TLS error

  • Open
  • quality assurance status badge
Details
2 participants
  • adanskana
  • Richard Sent
Owner
unassigned
Submitted by
Richard Sent
Severity
normal
R
R
Richard Sent wrote on 28 May 02:56 +0200
(address . bug-guix@gnu.org)
87plt692ky.fsf@freakingpenguin.com
Hi Guix!

The dump was uploaded as installer-dump-2e7b5f8f. Here's the installer's
error message:

Toggle snippet (4 lines)
May 27 22:15:49 localhost installer[708]: substitute: ^[[Kupdating substitutes from 'https://bordeaux.guix.gnu.org'... 0.0%guix substitute: error: TLS error in procedure 'write_to_session_record_port': Error in the push function.
May 27 22:15:49 localhost installer[708]: guix system: ^[[1;31merror: ^[[0m`/gnu/store/rdjjpch9m9xv4rdhhr6sv044qd322pj8-guix-command substitute' died unexpectedly

A Guix system installation generated via the following method
consistently fails to install due to a TLS error when updating
substitutes.

Toggle snippet (14 lines)
gibraltar :( guix$ guix time-machine -q -- describe
guix 00384ae
repository URL: https://git.savannah.gnu.org/git/guix.git
branch: master
commit: 00384aedbc6a371aaf90ca344a446952fdd5a6b3
gibraltar :) guix$ guix time-machine -q -- system image --image-type=iso9660 -e '(@ (gnu system install) installation-os)'
guix system: warning: Consider running 'guix pull' followed by
'guix system reconfigure' to get up-to-date packages and security updates.

Updating channel 'guix' from Git repository at 'https://git.savannah.gnu.org/git/guix.git'...
Computing Guix derivation for 'x86_64-linux'... \
/gnu/store/x9a2nflpnfpr8i3n1759hw7wg2qv5mm8-image.iso

Curiously this does NOT occur the first time substitutes are fetched. I
observed it occur three times when substitutes were fetched after Ruby
was substituted. I don't mean to say that Ruby is the problem (that'd be
crazy), just that the TLS error occurs at the same stage in the
installation every time. NOT randomly.

I've never encountered this error before on any other Guix machine on my
network. The installation machine was using a wired connection.

Possibly related: [1], [2], [3], [4]

Notably [3] claims to have a fix that was merged into Guix, but 00384ae
is after said fix was merged (and yes, $ guix describe on the installer
image does report 00384ae)


--
Take it easy,
Richard Sent
Making my computer weirder one commit at a time.
R
R
Richard Sent wrote on 28 May 04:31 +0200
(address . 71238@debbugs.gnu.org)
87a5ka8y5e.fsf@freakingpenguin.com
Toggle quote (9 lines)
> Curiously this does NOT occur the first time substitutes are fetched. I
> observed it occur three times when substitutes were fetched after Ruby
> was substituted. I don't mean to say that Ruby is the problem (that'd be
> crazy), just that the TLS error occurs at the same stage in the
> installation every time. NOT randomly.
>
> I've never encountered this error before on any other Guix machine on my
> network. The installation machine was using a wired connection.

I have now tried the v1.4.0 installer and get a failure at (seemingly)
the same point in the install, although the actual error is different.
See installer-dump-22e789d5.

What the heck is going on here? Those two images are wildly different
and are downloading wildly different sets of substitutes.

--
Take it easy,
Richard Sent
Making my computer weirder one commit at a time.
R
R
Richard Sent wrote on 28 May 06:44 +0200
(address . 71238@debbugs.gnu.org)
87y17u7dfu.fsf@freakingpenguin.com
Richard Sent <richard@freakingpenguin.com> writes:

Toggle quote (3 lines)
> What the heck is going on here? Those two images are wildly different
> and are downloading wildly different sets of substitutes.

Bad news. I connected my device to a different network with just an
ordinary consumer router and the installation succeeded (using the guix
00384aed media). Ordinary my devices are behind a opnsense router with a
/very/ lightly-customized firewall. To me, this means there are three
possibilities, none of which is particularly comforting:

1. There was a transient network issue for ~3 hours when I attempted to
install Guix ~4 times using different installation media that caused a
specific TLS handshake to fail.

2. A specific TLS handshake Guix undertakes during the installation
process fails to pass one of the built-in firewall rules shipped with
opnsense.

3. Some other odd aspect of my network messes things up for a specific
TLS handshake.

My money is on 2 given how this is a seemingly common issue on
enterprise networks [1] and the rules I have added seem irrelevant. (I'd
rather not talk openly about my firewall rules in an archived public
forum, but can discuss off-list). However, there is another comment in
that thread that says IT didn't notice any firewall blocking.

Toggle quote (10 lines)
>> Sometimes, usually when I'm on an enterprise network like my
>> university's of library's wifi, the `guix substitute` process dies
>> with a "TLS error in procedure 'write_to_session_record_port': Error
>> in the push function" error message. My connection is rock-solid
>> otherwise, and sometimes it doesn't happen at all.
> I get the same error on guix pull almost always when I am on my
> enterprise network. Re-running guix pull a second time also almost
> always then runs fine. I checked with our IT: nothing suspicious on
> the network, i.e. no firewall blocking.

Running Guix pull to work around the problem is great...... unless
you're trying to install Guix via the guided installer! :) In my case it
also wasn't guix pull that was failing.

I want to emphasize that the error occured in the same phase of the
installer every time, it was not the first handshake, no other machine
has ever had this issue, and the installer was (3/4 times) on a commit
that should include the fix described in [1].

I'm happy to assist with debugging this, although I'm not some TLS
networking genius so trying to solve it outright is probably beyond me.
I'd also LOVE to hear if other people using a largely stock opnsense or
other firewall software encountered this issue, particularly with the
installation media.

At some point I'll attempt to gradually "de-enterprise" parts of my
network and see exactly when (if ever) the problem is resolved. Due to
the nature of the problem, reliably reproducing it in the future will be
a challenge.

CC'ing people involved in [1] because this is just so weird and I don't
want it to be consigned to the dustbins of history. I don't think we
heard anyone with the issue explicitly say the fix resolved or at least
mitigated the problem.


--
Take it easy,
Richard Sent
Making my computer weirder one commit at a time.
A
A
adanskana wrote on 28 May 07:36 +0200
e69e8246-5835-5e56-a0f8-c7b54ec4b3b1@gmail.com
Hi Richard

On 5/28/24 4:44 AM, Richard Sent <richard@freakingpenguin.com> wrote:
Toggle quote (33 lines)
> Richard Sent <richard@freakingpenguin.com> writes:
>
> > What the heck is going on here? Those two images are wildly different
> > and are downloading wildly different sets of substitutes.
>
> Bad news. I connected my device to a different network with just an
> ordinary consumer router and the installation succeeded (using the guix
> 00384aed media). Ordinary my devices are behind a opnsense router with a
> /very/ lightly-customized firewall. To me, this means there are three
> possibilities, none of which is particularly comforting:
>
> 1. There was a transient network issue for ~3 hours when I attempted to
> install Guix ~4 times using different installation media that caused a
> specific TLS handshake to fail.
>
> 2. A specific TLS handshake Guix undertakes during the installation
> process fails to pass one of the built-in firewall rules shipped with
> opnsense.
>
> 3. Some other odd aspect of my network messes things up for a specific
> TLS handshake.
>
> My money is on 2 given how this is a seemingly common issue on
> enterprise networks [1] and the rules I have added seem irrelevant. (I'd
> rather not talk openly about my firewall rules in an archived public
> forum, but can discuss off-list). However, there is another comment in
> that thread that says IT didn't notice any firewall blocking.
>
> >> Sometimes, usually when I'm on an enterprise network like my
> >> university's of library's wifi, the `guix substitute` process dies
> >> with a "TLS error in procedure 'write_to_session_record_port': Error
> >> in the push function" error message. My connection is rock-solid
> >> otherwise, and sometimes it doesn't happen at all.
I was actually going to reopen this issue, as I'm still encountering this bug in the exact same scenarios. Nothing has changed at all.
Toggle quote (19 lines)
> > I get the same error on guix pull almost always when I am on my
> > enterprise network. Re-running guix pull a second time also almost
> > always then runs fine. I checked with our IT: nothing suspicious on
> > the network, i.e. no firewall blocking.
>
> Running Guix pull to work around the problem is great...... unless
> you're trying to install Guix via the guided installer! :) In my case it
> also wasn't guix pull that was failing.
>
> I want to emphasize that the error occured in the same phase of the
> installer every time, it was not the first handshake, no other machine
> has ever had this issue, and the installer was (3/4 times) on a commit
> that should include the fix described in [1].
>
> I'm happy to assist with debugging this, although I'm not some TLS
> networking genius so trying to solve it outright is probably beyond me.
> I'd also LOVE to hear if other people using a largely stock opnsense or
> other firewall software encountered this issue, particularly with the
> installation media.
Same, I'm happy to assist. The test that Ludo' provided to try and reproduce the bug doesn't work as referenced in previous emails. Is there some way I can attatch a debugger to a guile process running `guix upgrade` or something like that?
Toggle quote (10 lines)
>
> At some point I'll attempt to gradually "de-enterprise" parts of my
> network and see exactly when (if ever) the problem is resolved. Due to
> the nature of the problem, reliably reproducing it in the future will be
> a challenge.
>
> CC'ing people involved in [1] because this is just so weird and I don't
> want it to be consigned to the dustbins of history. I don't think we
> heard anyone with the issue explicitly say the fix resolved or at least
> mitigated the problem.
Thanks for CC'ing me. Yes, the problem was never resolved. For someone just upgrading their system, it's annoying, but can be mitigated pretty easily. For someone trying to install Guix, on the other hand, this is a intensely annoying problem. After my exams are finished in a couple weeks I want to try and fix this problem and also upgrade GRUB to fix issues with it recognising ext4 partitons with certain features enabled properly.
Toggle quote (4 lines)
>
> [1]: https://lists.gnu.org/archive/html/guix-devel/2024-03/msg00150.html
>
>
Anyway, please let me know how I can help. If someone could help me attaching some sort of debugger, I can reproduce the error fairly easily on my uni's wifi if I do a `guix gc -d 2w && guix upgrade && sudo guix system reconfigure config.scm`. The sheer number of substitutes downloaded seems to be enough for it to happen at least once.

Warmly,
Ada
R
R
Richard Sent wrote on 29 May 03:44 +0200
(address . 71238@debbugs.gnu.org)
87h6ehl7db.fsf@freakingpenguin.com
Richard Sent <richard@freakingpenguin.com> writes:

Toggle quote (17 lines)
> 1. There was a transient network issue for ~3 hours when I attempted to
> install Guix ~4 times using different installation media that caused a
> specific TLS handshake to fail.
>
> 2. A specific TLS handshake Guix undertakes during the installation
> process fails to pass one of the built-in firewall rules shipped with
> opnsense.
>
> 3. Some other odd aspect of my network messes things up for a specific
> TLS handshake.
>
> My money is on 2 given how this is a seemingly common issue on
> enterprise networks [1] and the rules I have added seem irrelevant. (I'd
> rather not talk openly about my firewall rules in an archived public
> forum, but can discuss off-list). However, there is another comment in
> that thread that says IT didn't notice any firewall blocking.

I ran the 1.4.0 installer again today behind my opnsense router and it
completed successfully, which is horrifying. I was hoping starting from
a constant image would make the error reproducible but that doesn't seem
to be the case. Even with a consistent system image and network, it's
only reproducible for somewhere between a few hours and one day. Perhaps
server load plays a part?

(Technically my process was a little bit different. Instead of fully
completing the graphical installer I swapped to a TTY after activating
the wired connection, mounted the root fs, and run $ guix system build
/mnt/etc/config.scm, where config.scm was unmodified since initial
installation. I'd be stunned if this caused the change in behavior but
figured I'd mention for completeness.)

--
Take it easy,
Richard Sent
Making my computer weirder one commit at a time.
A
A
adanskana wrote on 10 Jun 07:33 +0200
0c00df03-8ba7-c5d2-3a16-afb5175fb00e@gmail.com
Hi all,

On 29/05/2024 01:44, Richard Sent <richard@freakingpenguin.com> wrote:
Toggle quote (35 lines)
> Richard Sent <richard@freakingpenguin.com> writes:
>
> > 1. There was a transient network issue for ~3 hours when I attempted to
> > install Guix ~4 times using different installation media that caused a
> > specific TLS handshake to fail.
> >
> > 2. A specific TLS handshake Guix undertakes during the installation
> > process fails to pass one of the built-in firewall rules shipped with
> > opnsense.
> >
> > 3. Some other odd aspect of my network messes things up for a specific
> > TLS handshake.
> >
> > My money is on 2 given how this is a seemingly common issue on
> > enterprise networks [1] and the rules I have added seem irrelevant. (I'd
> > rather not talk openly about my firewall rules in an archived public
> > forum, but can discuss off-list). However, there is another comment in
> > that thread that says IT didn't notice any firewall blocking.
>
> I ran the 1.4.0 installer again today behind my opnsense router and it
> completed successfully, which is horrifying. I was hoping starting from
> a constant image would make the error reproducible but that doesn't seem
> to be the case. Even with a consistent system image and network, it's
> only reproducible for somewhere between a few hours and one day. Perhaps
> server load plays a part?
>
> (Technically my process was a little bit different. Instead of fully
> completing the graphical installer I swapped to a TTY after activating
> the wired connection, mounted the root fs, and run $ guix system build
> /mnt/etc/config.scm, where config.scm was unmodified since initial
> installation. I'd be stunned if this caused the change in behavior but
> figured I'd mention for completeness.)
>
>

I've mananged to reproduce this bug. First, I run `sudo guix gc delete-generations && guix gc -d 2w` to clear my store. Then I run `guix upgrade && sudo guix system -L /home/ada/dotfiles/guix/ reconfigure --fallback /home/ada/dotfiles/guix/ada/system/kissakoira.scm` to redownload all of those deleted store items. The process 9/10 will fail halfway through the upgrade process. Then, a retry will work without a hitch. Even re-gc-ing my system will not let me reproduce the bug - I need to restart my system. Then, the likelyhood it works is 7/10 until the next day (just my perception). By the way, this is on my university's network.

I managed to capture the problem happening under strace using this command `strace -ff -tt -o log_up.strace -s 500 guix upgrade && sudo strace -ff -tt -o log_sr.strace -s 500 sudo guix system -L /home/ada/dotfiles/guix/ reconfigure --fallback /home/ada/dotfiles/guix/ada/system/kissakoira.scm`. I've uploaded the logs to my Google Drive[1]. You can use `strace-log-merge log_up.strace` to view to merged logs.

As I can reproduce this error fairly consistently now, please let me know if you want me to run any more tools to capture more data.

Warmly,
Ada

?
Your comment

Commenting via the web interface is currently disabled.

To comment on this conversation send an email to 71238@debbugs.gnu.org

To respond to this issue using the mumi CLI, first switch to it
mumi current 71238
Then, you may apply the latest patchset in this issue (with sign off)
mumi am -- -s
Or, compose a reply to this issue
mumi compose
Or, send patches to this issue
mumi send-email *.patch