Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss
Weird delay in ssh login
46 views
Skip to first unread message
Stefan Monnier
Feb 21, 2022, 7:20:06 PM2/21/22
to
Hi,
I have a VM here which gives me weird delays when I log into it (which
I can only do via SSH) since I upgraded it to Bullseye.
The connection looks like:
% ssh -v ...
[...]
debug1: control_persist_detach: backgrounding master process
debug1: forking to background
debug1: Entering interactive session.
debug1: pledge: id
debug1: multiplexing control connection
debug1: channel 1: new [mux-control]
debug1: channel 2: new [client-session]
[ !!! a bit more than 1m30s delay here !!! ]
debug1: client_input_global_request: rtype hostk...@openssh.com want_reply 0
debug1: Remote: /home/.../.ssh/authorized_keys:NN: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Remote: /home/.../.ssh/authorized_keys:NN: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
[...]
Any idea what might be going on or how I could debug this?
`journalctl | grep sshd` doesn't show much of interest around that time:
Feb 21 19:02:34 ... sshd[...]: Accepted publickey for <MYUSER> from <MYIP> port 45732 ssh2: RSA ...
Feb 21 19:02:34 ... sshd[...]: pam_unix(sshd:session): session opened for user <MYUSER>(uid=<MYUID>) by (uid=0)
Feb 21 19:02:53 ... sshd[...]: Received disconnect from 109.230.224.192 port 33352:11: Bye Bye [preauth]
Feb 21 19:02:53 ... sshd[...]: Disconnected from authenticating user root 109.230.224.192 port 33352 [preauth]
Feb 21 19:03:26 ... sshd[...]: Invalid user mailing from 165.22.53.200 port 49372
Feb 21 19:03:26 ... sshd[...]: Received disconnect from 165.22.53.200 port 49372:11: Bye Bye [preauth]
Feb 21 19:03:26 ... sshd[...]: Disconnected from invalid user mailing 165.22.53.200 port 49372 [preauth]
Feb 21 19:03:32 ... sshd[...]: Connection closed by 13.92.91.254 port 47988 [preauth]
Feb 21 19:03:55 ... sshd[...]: Invalid user yogesh from 74.208.53.194 port 44634
Feb 21 19:03:55 ... sshd[...]: Received disconnect from 74.208.53.194 port 44634:11: Bye Bye [preauth]
Feb 21 19:03:55 ... sshd[...]: Disconnected from invalid user yogesh 74.208.53.194 port 44634 [preauth]
Feb 21 19:04:16 ... sshd[...]: Invalid user fiona from 178.128.218.29 port 57610
Only the first two entries seem related to my connection (and share the
same PID), the rest (from which I didn't scrub the IP and user names)
are the usual relentless attempts to log into the machine from botnets.
Stefan
I have a VM here which gives me weird delays when I log into it (which
I can only do via SSH) since I upgraded it to Bullseye.
The connection looks like:
% ssh -v ...
[...]
debug1: control_persist_detach: backgrounding master process
debug1: forking to background
debug1: Entering interactive session.
debug1: pledge: id
debug1: multiplexing control connection
debug1: channel 1: new [mux-control]
debug1: channel 2: new [client-session]
[ !!! a bit more than 1m30s delay here !!! ]
debug1: client_input_global_request: rtype hostk...@openssh.com want_reply 0
debug1: Remote: /home/.../.ssh/authorized_keys:NN: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Remote: /home/.../.ssh/authorized_keys:NN: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
[...]
Any idea what might be going on or how I could debug this?
`journalctl | grep sshd` doesn't show much of interest around that time:
Feb 21 19:02:34 ... sshd[...]: Accepted publickey for <MYUSER> from <MYIP> port 45732 ssh2: RSA ...
Feb 21 19:02:34 ... sshd[...]: pam_unix(sshd:session): session opened for user <MYUSER>(uid=<MYUID>) by (uid=0)
Feb 21 19:02:53 ... sshd[...]: Received disconnect from 109.230.224.192 port 33352:11: Bye Bye [preauth]
Feb 21 19:02:53 ... sshd[...]: Disconnected from authenticating user root 109.230.224.192 port 33352 [preauth]
Feb 21 19:03:26 ... sshd[...]: Invalid user mailing from 165.22.53.200 port 49372
Feb 21 19:03:26 ... sshd[...]: Received disconnect from 165.22.53.200 port 49372:11: Bye Bye [preauth]
Feb 21 19:03:26 ... sshd[...]: Disconnected from invalid user mailing 165.22.53.200 port 49372 [preauth]
Feb 21 19:03:32 ... sshd[...]: Connection closed by 13.92.91.254 port 47988 [preauth]
Feb 21 19:03:55 ... sshd[...]: Invalid user yogesh from 74.208.53.194 port 44634
Feb 21 19:03:55 ... sshd[...]: Received disconnect from 74.208.53.194 port 44634:11: Bye Bye [preauth]
Feb 21 19:03:55 ... sshd[...]: Disconnected from invalid user yogesh 74.208.53.194 port 44634 [preauth]
Feb 21 19:04:16 ... sshd[...]: Invalid user fiona from 178.128.218.29 port 57610
Only the first two entries seem related to my connection (and share the
same PID), the rest (from which I didn't scrub the IP and user names)
are the usual relentless attempts to log into the machine from botnets.
Stefan
to...@tuxteam.de
Feb 21, 2022, 11:40:05 PM2/21/22
to
On Mon, Feb 21, 2022 at 07:18:36PM -0500, Stefan Monnier wrote:
> Hi,
>
> I have a VM here which gives me weird delays when I log into it (which
> I can only do via SSH) since I upgraded it to Bullseye.
>
> The connection looks like:
>
> % ssh -v ...
> [...]
> debug1: control_persist_detach: backgrounding master process
> debug1: forking to background
> debug1: Entering interactive session.
> debug1: pledge: id
> debug1: multiplexing control connection
> debug1: channel 1: new [mux-control]
> debug1: channel 2: new [client-session]
> [ !!! a bit more than 1m30s delay here !!! ]
This smells like your VM's ssh server is trying to reverse-resolve
> Hi,
>
> I have a VM here which gives me weird delays when I log into it (which
> I can only do via SSH) since I upgraded it to Bullseye.
>
> The connection looks like:
>
> % ssh -v ...
> [...]
> debug1: control_persist_detach: backgrounding master process
> debug1: forking to background
> debug1: Entering interactive session.
> debug1: pledge: id
> debug1: multiplexing control connection
> debug1: channel 1: new [mux-control]
> debug1: channel 2: new [client-session]
> [ !!! a bit more than 1m30s delay here !!! ]
the client's IP address to a name until the resolver times out.
Caveat: a quick shot off the hip, I might be extremely wrong...
Cheers
--
t
Stefan Monnier
Feb 22, 2022, 8:50:06 AM2/22/22
to
>> The connection looks like:
>>
>> % ssh -v ...
>> [...]
>> debug1: control_persist_detach: backgrounding master process
>> debug1: forking to background
>> debug1: Entering interactive session.
>> debug1: pledge: id
>> debug1: multiplexing control connection
>> debug1: channel 1: new [mux-control]
>> debug1: channel 2: new [client-session]
>> [ !!! a bit more than 1m30s delay here !!! ]
>
> This smells like your VM's ssh server is trying to reverse-resolve
> the client's IP address to a name until the resolver times out.
My intuition also suggests this possibility but I tried to put `UseDNS
>>
>> % ssh -v ...
>> [...]
>> debug1: control_persist_detach: backgrounding master process
>> debug1: forking to background
>> debug1: Entering interactive session.
>> debug1: pledge: id
>> debug1: multiplexing control connection
>> debug1: channel 1: new [mux-control]
>> debug1: channel 2: new [client-session]
>> [ !!! a bit more than 1m30s delay here !!! ]
>
> This smells like your VM's ssh server is trying to reverse-resolve
> the client's IP address to a name until the resolver times out.
no` in /etc/ssh/sshd_config and it made no difference.
But this prompted me to try and increase sshd's logging to `DEBUG3` and
now I do something apparently related in the log: right when the delay
ends I get:
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: start operation timed out. Terminating.
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Main process exited, code=exited, status=1/FAILURE
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659208 (gpgconf) with signal SIGKILL.
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659209 (awk) with signal SIGKILL.
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659214 (dirmngr) with signal SIGKILL.
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Failed with result 'timeout'.
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659208 (gpgconf) remains running after unit stopped.
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659209 (awk) remains running after unit stopped.
Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659214 (dirmngr) remains running after unit stopped.
Feb 22 08:43:20 ... systemd[1]: Failed to start User Manager for UID 1001.
Feb 22 08:43:20 ... systemd[1]: Started Session 50020 of user <USERNAME>.
Any idea what that systemd's "start operation timed out" might be about
or how to track it down?
Stefan
to...@tuxteam.de
Feb 22, 2022, 2:40:06 PM2/22/22
to
On Tue, Feb 22, 2022 at 08:47:59AM -0500, Stefan Monnier wrote:
> >> The connection looks like:
[...]
> > This smells like your VM's ssh server is trying to reverse-resolve
> > the client's IP address [...]
> My intuition also suggests this possibility but I tried to put `UseDNS
> no` in /etc/ssh/sshd_config and it made no difference.
Darn :-(
> But this prompted me to try and increase sshd's logging to `DEBUG3` and
> now I do something apparently related in the log: right when the delay
> ends I get:
>
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: start operation timed out. Terminating.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Main process exited, code=exited, status=1/FAILURE
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659208 (gpgconf) with signal SIGKILL.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659209 (awk) with signal SIGKILL.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659214 (dirmngr) with signal SIGKILL.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Failed with result 'timeout'.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659208 (gpgconf) remains running after unit stopped.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659209 (awk) remains running after unit stopped.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659214 (dirmngr) remains running after unit stopped.
> Feb 22 08:43:20 ... systemd[1]: Failed to start User Manager for UID 1001.
> Feb 22 08:43:20 ... systemd[1]: Started Session 50020 of user <USERNAME>.
>
> Any idea what that systemd's "start operation timed out" might be about
> or how to track it down?
I'm totally out of my depth on this one, sorry. My search engine says it
looks a bit like
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=877985;msg=7
which points to
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=841740
which suggests that something with the systemd user session for your
user 1001 went sour. I know, handwaving...
Perhaps some systemd buff around here?
Cheers
--
t
> >> The connection looks like:
[...]
> > This smells like your VM's ssh server is trying to reverse-resolve
> My intuition also suggests this possibility but I tried to put `UseDNS
> no` in /etc/ssh/sshd_config and it made no difference.
> But this prompted me to try and increase sshd's logging to `DEBUG3` and
> now I do something apparently related in the log: right when the delay
> ends I get:
>
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: start operation timed out. Terminating.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Main process exited, code=exited, status=1/FAILURE
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659208 (gpgconf) with signal SIGKILL.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659209 (awk) with signal SIGKILL.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Killing process 3659214 (dirmngr) with signal SIGKILL.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Failed with result 'timeout'.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659208 (gpgconf) remains running after unit stopped.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659209 (awk) remains running after unit stopped.
> Feb 22 08:43:20 ... systemd[1]: us...@1001.service: Unit process 3659214 (dirmngr) remains running after unit stopped.
> Feb 22 08:43:20 ... systemd[1]: Failed to start User Manager for UID 1001.
> Feb 22 08:43:20 ... systemd[1]: Started Session 50020 of user <USERNAME>.
>
> Any idea what that systemd's "start operation timed out" might be about
> or how to track it down?
looks a bit like
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=877985;msg=7
which points to
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=841740
which suggests that something with the systemd user session for your
user 1001 went sour. I know, handwaving...
Perhaps some systemd buff around here?
Cheers
--
t
0 new messages