Questions about inferred state machines for OpenSSH

[P. V.]

Hi Damien,

Thanks for your reply. I really appreciate you taking the time to
investigate this.

I will try to clarify some things.

> I'm not sure what you mean by "entering a key exchange without receiving
> a proper kexinit message" because key exchange is initiated by a kexinit
> message. Do you mean that method specific messages are accepted before
> KEXINIT? (I can't see how this can happen from looking at the code).

Attached (log1) you find the OpenSSH debug log for a sequence in which
I manually send the sequence "SSH_MSG_KEXDH_INIT; SSH_MSG_KEXDH_INIT;
SSH_MSG_NEWKEYS". A normal key exchange sequence would be
"SSH_MSG_KEXINIT; SSH_MSG_KEXDH_INIT; SSH_MSG_NEWKEYS". Unless there
is an error in my code, it seems that OpenSSH does accept this anyway.
The log states:
> Jan 27 11:19:31 desktop sshd[4066]: debug1: SSH2_MSG_KEXINIT received [preauth]
while it didn't receive a KEXINIT but a KEXDH_INIT.

Same goes for a sequence such as: "SSH_MSG_IGNORE; SSH_MSG_KEXDH_INIT;
SSH_MSG_NEWKEYS". Instead of receiving a KEXINIT, the server receives
an IGNORE but continues with the key exchange anyway.

This only applies to the messages the server receives, it always
correctly sends an KEXINIT upon connection.

> I don't think this is the case, it is true that ssh/sshd
> fail to apply rekeying limits before completion of userauth but I
> think they will respond to KEXINIT messages.

I sent the following message sequence to the server: "SSH_MSG_KEXINIT;
SSH_MSG_KEXDH_INIT; SSH_MSG_NEWKEYS; SSH_MSG_SERVICE_REQUEST;
SSH_MSG_NEWKEYS". It behaves normally up until the point that I
initiate a key re-exchange (last message). The SSH server returns an
SSH_MSG_UNIMPLEMENTED and closes the connection. Log2 gives the debug
output.

The sequence "SSH_MSG_KEXINIT; SSH_MSG_KEXDH_INIT; SSH_MSG_NEWKEYS;
SSH_MSG_SERVICE_REQUEST; SSH_MSG_USERAUTH_REQUEST; SSH_MSG_NEWKEYS;
SSH_MSG_KEXDH_INIT; SSH_MSG_NEWKEYS" performs a kex-exchange,
authentication and another key exchange. This does work as expected.
Log3 gives the debug output.

Again, I can't exclude a programming error on my side, but it seems
that rekeying does not work until after successful user
authentication.

> Not sure what you mean here, but we don't support re-authentication
> (as I understand the term). Do you mean subsequent authentication
> requests after a "partial" authentication success, authentication
> requests after a failed request or something different?
> We certainly shouldn't allow requesting the userauth service after
> userauth has completed.

Forgive my ambiguity, I meant authentication requests after an earlier
failed authentication request. Debug log gives the answer however, I
tried the other methods with another username. This is apparently not
allowed:
> Jan 27 12:01:07 desktop sshd[4845]: Disconnecting: Change of username or service not allowed: (NOACCESS,ssh-connection) -> (thesis,ssh-connection) [preauth]

> It would be helpful to see debug messages from ssh/sshd for this case
> (well, all cases but this in particular).

I sent the following sequence to the OpenSSH server.

SSH_MSG_KEXINIT;
 (server replies with SSH_MSG_KEXINIT)
SSH_MSG_KEXDH_INIT;
 (server replies with SSH_MSG_KEXDH_REPLY)
SSH_MSG_NEWKEYS;
 (server does not reply)
SSH_MSG_SERVICE_REQUEST;
 (server replies with SSH_MSG_SERVICE_ACCEPT)
SSH_MSG_USERAUTH_REQUEST
 (server replies with SSH_MSG_USERAUTH_SUCCESS and SSH_MSG_GLOBAL_REQUEST)
SSH_MSG_CHANNEL_OPEN
 (server replies with SSH_MSG_CHANNEL_OPEN_CONFIRMATION)

-- Now I do a rekey --
SSH_MSG_KEXINIT;
 (server replies with SSH_MSG_KEXINIT)
SSH_MSG_KEXDH_INIT;
 (server replies with SSH_MSG_KEXDH_REPLY)
SSH_MSG_NEWKEYS;
 (server does not reply)

-- Now I close the channel --

SSH_MSG_CHANNEL_CLOSE
  (server replies with SSH_MSG_CHANNEL_CLOSE and sends an SSH_MSG_DISCONNECT)

The entire debug log can be found in the log4 attachment.

Hope this clarifies everything. I would love to hear your thoughts on
these issues!

Kind regards,

[1] https://drive.google.com/drive/folders/0B6T2_FvFKPIkRGdqVDFtOXNQQWc

On Wed, Jan 27, 2016 at 8:38 AM, Damien Miller <djm at mindrot.org> wrote:
> On Tue, 26 Jan 2016, P. V. wrote:
>
>> Dear all,
>>
>> For my thesis, I've been working on automatic inference of state
>> machines for SSH servers. I ran into a couple of particularities
>> regarding OpenSSH's inferred state machine, and was hoping some of you
>> might be interested. Maybe you can even shed some light on it.
>>
>> Setup: I'm using LearnLib's (Java) version of the L* learning
>> algorithm [1] to come up with sequences of textual representations of
>> SSH messages (such as "DEBUG; DISCONNECT"). An altered version of
>> Paramiko (Python) receives those queries and translates them to actual
>> SSH traffic, which is sent to OpenSSH. Responses are fed to the
>> learning algorithm, resulting in a state machine.
>
>> The PDFs of inferred state machines, as well as the used messages, can
>> be found online [2]. I've queried the the transport layer, user
>> authentication layer and connection layer separately.
>>
>> Now for my questions. Assuming my results are correct, it seems that:
>> 1) OpenSSH is extremely liberal when it comes to exchanging kexinit
>> messsages (openssh-localhost-L1.pdf). It allows entering a key
>> exchange without receiving a proper kexinit message at all. Since this
>> message is required to exchange parameters, does this imply that
>> OpenSSH will guess those when no kexinit is received?
>
> I'm not sure what you mean by "entering a key exchange without receiving
> a proper kexinit message" because key exchange is initiated by a kexinit
> message. Do you mean that method specific messages are accepted before
> KEXINIT? (I can't see how this can happen from looking at the code).
>
>> 2) OpenSSH does not allow rekeying until after correct user
>> authentication. The RFCs specify otherwise. Is this a deliberate
>> choice?
>
> I don't think this is the case, it is true that ssh/sshd
> fail to apply rekeying limits before completion of userauth but I
> think they will respond to KEXINIT messages.
>
>> 3) OpenSSH shows peculiar behavior in user re-authentication. Some
>> re-authentication methods seem to be disallowed after an unsuccessful
>> authentication attempt. You can see what I mean in
>> openssh-localhost-L2.pdf. Is this intended behavior, a bug, or perhaps
>> an error on my side?
>
> Not sure what you mean here, but we don't support re-authentication
> (as I understand the term). Do you mean subsequent authentication
> requests after a "partial" authentication success, authentication
> requests after a failed request or something different?
>
> We certainly shouldn't allow requesting the userauth service after
> userauth has completed.
>
>> 4) Unlike other tested SSH servers, OpenSSH seems to close the entire
>> connection (rather than close the channel) on a channel-close message
>> in certain conditions. This results in the 'has_commands' and
>> 'has_commands_pty' states in openssh-localhost-L3.pdf. I was wondering
>> why. An error on my side, or intended behavior?
>
> It would be helpful to see debug messages from ssh/sshd for this case
> (well, all cases but this in particular).
>
> -d
-------------- next part --------------
Jan 27 11:19:28 desktop sshd[798]: debug1: Forked child 4066.
Jan 27 11:19:28 desktop sshd[4066]: Set /proc/self/oom_score_adj to 0
Jan 27 11:19:28 desktop sshd[4066]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Jan 27 11:19:28 desktop sshd[4066]: debug1: inetd sockets after dupping: 3, 3
Jan 27 11:19:28 desktop sshd[4066]: Connection from 127.0.0.1 port 45678 on 127.0.0.1 port 22
Jan 27 11:19:28 desktop sshd[4066]: debug1: Client protocol version 2.0; client software version paramiko_1.16.0
Jan 27 11:19:28 desktop sshd[4066]: debug1: no match: paramiko_1.16.0
Jan 27 11:19:28 desktop sshd[4066]: debug1: Enabling compatibility mode for protocol 2.0
Jan 27 11:19:28 desktop sshd[4066]: debug1: Local version string SSH-2.0-OpenSSH_6.9p1 Ubuntu-2ubuntu0.1
Jan 27 11:19:28 desktop sshd[4066]: debug1: permanently_set_uid: 123/65534 [preauth]
Jan 27 11:19:28 desktop sshd[4066]: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 27 11:19:28 desktop sshd[4066]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jan 27 11:19:31 desktop sshd[4066]: error: Hm, kex protocol error: type 30 seq 0 [preauth]
Jan 27 11:19:31 desktop sshd[4066]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jan 27 11:19:31 desktop sshd[4066]: debug1: kex: client->server aes128-ctr hmac-sha1 none [preauth]
Jan 27 11:19:31 desktop sshd[4066]: debug1: kex: server->client aes128-ctr hmac-sha1 none [preauth]
Jan 27 11:19:31 desktop sshd[4066]: debug1: expecting SSH2_MSG_KEXDH_INIT [preauth]
Jan 27 11:19:33 desktop sshd[4066]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jan 27 11:19:33 desktop sshd[4066]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jan 27 11:19:38 desktop sshd[4066]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jan 27 11:19:38 desktop sshd[4066]: debug1: KEX done [preauth]


-------------- next part --------------
Jan 27 11:30:12 desktop sshd[798]: debug1: Forked child 4368.
Jan 27 11:30:12 desktop sshd[4368]: Set /proc/self/oom_score_adj to 0
Jan 27 11:30:12 desktop sshd[4368]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Jan 27 11:30:12 desktop sshd[4368]: debug1: inetd sockets after dupping: 3, 3
Jan 27 11:30:12 desktop sshd[4368]: Connection from 127.0.0.1 port 45726 on 127.0.0.1 port 22
Jan 27 11:30:12 desktop sshd[4368]: debug1: Client protocol version 2.0; client software version paramiko_1.16.0
Jan 27 11:30:12 desktop sshd[4368]: debug1: no match: paramiko_1.16.0
Jan 27 11:30:12 desktop sshd[4368]: debug1: Enabling compatibility mode for protocol 2.0
Jan 27 11:30:12 desktop sshd[4368]: debug1: Local version string SSH-2.0-OpenSSH_6.9p1 Ubuntu-2ubuntu0.1
Jan 27 11:30:12 desktop sshd[4368]: debug1: permanently_set_uid: 123/65534 [preauth]
Jan 27 11:30:12 desktop sshd[4368]: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 27 11:30:12 desktop sshd[4368]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jan 27 11:30:17 desktop sshd[4368]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jan 27 11:30:17 desktop sshd[4368]: debug1: kex: client->server aes128-ctr hmac-sha1 none [preauth]
Jan 27 11:30:17 desktop sshd[4368]: debug1: kex: server->client aes128-ctr hmac-sha1 none [preauth]
Jan 27 11:30:17 desktop sshd[4368]: debug1: expecting SSH2_MSG_KEXDH_INIT [preauth]
Jan 27 11:30:21 desktop sshd[4368]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jan 27 11:30:21 desktop sshd[4368]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jan 27 11:30:25 desktop sshd[4368]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jan 27 11:30:25 desktop sshd[4368]: debug1: KEX done [preauth]
Jan 27 11:30:37 desktop sshd[4368]: dispatch_protocol_error: type 20 seq 4 [preauth]


-------------- next part --------------
Jan 27 11:35:38 desktop sshd[798]: debug1: Forked child 4459.
Jan 27 11:35:38 desktop sshd[4459]: Set /proc/self/oom_score_adj to 0
Jan 27 11:35:38 desktop sshd[4459]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Jan 27 11:35:38 desktop sshd[4459]: debug1: inetd sockets after dupping: 3, 3
Jan 27 11:35:38 desktop sshd[4459]: Connection from 127.0.0.1 port 45744 on 127.0.0.1 port 22
Jan 27 11:35:38 desktop sshd[4459]: debug1: Client protocol version 2.0; client software version paramiko_1.16.0
Jan 27 11:35:38 desktop sshd[4459]: debug1: no match: paramiko_1.16.0
Jan 27 11:35:38 desktop sshd[4459]: debug1: Enabling compatibility mode for protocol 2.0
Jan 27 11:35:38 desktop sshd[4459]: debug1: Local version string SSH-2.0-OpenSSH_6.9p1 Ubuntu-2ubuntu0.1
Jan 27 11:35:38 desktop sshd[4459]: debug1: permanently_set_uid: 123/65534 [preauth]
Jan 27 11:35:38 desktop sshd[4459]: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 27 11:35:38 desktop sshd[4459]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jan 27 11:35:40 desktop sshd[4459]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jan 27 11:35:40 desktop sshd[4459]: debug1: kex: client->server aes128-ctr hmac-sha1 none [preauth]
Jan 27 11:35:40 desktop sshd[4459]: debug1: kex: server->client aes128-ctr hmac-sha1 none [preauth]
Jan 27 11:35:40 desktop sshd[4459]: debug1: expecting SSH2_MSG_KEXDH_INIT [preauth]
Jan 27 11:35:44 desktop sshd[4459]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jan 27 11:35:44 desktop sshd[4459]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jan 27 11:35:48 desktop sshd[4459]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jan 27 11:35:48 desktop sshd[4459]: debug1: KEX done [preauth]
Jan 27 11:36:06 desktop sshd[4459]: debug1: userauth-request for user thesis service ssh-connection method password [preauth]
Jan 27 11:36:06 desktop sshd[4459]: debug1: attempt 0 failures 0 [preauth]
Jan 27 11:36:06 desktop sshd[4459]: debug1: PAM: initializing for "thesis"
Jan 27 11:36:06 desktop sshd[4459]: debug1: PAM: setting PAM_RHOST to "127.0.0.1"
Jan 27 11:36:06 desktop sshd[4459]: debug1: PAM: setting PAM_TTY to "ssh"
Jan 27 11:36:06 desktop sshd[4459]: debug1: PAM: password authentication accepted for thesis
Jan 27 11:36:06 desktop sshd[4459]: debug1: do_pam_account: called
Jan 27 11:36:06 desktop sshd[4459]: Accepted password for thesis from 127.0.0.1 port 45744 ssh2
Jan 27 11:36:06 desktop sshd[4459]: debug1: monitor_child_preauth: thesis has been authenticated by privileged process
Jan 27 11:36:06 desktop sshd[4459]: debug1: monitor_read_log: child log fd closed
Jan 27 11:36:06 desktop sshd[4459]: debug1: PAM: establishing credentials
Jan 27 11:36:06 desktop sshd[4459]: pam_unix(sshd:session): session opened for user thesis by (uid=0)
Jan 27 11:36:06 desktop systemd: pam_unix(systemd-user:session): session opened for user thesis by (uid=0)
Jan 27 11:36:06 desktop systemd-logind[686]: New session 2 of user thesis.
Jan 27 11:36:06 desktop sshd[4459]: User child is on pid 4522
Jan 27 11:36:06 desktop sshd[4522]: debug1: SELinux support disabled
Jan 27 11:36:06 desktop sshd[4522]: debug1: PAM: establishing credentials
Jan 27 11:36:06 desktop sshd[4522]: debug1: permanently_set_uid: 1002/1002
Jan 27 11:36:06 desktop sshd[4522]: debug1: ssh_packet_set_postauth: called
Jan 27 11:36:06 desktop sshd[4522]: debug1: Entering interactive session for SSH2.
Jan 27 11:36:06 desktop sshd[4522]: debug1: server_init_dispatch_20
Jan 27 11:36:16 desktop sshd[4522]: debug1: SSH2_MSG_KEXINIT received
Jan 27 11:36:16 desktop sshd[4522]: debug1: SSH2_MSG_KEXINIT sent
Jan 27 11:36:16 desktop sshd[4522]: debug1: kex: client->server aes128-ctr hmac-sha1 none
Jan 27 11:36:16 desktop sshd[4522]: debug1: kex: server->client aes128-ctr hmac-sha1 none
Jan 27 11:36:16 desktop sshd[4522]: debug1: expecting SSH2_MSG_KEXDH_INIT
Jan 27 11:36:24 desktop sshd[4522]: debug1: set_newkeys: rekeying
Jan 27 11:36:24 desktop sshd[4522]: debug1: SSH2_MSG_NEWKEYS sent
Jan 27 11:36:24 desktop sshd[4522]: debug1: expecting SSH2_MSG_NEWKEYS
Jan 27 11:36:27 desktop sshd[4522]: debug1: set_newkeys: rekeying
Jan 27 11:36:27 desktop sshd[4522]: debug1: SSH2_MSG_NEWKEYS received


-------------- next part --------------
Jan 27 11:46:13 desktop sshd[798]: debug1: Forked child 4631.
Jan 27 11:46:13 desktop sshd[4631]: Set /proc/self/oom_score_adj to 0
Jan 27 11:46:13 desktop sshd[4631]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Jan 27 11:46:13 desktop sshd[4631]: debug1: inetd sockets after dupping: 3, 3
Jan 27 11:46:13 desktop sshd[4631]: Connection from 127.0.0.1 port 45758 on 127.0.0.1 port 22
Jan 27 11:46:13 desktop sshd[4631]: debug1: Client protocol version 2.0; client software version paramiko_1.16.0
Jan 27 11:46:13 desktop sshd[4631]: debug1: no match: paramiko_1.16.0
Jan 27 11:46:13 desktop sshd[4631]: debug1: Enabling compatibility mode for protocol 2.0
Jan 27 11:46:13 desktop sshd[4631]: debug1: Local version string SSH-2.0-OpenSSH_6.9p1 Ubuntu-2ubuntu0.1
Jan 27 11:46:13 desktop sshd[4631]: debug1: permanently_set_uid: 123/65534 [preauth]
Jan 27 11:46:13 desktop sshd[4631]: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 27 11:46:13 desktop sshd[4631]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jan 27 11:46:16 desktop sshd[4631]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jan 27 11:46:16 desktop sshd[4631]: debug1: kex: client->server aes128-ctr hmac-sha1 none [preauth]
Jan 27 11:46:16 desktop sshd[4631]: debug1: kex: server->client aes128-ctr hmac-sha1 none [preauth]
Jan 27 11:46:16 desktop sshd[4631]: debug1: expecting SSH2_MSG_KEXDH_INIT [preauth]
Jan 27 11:46:19 desktop sshd[4631]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jan 27 11:46:19 desktop sshd[4631]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jan 27 11:46:25 desktop sshd[4631]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jan 27 11:46:25 desktop sshd[4631]: debug1: KEX done [preauth]
Jan 27 11:46:47 desktop sshd[4631]: debug1: userauth-request for user thesis service ssh-connection method password [preauth]
Jan 27 11:46:47 desktop sshd[4631]: debug1: attempt 0 failures 0 [preauth]
Jan 27 11:46:47 desktop sshd[4631]: debug1: PAM: initializing for "thesis"
Jan 27 11:46:47 desktop sshd[4631]: debug1: PAM: setting PAM_RHOST to "127.0.0.1"
Jan 27 11:46:47 desktop sshd[4631]: debug1: PAM: setting PAM_TTY to "ssh"
Jan 27 11:46:47 desktop sshd[4631]: debug1: PAM: password authentication accepted for thesis
Jan 27 11:46:47 desktop sshd[4631]: debug1: do_pam_account: called
Jan 27 11:46:47 desktop sshd[4631]: Accepted password for thesis from 127.0.0.1 port 45758 ssh2
Jan 27 11:46:47 desktop sshd[4631]: debug1: monitor_child_preauth: thesis has been authenticated by privileged process
Jan 27 11:46:47 desktop sshd[4631]: debug1: monitor_read_log: child log fd closed
Jan 27 11:46:47 desktop sshd[4631]: debug1: PAM: establishing credentials
Jan 27 11:46:47 desktop sshd[4631]: pam_unix(sshd:session): session opened for user thesis by (uid=0)
Jan 27 11:46:47 desktop systemd: pam_unix(systemd-user:session): session opened for user thesis by (uid=0)
Jan 27 11:46:47 desktop systemd-logind[686]: New session 4 of user thesis.
Jan 27 11:46:47 desktop sshd[4631]: User child is on pid 4673
Jan 27 11:46:47 desktop sshd[4673]: debug1: SELinux support disabled
Jan 27 11:46:47 desktop sshd[4673]: debug1: PAM: establishing credentials
Jan 27 11:46:47 desktop sshd[4673]: debug1: permanently_set_uid: 1002/1002
Jan 27 11:46:47 desktop sshd[4673]: debug1: ssh_packet_set_postauth: called
Jan 27 11:46:47 desktop sshd[4673]: debug1: Entering interactive session for SSH2.
Jan 27 11:46:47 desktop sshd[4673]: debug1: server_init_dispatch_20
Jan 27 11:47:02 desktop sshd[4673]: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
Jan 27 11:47:02 desktop sshd[4673]: debug1: input_session_request
Jan 27 11:47:02 desktop sshd[4673]: debug1: channel 0: new [server-session]
Jan 27 11:47:02 desktop sshd[4673]: debug1: session_new: session 0
Jan 27 11:47:02 desktop sshd[4673]: debug1: session_open: channel 0
Jan 27 11:47:02 desktop sshd[4673]: debug1: session_open: session 0: link with channel 0
Jan 27 11:47:02 desktop sshd[4673]: debug1: server_input_channel_open: confirm session
Jan 27 11:47:19 desktop sshd[4673]: debug1: SSH2_MSG_KEXINIT received
Jan 27 11:47:19 desktop sshd[4673]: debug1: SSH2_MSG_KEXINIT sent
Jan 27 11:47:19 desktop sshd[4673]: debug1: kex: client->server aes128-ctr hmac-sha1 none
Jan 27 11:47:19 desktop sshd[4673]: debug1: kex: server->client aes128-ctr hmac-sha1 none
Jan 27 11:47:19 desktop sshd[4673]: debug1: expecting SSH2_MSG_KEXDH_INIT
Jan 27 11:47:23 desktop sshd[4673]: debug1: set_newkeys: rekeying
Jan 27 11:47:23 desktop sshd[4673]: debug1: SSH2_MSG_NEWKEYS sent
Jan 27 11:47:23 desktop sshd[4673]: debug1: expecting SSH2_MSG_NEWKEYS
Jan 27 11:47:27 desktop sshd[4673]: debug1: set_newkeys: rekeying
Jan 27 11:47:27 desktop sshd[4673]: debug1: SSH2_MSG_NEWKEYS received
Jan 27 11:47:32 desktop sshd[4673]: debug1: session_by_channel: session 0 channel 0
Jan 27 11:47:32 desktop sshd[4673]: debug1: session_close_by_channel: channel 0 child 0
Jan 27 11:47:32 desktop sshd[4673]: debug1: session_close: session 0 pid 0
Jan 27 11:47:32 desktop sshd[4673]: debug1: channel 0: free: server-session, nchannels 1
Jan 27 11:47:32 desktop sshd[4673]: channel_by_id: 0: bad id: channel free
Jan 27 11:47:32 desktop sshd[4673]: Disconnecting: Received oclose for nonexistent channel 0.
Jan 27 11:47:32 desktop sshd[4673]: debug1: do_cleanup
Jan 27 11:47:32 desktop sshd[4631]: debug1: do_cleanup
Jan 27 11:47:32 desktop sshd[4631]: debug1: PAM: cleanup
Jan 27 11:47:32 desktop sshd[4631]: debug1: PAM: closing session
Jan 27 11:47:32 desktop sshd[4631]: pam_unix(sshd:session): session closed for user thesis
Jan 27 11:47:32 desktop sshd[4631]: debug1: PAM: deleting credentials
Jan 27 11:47:32 desktop sshd[4631]: debug1: audit_event: unhandled event 12
Jan 27 11:47:32 desktop systemd-logind[686]: Removed session 4.
Jan 27 11:47:32 desktop systemd: pam_unix(systemd-user:session): session closed for user thesis