Infrastructure/fedora-infrastructure

Fork 0

Random hangs when pushing to pkgs.fedoraproject.org #12442

New issue

Open

opened 2025-03-08 15:50:15 +00:00 by ngompa · 8 comments

ngompa commented

2025-03-08 15:50:15 +00:00

I've been seeing this randomly for some time, and I was finally able to capture some logs about what's going on:

ngompa@fedora ~> ssh -Tvvv ssh://ngompa@pkgs.fedoraproject.org
OpenSSH_9.9p1, OpenSSL 3.2.2 4 Jun 2024
debug1: Reading configuration data /home/ngompa/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/20-systemd-ssh-proxy.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/20-systemd-ssh-proxy.conf
debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/30-libvirt-ssh-proxy.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/30-libvirt-ssh-proxy.conf
debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/50-redhat.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/50-redhat.conf
debug2: checking match for 'final all' host pkgs.fedoraproject.org originally pkgs.fedoraproject.org
debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 3: not matched 'final'
debug2: match not found
debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 5: Including file /etc/crypto-policies/back-ends/openssh.config depth 1 (parse only)
debug1: Reading configuration data /etc/crypto-policies/back-ends/openssh.config
debug3: gss kex names ok: [gss-curve25519-sha256-,gss-nistp256-sha256-,gss-group14-sha256-,gss-group16-sha512-]
debug3: kex names ok: [curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512]
debug1: configuration requests final Match pass
debug1: re-parsing configuration
debug1: Reading configuration data /home/ngompa/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/20-systemd-ssh-proxy.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/20-systemd-ssh-proxy.conf
debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/30-libvirt-ssh-proxy.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/30-libvirt-ssh-proxy.conf
debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/50-redhat.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/50-redhat.conf
debug2: checking match for 'final all' host pkgs.fedoraproject.org originally pkgs.fedoraproject.org
debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 3: matched 'final'
debug2: match found
debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 5: Including file /etc/crypto-policies/back-ends/openssh.config depth 1
debug1: Reading configuration data /etc/crypto-policies/back-ends/openssh.config
debug3: gss kex names ok: [gss-curve25519-sha256-,gss-nistp256-sha256-,gss-group14-sha256-,gss-group16-sha512-]
debug3: kex names ok: [curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512]
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/home/ngompa/.ssh/known_hosts'
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/home/ngompa/.ssh/known_hosts2'
debug2: resolving "pkgs.fedoraproject.org" port 22
debug3: resolve_host: lookup pkgs.fedoraproject.org:22
debug3: channel_clear_timeouts: clearing
debug3: ssh_connect_direct: entering
debug1: Connecting to pkgs.fedoraproject.org [38.145.60.17] port 22.
debug3: set_sock_tos: set socket 3 IP_TOS 0x48
debug1: connect to address 38.145.60.17 port 22: Connection timed out
ssh: connect to host pkgs.fedoraproject.org port 22: Connection timed out

I've been seeing this randomly for some time, and I was finally able to capture some logs about what's going on: ``` ngompa@fedora ~> ssh -Tvvv ssh://ngompa@pkgs.fedoraproject.org OpenSSH_9.9p1, OpenSSL 3.2.2 4 Jun 2024 debug1: Reading configuration data /home/ngompa/.ssh/config debug1: Reading configuration data /etc/ssh/ssh_config debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/20-systemd-ssh-proxy.conf depth 0 debug1: Reading configuration data /etc/ssh/ssh_config.d/20-systemd-ssh-proxy.conf debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/30-libvirt-ssh-proxy.conf depth 0 debug1: Reading configuration data /etc/ssh/ssh_config.d/30-libvirt-ssh-proxy.conf debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/50-redhat.conf depth 0 debug1: Reading configuration data /etc/ssh/ssh_config.d/50-redhat.conf debug2: checking match for 'final all' host pkgs.fedoraproject.org originally pkgs.fedoraproject.org debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 3: not matched 'final' debug2: match not found debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 5: Including file /etc/crypto-policies/back-ends/openssh.config depth 1 (parse only) debug1: Reading configuration data /etc/crypto-policies/back-ends/openssh.config debug3: gss kex names ok: [gss-curve25519-sha256-,gss-nistp256-sha256-,gss-group14-sha256-,gss-group16-sha512-] debug3: kex names ok: [curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512] debug1: configuration requests final Match pass debug1: re-parsing configuration debug1: Reading configuration data /home/ngompa/.ssh/config debug1: Reading configuration data /etc/ssh/ssh_config debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/20-systemd-ssh-proxy.conf depth 0 debug1: Reading configuration data /etc/ssh/ssh_config.d/20-systemd-ssh-proxy.conf debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/30-libvirt-ssh-proxy.conf depth 0 debug1: Reading configuration data /etc/ssh/ssh_config.d/30-libvirt-ssh-proxy.conf debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/50-redhat.conf depth 0 debug1: Reading configuration data /etc/ssh/ssh_config.d/50-redhat.conf debug2: checking match for 'final all' host pkgs.fedoraproject.org originally pkgs.fedoraproject.org debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 3: matched 'final' debug2: match found debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 5: Including file /etc/crypto-policies/back-ends/openssh.config depth 1 debug1: Reading configuration data /etc/crypto-policies/back-ends/openssh.config debug3: gss kex names ok: [gss-curve25519-sha256-,gss-nistp256-sha256-,gss-group14-sha256-,gss-group16-sha512-] debug3: kex names ok: [curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512] debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/home/ngompa/.ssh/known_hosts' debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/home/ngompa/.ssh/known_hosts2' debug2: resolving "pkgs.fedoraproject.org" port 22 debug3: resolve_host: lookup pkgs.fedoraproject.org:22 debug3: channel_clear_timeouts: clearing debug3: ssh_connect_direct: entering debug1: Connecting to pkgs.fedoraproject.org [38.145.60.17] port 22. debug3: set_sock_tos: set socket 3 IP_TOS 0x48 debug1: connect to address 38.145.60.17 port 22: Connection timed out ssh: connect to host pkgs.fedoraproject.org port 22: Connection timed out ```

zlopez commented

2025-03-10 11:19:58 +00:00

Contributor

Metadata Update from @zlopez:

Issue priority set to: Waiting on Assignee (was: Needs Review)
Issue tagged with: Needs investigation, low-gain

**Metadata Update from @zlopez**: - Issue priority set to: Waiting on Assignee (was: Needs Review) - Issue tagged with: Needs investigation, low-gain

markrosenbaum commented

2025-03-10 11:46:09 +00:00

I was unable to reproduce(but you did say it was something randomly occurring), was there any specific date/time that this occurred?

james commented

2025-03-10 15:21:50 +00:00

FWIW I tried looking at the logs for pkgs01.iad2.fedoraproject.org/2025/03/08 and nothing looks different, there were four sessions around that time:

15:39:37
15:39:59
15:40:24
15:40:41

...they all look like the same things happened.

FWIW I tried looking at the logs for pkgs01.iad2.fedoraproject.org/2025/03/08 and nothing looks different, there were four sessions around that time: 15:39:37 15:39:59 15:40:24 15:40:41 ...they all look like the same things happened.

james commented

2025-03-10 15:34:59 +00:00

Okay, I used lnav and that helped me find these SELinux errors from the first session:

Mar 8 15:39:43 pkgs01 tag_audit_log: type=USER_ERR msg=audit(1741448375.478:6440543): pid=2063495 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=PAM:bad_ident grantors=? acct="?" exe="/usr/sbin/sshd" hostname=218.92.0.243 addr=218.92.0.243 terminal=ssh res=failed'^]UID="root" AUID="unset"

Mar 8 15:39:43 pkgs01 tag_audit_log: type=USER_LOGIN msg=audit(1741448375.479:6440545): pid=2063495 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=login acct="root" exe="/usr/sbin/sshd" hostname=? addr=218.92.0.243 terminal=ssh res=failed'^]UID="root" AUID="unset"

Okay, I used lnav and that helped me find these SELinux errors from the first session: Mar 8 15:39:43 pkgs01 tag_audit_log: type=USER_ERR msg=audit(1741448375.478:6440543): pid=2063495 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=PAM:bad_ident grantors=? acct="?" exe="/usr/sbin/sshd" hostname=218.92.0.243 addr=218.92.0.243 terminal=ssh res=failed'^]UID="root" AUID="unset" Mar 8 15:39:43 pkgs01 tag_audit_log: type=USER_LOGIN msg=audit(1741448375.479:6440545): pid=2063495 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=login acct="root" exe="/usr/sbin/sshd" hostname=? addr=218.92.0.243 terminal=ssh res=failed'^]UID="root" AUID="unset"

james commented

2025-03-10 15:39:30 +00:00

Blah, that's probably a false hit ... it doesn't always happen, but it happens a bunch for a lot of different sessions.

kevin commented

2025-03-13 23:36:54 +00:00

It seems like it never even connects to the pkgs side... just tries and times out.

I wonder if there could something going on at the router/NAT level here? Like it's shutting down due to too many connections or something. ;(

@ngompa when this happens... is it after you have connected a bunch? Or that doesn't seem to matter? and how long do the timeouts last? Or hard to say?

It seems like it never even connects to the pkgs side... just tries and times out. I wonder if there could something going on at the router/NAT level here? Like it's shutting down due to too many connections or something. ;( @ngompa when this happens... is it after you have connected a bunch? Or that doesn't seem to matter? and how long do the timeouts last? Or hard to say?

ngompa commented

2025-03-14 15:47:25 +00:00

Author

This is happening right now. And I've been stuck for several minutes now.

I've only done a couple of sequential pushes and then I'm locked out via SSH.

This is happening right now. And I've been stuck for several minutes now. I've only done a couple of sequential pushes and then I'm locked out via SSH.

ngompa commented

2025-03-14 15:49:00 +00:00

Author

I'm also now seeing it with HTTPS too:

ngompa@fedora ~/f/miracle-wm (f42)> git merge rawhide && fedpkg push
Updating 5d09240..f200dc9
Fast-forward
 miracle-wm.spec | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)
Total 0 (delta 0), reused 0 (delta 0), pack-reused 0 (from 0)
error: RPC failed; HTTP 500 curl 22 The requested URL returned error: 500
send-pack: unexpected disconnect while reading sideband packet
fatal: the remote end hung up unexpectedly
Everything up-to-date
Could not execute push: Failed to execute command.

I'm also now seeing it with HTTPS too: ``` ngompa@fedora ~/f/miracle-wm (f42)> git merge rawhide && fedpkg push Updating 5d09240..f200dc9 Fast-forward miracle-wm.spec | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) Total 0 (delta 0), reused 0 (delta 0), pack-reused 0 (from 0) error: RPC failed; HTTP 500 curl 22 The requested URL returned error: 500 send-pack: unexpected disconnect while reading sideband packet fatal: the remote end hung up unexpectedly Everything up-to-date Could not execute push: Failed to execute command. ```