Azure / Azure/azure-cli-extensions

az ssh hangs for duration of ControlPersist if ControlPersist option is set.

Open
#7,285 12 comments 0 reactions 1 assignee Claimed by @vthiebaut10 View on GitHub
Auto-Assign bug customer-reported Service Attention VM SSH
Dominant language
Python
Stars
454
Forks
1.7k
Avg merge
2d 19h
Merged PRs (30d)
64

Description

### Describe the bug

If `az ssh` is called with the ssh ControlPersist options, it hangs for specified duration of ControlPersist.

For example, the following takes 2.8 seconds:

``` sh
az ssh vm --ip 1.2.3.4 -- exit
```

While this takes 63.3 seconds.

``` sh
az ssh vm --ip 1.2.3.4 -- -o ControlMaster=auto -o ControlPath=/home/example/controlpath -o ControlPersist=60s exit
```

### Related command

`az ssh vm`

### Errors

No error.

### Issue script & Debug output

```
❯ az ssh vm --ip 1.2.3.4 -- -vvv -o ControlMaster=auto -o ControlPath=/home/example/controlpath -o ControlPersist=60s exit 2>&1 | ts -s '(%H:%M:%.S)]' | ts '[%Y-%m-%d %H:%M:%S'
[2024-02-13 14:41:28 (00:00:01.570274)] OpenSSH_8.9p1 Ubuntu-3ubuntu0.6, OpenSSL 3.0.2 15 Mar 2022
[2024-02-13 14:41:28 (00:00:01.570396)] debug1: Reading configuration data /etc/ssh/ssh_config
[2024-02-13 14:41:28 (00:00:01.570407)] debug1: /etc/ssh/ssh_config line 19: include /etc/ssh/ssh_config.d/*.conf matched no files
[2024-02-13 14:41:28 (00:00:01.570421)] debug1: /etc/ssh/ssh_config line 21: Applying options for *
[2024-02-13 14:41:28 (00:00:01.570425)] debug2: resolve_canonicalize: hostname 1.2.3.4 is address
[2024-02-13 14:41:28 (00:00:01.570593)] debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/home/example/.ssh/known_hosts'
[2024-02-13 14:41:28 (00:00:01.570611)] debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/home/example/.ssh/known_hosts2'
[2024-02-13 14:41:28 (00:00:01.570615)] debug1: auto-mux: Trying existing master
[2024-02-13 14:41:28 (00:00:01.570618)] debug1: Control socket "/home/example/controlpath" does not exist
[2024-02-13 14:41:28 (00:00:01.570620)] debug3: ssh_connect_direct: entering
[2024-02-13 14:41:28 (00:00:01.570623)] debug1: Connecting to 1.2.3.4 [1.2.3.4] port 22.
[2024-02-13 14:41:28 (00:00:01.570626)] debug3: set_sock_tos: set socket 3 IP_TOS 0x10
[2024-02-13 14:41:28 (00:00:01.707927)] debug1: Connection established.
[2024-02-13 14:41:28 (00:00:01.708088)] debug1: identity file /tmp/aadsshcertwkuqc7gy/id_rsa type 0
[2024-02-13 14:41:28 (00:00:01.708565)] debug1: certificate file /tmp/aadsshcertwkuqc7gy/id_rsa.pub-aadcert.pub type 4
[2024-02-13 14:41:28 (00:00:01.708680)] debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
[2024-02-13 14:41:28 (00:00:01.745288)] debug1: Remote protocol version 2.0, remote software version OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
[2024-02-13 14:41:28 (00:00:01.745394)] debug1: compat_banner: match: OpenSSH_8.9p1 Ubuntu-3ubuntu0.6 pat OpenSSH* compat 0x04000000
[2024-02-13 14:41:28 (00:00:01.745410)] debug2: fd 3 setting O_NONBLOCK
[2024-02-13 14:41:28 (00:00:01.745418)] debug1: Authenticating to 1.2.3.4:22 as 'user@example.com'
[2024-02-13 14:41:28 (00:00:01.745667)] debug3: record_hostkey: found key type ED25519 in file /home/example/.ssh/known_hosts:25
[2024-02-13 14:41:28 (00:00:01.745751)] debug3: record_hostkey: found key type RSA in file /home/example/.ssh/known_hosts:26
[2024-02-13 14:41:28 (00:00:01.745834)] debug3: record_hostkey: found key type ECDSA in file /home/example/.ssh/known_hosts:27
[2024-02-13 14:41:28 (00:00:01.745859)] debug3: load_hostkeys_file: loaded 3 keys from 1.2.3.4
[2024-02-13 14:41:28 (00:00:01.745867)] debug1: load_hostkeys: fopen /home/example/.ssh/known_hosts2: No such file or directory
[2024-02-13 14:41:28 (00:00:01.745874)] debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
[2024-02-13 14:41:28 (00:00:01.745881)] debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
[2024-02-13 14:41:28 (00:00:01.745889)] debug3: order_hostkeyalgs: have matching best-preference key type ssh-ed25519-cert-v01@openssh.com, using HostkeyAlgorithms verbatim
[2024-02-13 14:41:28 (00:00:01.745897)] debug3: send packet: type 20
[2024-02-13 14:41:28 (00:00:01.745901)] debug1: SSH2_MSG_KEXINIT sent
[2024-02-13 14:41:28 (00:00:01.830207)] debug3: receive packet: type 20
[2024-02-13 14:41:28 (00:00:01.830376)] debug1: SSH2_MSG_KEXINIT received
[2024-02-13 14:41:28 (00:00:01.830436)] debug2: local client KEXINIT proposal
[2024-02-13 14:41:28 (00:00:01.830464)] debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,sntrup761x25519-sha512@openssh.com,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-c,kex-strict-c-v00@openssh.com
[2024-02-13 14:41:28 (00:00:01.830492)] debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,sk-ssh-ed25519-cert-v01@openssh.com,sk-ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ssh-ed25519@openssh.com,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-512,rsa-sha2-256
[2024-02-13 14:41:28 (00:00:01.830509)] debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2024-02-13 14:41:28 (00:00:01.830525)] debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2024-02-13 14:41:28 (00:00:01.830541)] debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:28 (00:00:01.830556)] debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:28 (00:00:01.830577)] debug2: compression ctos: none,zlib@openssh.com,zlib
[2024-02-13 14:41:28 (00:00:01.830592)] debug2: compression stoc: none,zlib@openssh.com,zlib
[2024-02-13 14:41:28 (00:00:01.830608)] debug2: languages ctos:
[2024-02-13 14:41:28 (00:00:01.830623)] debug2: languages stoc:
[2024-02-13 14:41:28 (00:00:01.830639)] debug2: first_kex_follows 0
[2024-02-13 14:41:28 (00:00:01.830656)] debug2: reserved 0
[2024-02-13 14:41:28 (00:00:01.830672)] debug2: peer server KEXINIT proposal
[2024-02-13 14:41:28 (00:00:01.830685)] debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,sntrup761x25519-sha512@openssh.com,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,kex-strict-s-v00@openssh.com
[2024-02-13 14:41:28 (00:00:01.830700)] debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519
[2024-02-13 14:41:28 (00:00:01.830712)] debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2024-02-13 14:41:28 (00:00:01.830727)] debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2024-02-13 14:41:28 (00:00:01.830742)] debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:28 (00:00:01.830761)] debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:28 (00:00:01.830775)] debug2: compression ctos: none,zlib@openssh.com
[2024-02-13 14:41:28 (00:00:01.830790)] debug2: compression stoc: none,zlib@openssh.com
[2024-02-13 14:41:28 (00:00:01.830804)] debug2: languages ctos:
[2024-02-13 14:41:28 (00:00:01.830817)] debug2: languages stoc:
[2024-02-13 14:41:28 (00:00:01.830831)] debug2: first_kex_follows 0
[2024-02-13 14:41:28 (00:00:01.830845)] debug2: reserved 0
[2024-02-13 14:41:28 (00:00:01.830859)] debug3: kex_choose_conf: will use strict KEX ordering
[2024-02-13 14:41:28 (00:00:01.830873)] debug1: kex: algorithm: curve25519-sha256
[2024-02-13 14:41:28 (00:00:01.830888)] debug1: kex: host key algorithm: ssh-ed25519
[2024-02-13 14:41:28 (00:00:01.830902)] debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: compression: none
[2024-02-13 14:41:28 (00:00:01.830917)] debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: compression: none
[2024-02-13 14:41:28 (00:00:01.834468)] debug3: send packet: type 30
[2024-02-13 14:41:28 (00:00:01.834553)] debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
[2024-02-13 14:41:28 (00:00:01.970279)] debug3: receive packet: type 31
[2024-02-13 14:41:28 (00:00:01.970350)] debug1: SSH2_MSG_KEX_ECDH_REPLY received
[2024-02-13 14:41:28 (00:00:01.970360)] debug1: Server host key: ssh-ed25519 SHA256:/+sPE/s8G+tWHHDlreMk5D5IlMTILJIsCep9dx5g
[2024-02-13 14:41:28 (00:00:01.970366)] debug3: record_hostkey: found key type ED25519 in file /home/example/.ssh/known_hosts:25
[2024-02-13 14:41:28 (00:00:01.970406)] debug3: record_hostkey: found key type RSA in file /home/example/.ssh/known_hosts:26
[2024-02-13 14:41:28 (00:00:01.970540)] debug3: record_hostkey: found key type ECDSA in file /home/example/.ssh/known_hosts:27
[2024-02-13 14:41:28 (00:00:01.970580)] debug3: load_hostkeys_file: loaded 3 keys from 1.2.3.4
[2024-02-13 14:41:28 (00:00:01.970593)] debug1: load_hostkeys: fopen /home/example/.ssh/known_hosts2: No such file or directory
[2024-02-13 14:41:28 (00:00:01.970600)] debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
[2024-02-13 14:41:28 (00:00:01.970606)] debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
[2024-02-13 14:41:28 (00:00:01.970612)] debug1: Host '1.2.3.4' is known and matches the ED25519 host key.
[2024-02-13 14:41:28 (00:00:01.970618)] debug1: Found key in /home/example/.ssh/known_hosts:25
[2024-02-13 14:41:28 (00:00:01.976400)] debug3: send packet: type 21
[2024-02-13 14:41:28 (00:00:01.976456)] debug1: ssh_packet_send2_wrapped: resetting send seqnr 3
[2024-02-13 14:41:28 (00:00:01.976464)] debug2: ssh_set_newkeys: mode 1
[2024-02-13 14:41:28 (00:00:01.976466)] debug1: rekey out after 134217728 blocks
[2024-02-13 14:41:28 (00:00:01.976469)] debug1: SSH2_MSG_NEWKEYS sent
[2024-02-13 14:41:28 (00:00:01.976473)] debug1: expecting SSH2_MSG_NEWKEYS
[2024-02-13 14:41:28 (00:00:01.976476)] debug3: receive packet: type 21
[2024-02-13 14:41:28 (00:00:01.976479)] debug1: ssh_packet_read_poll2: resetting read seqnr 3
[2024-02-13 14:41:28 (00:00:01.976482)] debug1: SSH2_MSG_NEWKEYS received
[2024-02-13 14:41:28 (00:00:01.976484)] debug2: ssh_set_newkeys: mode 0
[2024-02-13 14:41:28 (00:00:01.976487)] debug1: rekey in after 134217728 blocks
[2024-02-13 14:41:28 (00:00:01.976490)] debug1: Will attempt key: /tmp/aadsshcertwkuqc7gy/id_rsa.pub-aadcert.pub RSA-CERT SHA256:/amun9vc explicit
[2024-02-13 14:41:28 (00:00:01.976493)] debug1: Will attempt key: /tmp/aadsshcertwkuqc7gy/id_rsa RSA SHA256:/amun9vc explicit
[2024-02-13 14:41:28 (00:00:01.976495)] debug2: pubkey_prepare: done
[2024-02-13 14:41:28 (00:00:01.976498)] debug3: send packet: type 5
[2024-02-13 14:41:28 (00:00:01.976501)] debug3: receive packet: type 7
[2024-02-13 14:41:28 (00:00:01.976504)] debug1: SSH2_MSG_EXT_INFO received
[2024-02-13 14:41:28 (00:00:01.976507)] debug1: kex_input_ext_info: server-sig-algs=
[2024-02-13 14:41:28 (00:00:01.976510)] debug1: kex_input_ext_info: publickey-hostbound@openssh.com=<0>
[2024-02-13 14:41:28 (00:00:02.189683)] debug3: receive packet: type 6
[2024-02-13 14:41:28 (00:00:02.189828)] debug2: service_accept: ssh-userauth
[2024-02-13 14:41:28 (00:00:02.189853)] debug1: SSH2_MSG_SERVICE_ACCEPT received
[2024-02-13 14:41:28 (00:00:02.189863)] debug3: send packet: type 50
[2024-02-13 14:41:28 (00:00:02.222375)] debug3: receive packet: type 51
[2024-02-13 14:41:28 (00:00:02.222463)] debug1: Authentications that can continue: publickey
[2024-02-13 14:41:28 (00:00:02.222475)] debug3: start over, passed a different list publickey
[2024-02-13 14:41:28 (00:00:02.222488)] debug3: preferred gssapi-with-mic,publickey,keyboard-interactive,password
[2024-02-13 14:41:28 (00:00:02.222491)] debug3: authmethod_lookup publickey
[2024-02-13 14:41:28 (00:00:02.222493)] debug3: remaining preferred: keyboard-interactive,password
[2024-02-13 14:41:28 (00:00:02.222496)] debug3: authmethod_is_enabled publickey
[2024-02-13 14:41:28 (00:00:02.222499)] debug1: Next authentication method: publickey
[2024-02-13 14:41:28 (00:00:02.222501)] debug1: Offering public key: /tmp/aadsshcertwkuqc7gy/id_rsa.pub-aadcert.pub RSA-CERT SHA256:/amun9vc explicit
[2024-02-13 14:41:28 (00:00:02.222504)] debug3: send packet: type 50
[2024-02-13 14:41:28 (00:00:02.222507)] debug2: we sent a publickey packet, wait for reply
[2024-02-13 14:41:28 (00:00:02.307577)] debug3: receive packet: type 60
[2024-02-13 14:41:28 (00:00:02.307709)] debug1: Server accepts key: /tmp/aadsshcertwkuqc7gy/id_rsa.pub-aadcert.pub RSA-CERT SHA256:/amun9vc explicit
[2024-02-13 14:41:28 (00:00:02.307732)] debug3: sign_and_send_pubkey: using publickey-hostbound-v00@openssh.com with RSA-CERT SHA256:/amun9vc
[2024-02-13 14:41:28 (00:00:02.307740)] debug2: sign_and_send_pubkey: using private key "/tmp/aadsshcertwkuqc7gy/id_rsa" for certificate
[2024-02-13 14:41:28 (00:00:02.307748)] debug3: sign_and_send_pubkey: signing using rsa-sha2-512-cert-v01@openssh.com SHA256:/amun9vc
[2024-02-13 14:41:28 (00:00:02.311247)] debug3: send packet: type 50
[2024-02-13 14:41:29 (00:00:02.427500)] debug3: receive packet: type 52
[2024-02-13 14:41:29 (00:00:02.427646)] Authenticated to 1.2.3.4 ([1.2.3.4]:22) using "publickey".
[2024-02-13 14:41:29 (00:00:02.427672)] debug1: setting up multiplex master socket
[2024-02-13 14:41:29 (00:00:02.427682)] debug3: muxserver_listen: temporary control path /home/example/controlpath.NUb1qJ8zoQl7WGsp
[2024-02-13 14:41:29 (00:00:02.427695)] debug2: fd 4 setting O_NONBLOCK
[2024-02-13 14:41:29 (00:00:02.427704)] debug3: fd 4 is O_NONBLOCK
[2024-02-13 14:41:29 (00:00:02.427713)] debug3: fd 4 is O_NONBLOCK
[2024-02-13 14:41:29 (00:00:02.427721)] debug1: channel 0: new [/home/example/controlpath]
[2024-02-13 14:41:29 (00:00:02.427730)] debug3: muxserver_listen: mux listener channel 0 fd 4
[2024-02-13 14:41:29 (00:00:02.427738)] debug2: fd 3 setting TCP_NODELAY
[2024-02-13 14:41:29 (00:00:02.427746)] debug3: set_sock_tos: set socket 3 IP_TOS 0x08
[2024-02-13 14:41:29 (00:00:02.427755)] debug1: control_persist_detach: backgrounding master process
[2024-02-13 14:41:29 (00:00:02.427910)] debug2: control_persist_detach: background process is 19616
[2024-02-13 14:41:29 (00:00:02.427957)] debug2: fd 4 setting O_NONBLOCK
[2024-02-13 14:41:29 (00:00:02.428606)] debug1: forking to background
[2024-02-13 14:41:29 (00:00:02.429418)] debug1: Entering interactive session.
[2024-02-13 14:41:29 (00:00:02.429528)] debug1: pledge: id
[2024-02-13 14:41:29 (00:00:02.429555)] debug2: set_control_persist_exit_time: schedule exit in 15 seconds
[2024-02-13 14:41:29 (00:00:02.429565)] debug1: multiplexing control connection
[2024-02-13 14:41:29 (00:00:02.429574)] debug2: fd 5 setting O_NONBLOCK
[2024-02-13 14:41:29 (00:00:02.429582)] debug3: fd 5 is O_NONBLOCK
[2024-02-13 14:41:29 (00:00:02.429591)] debug1: channel 1: new [mux-control]
[2024-02-13 14:41:29 (00:00:02.429601)] debug3: channel_post_mux_listener: new mux channel 1 fd 5
[2024-02-13 14:41:29 (00:00:02.429609)] debug3: mux_master_read_cb: channel 1: hello sent
[2024-02-13 14:41:29 (00:00:02.429620)] debug2: set_control_persist_exit_time: cancel scheduled exit
[2024-02-13 14:41:29 (00:00:02.429655)] debug3: mux_master_read_cb: channel 1 packet type 0x00000001 len 4
[2024-02-13 14:41:29 (00:00:02.429665)] debug2: mux_master_process_hello: channel 1 client version 4
[2024-02-13 14:41:29 (00:00:02.429919)] debug2: mux_client_hello_exchange: master version 4
[2024-02-13 14:41:29 (00:00:02.429976)] debug3: mux_client_forwards: request forwardings: 0 local, 0 remote
[2024-02-13 14:41:29 (00:00:02.429996)] debug3: mux_client_request_session: entering
[2024-02-13 14:41:29 (00:00:02.430012)] debug3: mux_client_request_alive: entering
[2024-02-13 14:41:29 (00:00:02.430029)] debug3: mux_master_read_cb: channel 1 packet type 0x10000004 len 4
[2024-02-13 14:41:29 (00:00:02.430043)] debug2: mux_master_process_alive_check: channel 1: alive check
[2024-02-13 14:41:29 (00:00:02.430199)] debug3: mux_client_request_alive: done pid = 19618
[2024-02-13 14:41:29 (00:00:02.430262)] debug3: mux_client_request_session: session request sent
[2024-02-13 14:41:29 (00:00:02.430328)] debug3: mux_master_read_cb: channel 1 packet type 0x10000002 len 70
[2024-02-13 14:41:29 (00:00:02.430348)] debug2: mux_master_process_new_session: channel 1: request tty 0, X 0, agent 0, subsys 0, term "xterm-256color", cmd "exit", env 1
[2024-02-13 14:41:29 (00:00:02.430360)] debug3: mux_master_process_new_session: got fds stdin 6, stdout 7, stderr 8
[2024-02-13 14:41:29 (00:00:02.430370)] debug1: channel 2: new [client-session]
[2024-02-13 14:41:29 (00:00:02.430380)] debug2: mux_master_process_new_session: channel_new: 2 linked to control channel 1
[2024-02-13 14:41:29 (00:00:02.430389)] debug2: channel 2: send open
[2024-02-13 14:41:29 (00:00:02.430398)] debug3: send packet: type 90
[2024-02-13 14:41:29 (00:00:03.040888)] debug3: receive packet: type 80
[2024-02-13 14:41:29 (00:00:03.040980)] debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
[2024-02-13 14:41:29 (00:00:03.040995)] debug3: client_input_hostkeys: received RSA key SHA256:/x35FolY
[2024-02-13 14:41:29 (00:00:03.041082)] debug3: client_input_hostkeys: received ECDSA key SHA256:
[2024-02-13 14:41:29 (00:00:03.041108)] debug3: client_input_hostkeys: received ED25519 key SHA256:/+sPE/s8G+tWHHDlreMk5D5IlMTILJIsCep9dx5g
[2024-02-13 14:41:29 (00:00:03.041114)] debug1: client_input_hostkeys: searching /home/example/.ssh/known_hosts for 1.2.3.4 / (none)
[2024-02-13 14:41:29 (00:00:03.041121)] debug3: hostkeys_foreach: reading file "/home/example/.ssh/known_hosts"
[2024-02-13 14:41:29 (00:00:03.043949)] debug3: hostkeys_find: found ssh-ed25519 key at /home/example/.ssh/known_hosts:25
[2024-02-13 14:41:29 (00:00:03.044015)] debug3: hostkeys_find: found ssh-rsa key at /home/example/.ssh/known_hosts:26
[2024-02-13 14:41:29 (00:00:03.044032)] debug3: hostkeys_find: found ecdsa-sha2-nistp256 key at /home/example/.ssh/known_hosts:27
[2024-02-13 14:41:29 (00:00:03.044038)] debug1: client_input_hostkeys: searching /home/example/.ssh/known_hosts2 for 1.2.3.4 / (none)
[2024-02-13 14:41:29 (00:00:03.044043)] debug1: client_input_hostkeys: hostkeys file /home/example/.ssh/known_hosts2 does not exist
[2024-02-13 14:41:29 (00:00:03.044048)] debug3: client_input_hostkeys: 3 server keys: 0 new, 3 retained, 0 incomplete match. 0 to remove
[2024-02-13 14:41:29 (00:00:03.044053)] debug1: client_input_hostkeys: no new or deprecated keys from server
[2024-02-13 14:41:29 (00:00:03.044057)] debug3: receive packet: type 4
[2024-02-13 14:41:29 (00:00:03.044062)] debug1: Remote: /usr/sbin/aad_certhandler %u %k:1: key options: agent-forwarding port-forwarding principals pty user-rc x11-forwarding
[2024-02-13 14:41:29 (00:00:03.108931)] debug3: receive packet: type 4
[2024-02-13 14:41:29 (00:00:03.109075)] debug1: Remote: /usr/sbin/aad_certhandler %u %k:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
[2024-02-13 14:41:29 (00:00:03.109106)] debug3: receive packet: type 4
[2024-02-13 14:41:29 (00:00:03.109121)] debug1: Remote: /usr/sbin/aad_certhandler %u %k:1: key options: agent-forwarding port-forwarding principals pty user-rc x11-forwarding
[2024-02-13 14:41:29 (00:00:03.109134)] debug3: receive packet: type 4
[2024-02-13 14:41:29 (00:00:03.109145)] debug1: Remote: /usr/sbin/aad_certhandler %u %k:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
[2024-02-13 14:41:29 (00:00:03.109157)] debug3: receive packet: type 91
[2024-02-13 14:41:29 (00:00:03.109169)] debug2: channel_input_open_confirmation: channel 2: callback start
[2024-02-13 14:41:29 (00:00:03.109181)] debug2: client_session2_setup: id 2
[2024-02-13 14:41:29 (00:00:03.109193)] debug1: Sending environment.
[2024-02-13 14:41:29 (00:00:03.109205)] debug1: channel 2: setting env LANG = "C.UTF-8"
[2024-02-13 14:41:29 (00:00:03.109217)] debug2: channel 2: request env confirm 0
[2024-02-13 14:41:29 (00:00:03.109229)] debug3: send packet: type 98
[2024-02-13 14:41:29 (00:00:03.109240)] debug1: Sending command: exit
[2024-02-13 14:41:29 (00:00:03.109248)] debug2: channel 2: request exec confirm 1
[2024-02-13 14:41:29 (00:00:03.109255)] debug3: send packet: type 98
[2024-02-13 14:41:29 (00:00:03.109262)] debug3: mux_session_confirm: sending success reply
[2024-02-13 14:41:29 (00:00:03.109269)] debug2: channel_input_open_confirmation: channel 2: callback done
[2024-02-13 14:41:29 (00:00:03.109276)] debug2: channel 2: open confirm rwindow 0 rmax 32768
[2024-02-13 14:41:29 (00:00:03.109283)] debug1: mux_client_request_session: master session id: 2
[2024-02-13 14:41:29 (00:00:03.253792)] debug2: channel 2: rcvd adjust 2097152
[2024-02-13 14:41:29 (00:00:03.253859)] debug3: receive packet: type 99
[2024-02-13 14:41:29 (00:00:03.253866)] debug2: channel_input_status_confirm: type 99 id 2
[2024-02-13 14:41:29 (00:00:03.253869)] debug2: exec request accepted on channel 2
[2024-02-13 14:41:29 (00:00:03.253872)] debug3: receive packet: type 96
[2024-02-13 14:41:29 (00:00:03.253875)] debug2: channel 2: rcvd eof
[2024-02-13 14:41:29 (00:00:03.253878)] debug2: channel 2: output open -> drain
[2024-02-13 14:41:29 (00:00:03.253880)] debug2: channel 2: obuf empty
[2024-02-13 14:41:29 (00:00:03.253883)] debug2: chan_shutdown_write: channel 2: (i0 o1 sock -1 wfd 7 efd 8 [write])
[2024-02-13 14:41:29 (00:00:03.253886)] debug2: channel 2: output drain -> closed
[2024-02-13 14:41:29 (00:00:03.253889)] debug3: receive packet: type 98
[2024-02-13 14:41:29 (00:00:03.253891)] debug1: client_input_channel_req: channel 2 rtype exit-status reply 0
[2024-02-13 14:41:29 (00:00:03.253894)] debug3: mux_exit_message: channel 2: exit message, exitval 0
[2024-02-13 14:41:29 (00:00:03.253897)] debug3: receive packet: type 98
[2024-02-13 14:41:29 (00:00:03.253899)] debug1: client_input_channel_req: channel 2 rtype eow@openssh.com reply 0
[2024-02-13 14:41:29 (00:00:03.253902)] debug2: channel 2: rcvd eow
[2024-02-13 14:41:29 (00:00:03.253905)] debug2: chan_shutdown_read: channel 2: (i0 o3 sock -1 wfd 6 efd 8 [write])
[2024-02-13 14:41:29 (00:00:03.253907)] debug2: channel 2: input open -> closed
[2024-02-13 14:41:29 (00:00:03.253910)] debug3: receive packet: type 97
[2024-02-13 14:41:29 (00:00:03.253913)] debug2: channel 2: rcvd close
[2024-02-13 14:41:29 (00:00:03.253916)] debug3: channel 2: will not send data after close
[2024-02-13 14:41:29 (00:00:03.253918)] debug2: channel 2: send close
[2024-02-13 14:41:29 (00:00:03.253922)] debug3: send packet: type 97
[2024-02-13 14:41:29 (00:00:03.253927)] debug2: channel 2: is dead
[2024-02-13 14:41:29 (00:00:03.253931)] debug2: channel 2: gc: notify user
[2024-02-13 14:41:29 (00:00:03.253936)] debug3: mux_master_session_cleanup_cb: entering for channel 2
[2024-02-13 14:41:29 (00:00:03.253940)] debug2: channel 1: rcvd close
[2024-02-13 14:41:29 (00:00:03.253944)] debug2: channel 1: output open -> drain
[2024-02-13 14:41:29 (00:00:03.253948)] debug2: chan_shutdown_read: channel 1: (i0 o1 sock 5 wfd 5 efd -1 [closed])
[2024-02-13 14:41:29 (00:00:03.253952)] debug2: channel 1: input open -> closed
[2024-02-13 14:41:29 (00:00:03.253957)] debug2: channel 2: gc: user detached
[2024-02-13 14:41:29 (00:00:03.253961)] debug2: channel 2: is dead
[2024-02-13 14:41:29 (00:00:03.253965)] debug2: channel 2: garbage collecting
[2024-02-13 14:41:29 (00:00:03.253970)] debug1: channel 2: free: client-session, nchannels 3
[2024-02-13 14:41:29 (00:00:03.253977)] debug3: channel 2: status: The following connections are open:
[2024-02-13 14:41:29 (00:00:03.253981)] #1 mux-control (t16 nr0 i3/0 o1/16 e[closed]/0 fd 5/5/-1 sock 5 cc -1 io 0x03/0x00)
[2024-02-13 14:41:29 (00:00:03.253990)] #2 client-session (t4 r0 i3/0 o3/0 e[write]/0 fd -1/-1/8 sock -1 cc -1 io 0x00/0x00)
[2024-02-13 14:41:29 (00:00:03.253994)]
[2024-02-13 14:41:29 (00:00:03.253998)] debug2: channel 1: obuf empty
[2024-02-13 14:41:29 (00:00:03.254003)] debug2: chan_shutdown_write: channel 1: (i3 o1 sock 5 wfd 5 efd -1 [closed])
[2024-02-13 14:41:29 (00:00:03.254007)] debug2: channel 1: output drain -> closed
[2024-02-13 14:41:29 (00:00:03.254011)] debug2: channel 1: is dead (local)
[2024-02-13 14:41:29 (00:00:03.254015)] debug2: channel 1: gc: notify user
[2024-02-13 14:41:29 (00:00:03.254021)] debug3: mux_master_control_cleanup_cb: entering for channel 1
[2024-02-13 14:41:29 (00:00:03.254027)] debug2: channel 1: gc: user detached
[2024-02-13 14:41:29 (00:00:03.254034)] debug2: channel 1: is dead (local)
[2024-02-13 14:41:29 (00:00:03.254040)] debug2: channel 1: garbage collecting
[2024-02-13 14:41:29 (00:00:03.254047)] debug1: channel 1: free: mux-control, nchannels 2
[2024-02-13 14:41:29 (00:00:03.254052)] debug3: channel 1: status: The following connections are open:
[2024-02-13 14:41:29 (00:00:03.254059)] #1 mux-control (t16 nr0 i3/0 o3/0 e[closed]/0 fd 5/5/-1 sock 5 cc -1 io 0x00/0x03)
[2024-02-13 14:41:29 (00:00:03.254069)]
[2024-02-13 14:41:29 (00:00:03.254079)] debug2: set_control_persist_exit_time: schedule exit in 15 seconds
[2024-02-13 14:41:29 (00:00:03.254085)] debug3: mux_client_read_packet: read header failed: Broken pipe
[2024-02-13 14:41:29 (00:00:03.254093)] debug2: Received exit status from master 0
[2024-02-13 14:41:44 (00:00:18.269254)] debug1: ControlPersist timeout expired
[2024-02-13 14:41:44 (00:00:18.269389)] debug3: send packet: type 1
[2024-02-13 14:41:44 (00:00:18.269408)] debug1: channel 0: free: /home/example/controlpath, nchannels 1
[2024-02-13 14:41:44 (00:00:18.269415)] debug3: channel 0: status: The following connections are open:
[2024-02-13 14:41:44 (00:00:18.269422)]
[2024-02-13 14:41:44 (00:00:18.269428)] Transferred: sent 5604, received 4588 bytes, in 15.8 seconds
[2024-02-13 14:41:44 (00:00:18.269435)] Bytes per second: sent 353.8, received 289.7
[2024-02-13 14:41:44 (00:00:18.269441)] debug1: Exit status -1
❯ az ssh vm --ip 1.2.3.4 -- -vvv -o ControlMaster=auto -o ControlPath=/home/example/controlpath -o ControlPersist=60s exit 2>&1 | ts -s '(%H:%M:%.S)]' | ts '[%Y-%m-%d %H:%M:%S'
[2024-02-13 14:41:58 (00:00:00.997196)] OpenSSH_8.9p1 Ubuntu-3ubuntu0.6, OpenSSL 3.0.2 15 Mar 2022
[2024-02-13 14:41:58 (00:00:00.997283)] debug1: Reading configuration data /etc/ssh/ssh_config
[2024-02-13 14:41:58 (00:00:00.997297)] debug1: /etc/ssh/ssh_config line 19: include /etc/ssh/ssh_config.d/*.conf matched no files
[2024-02-13 14:41:58 (00:00:00.997308)] debug1: /etc/ssh/ssh_config line 21: Applying options for *
[2024-02-13 14:41:58 (00:00:00.997313)] debug2: resolve_canonicalize: hostname 1.2.3.4 is address
[2024-02-13 14:41:58 (00:00:00.997505)] debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/home/example/.ssh/known_hosts'
[2024-02-13 14:41:58 (00:00:00.997543)] debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/home/example/.ssh/known_hosts2'
[2024-02-13 14:41:58 (00:00:00.997552)] debug1: auto-mux: Trying existing master
[2024-02-13 14:41:58 (00:00:00.997555)] debug1: Control socket "/home/example/controlpath" does not exist
[2024-02-13 14:41:58 (00:00:00.997558)] debug3: ssh_connect_direct: entering
[2024-02-13 14:41:58 (00:00:00.997560)] debug1: Connecting to 1.2.3.4 [1.2.3.4] port 22.
[2024-02-13 14:41:58 (00:00:00.997563)] debug3: set_sock_tos: set socket 3 IP_TOS 0x10
[2024-02-13 14:41:58 (00:00:01.041924)] debug1: Connection established.
[2024-02-13 14:41:58 (00:00:01.042009)] debug1: identity file /tmp/aadsshcertit8omp_9/id_rsa type 0
[2024-02-13 14:41:58 (00:00:01.042136)] debug1: certificate file /tmp/aadsshcertit8omp_9/id_rsa.pub-aadcert.pub type 4
[2024-02-13 14:41:58 (00:00:01.042160)] debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
[2024-02-13 14:41:58 (00:00:01.076729)] debug1: Remote protocol version 2.0, remote software version OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
[2024-02-13 14:41:58 (00:00:01.076820)] debug1: compat_banner: match: OpenSSH_8.9p1 Ubuntu-3ubuntu0.6 pat OpenSSH* compat 0x04000000
[2024-02-13 14:41:58 (00:00:01.076830)] debug2: fd 3 setting O_NONBLOCK
[2024-02-13 14:41:58 (00:00:01.076853)] debug1: Authenticating to 1.2.3.4:22 as 'user@example.com'
[2024-02-13 14:41:58 (00:00:01.076862)] debug3: record_hostkey: found key type ED25519 in file /home/example/.ssh/known_hosts:25
[2024-02-13 14:41:58 (00:00:01.076867)] debug3: record_hostkey: found key type RSA in file /home/example/.ssh/known_hosts:26
[2024-02-13 14:41:58 (00:00:01.076871)] debug3: record_hostkey: found key type ECDSA in file /home/example/.ssh/known_hosts:27
[2024-02-13 14:41:58 (00:00:01.076874)] debug3: load_hostkeys_file: loaded 3 keys from 1.2.3.4
[2024-02-13 14:41:58 (00:00:01.076879)] debug1: load_hostkeys: fopen /home/example/.ssh/known_hosts2: No such file or directory
[2024-02-13 14:41:58 (00:00:01.076883)] debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
[2024-02-13 14:41:58 (00:00:01.076887)] debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
[2024-02-13 14:41:58 (00:00:01.076891)] debug3: order_hostkeyalgs: have matching best-preference key type ssh-ed25519-cert-v01@openssh.com, using HostkeyAlgorithms verbatim
[2024-02-13 14:41:58 (00:00:01.076897)] debug3: send packet: type 20
[2024-02-13 14:41:58 (00:00:01.076904)] debug1: SSH2_MSG_KEXINIT sent
[2024-02-13 14:41:58 (00:00:01.118369)] debug3: receive packet: type 20
[2024-02-13 14:41:58 (00:00:01.118435)] debug1: SSH2_MSG_KEXINIT received
[2024-02-13 14:41:58 (00:00:01.118442)] debug2: local client KEXINIT proposal
[2024-02-13 14:41:58 (00:00:01.118446)] debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,sntrup761x25519-sha512@openssh.com,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-c,kex-strict-c-v00@openssh.com
[2024-02-13 14:41:58 (00:00:01.118453)] debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,sk-ssh-ed25519-cert-v01@openssh.com,sk-ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ssh-ed25519@openssh.com,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-512,rsa-sha2-256
[2024-02-13 14:41:58 (00:00:01.118457)] debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2024-02-13 14:41:58 (00:00:01.118460)] debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2024-02-13 14:41:58 (00:00:01.118464)] debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:58 (00:00:01.118467)] debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:58 (00:00:01.118470)] debug2: compression ctos: none,zlib@openssh.com,zlib
[2024-02-13 14:41:58 (00:00:01.118473)] debug2: compression stoc: none,zlib@openssh.com,zlib
[2024-02-13 14:41:58 (00:00:01.118476)] debug2: languages ctos:
[2024-02-13 14:41:58 (00:00:01.118479)] debug2: languages stoc:
[2024-02-13 14:41:58 (00:00:01.118482)] debug2: first_kex_follows 0
[2024-02-13 14:41:58 (00:00:01.118485)] debug2: reserved 0
[2024-02-13 14:41:58 (00:00:01.118488)] debug2: peer server KEXINIT proposal
[2024-02-13 14:41:58 (00:00:01.118491)] debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,sntrup761x25519-sha512@openssh.com,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,kex-strict-s-v00@openssh.com
[2024-02-13 14:41:58 (00:00:01.118494)] debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519
[2024-02-13 14:41:58 (00:00:01.118497)] debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2024-02-13 14:41:58 (00:00:01.118500)] debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2024-02-13 14:41:58 (00:00:01.118503)] debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:58 (00:00:01.118506)] debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:58 (00:00:01.118509)] debug2: compression ctos: none,zlib@openssh.com
[2024-02-13 14:41:58 (00:00:01.118512)] debug2: compression stoc: none,zlib@openssh.com
[2024-02-13 14:41:58 (00:00:01.118515)] debug2: languages ctos:
[2024-02-13 14:41:58 (00:00:01.118518)] debug2: languages stoc:
[2024-02-13 14:41:58 (00:00:01.118521)] debug2: first_kex_follows 0
[2024-02-13 14:41:58 (00:00:01.118524)] debug2: reserved 0
[2024-02-13 14:41:58 (00:00:01.118527)] debug3: kex_choose_conf: will use strict KEX ordering
[2024-02-13 14:41:58 (00:00:01.118530)] debug1: kex: algorithm: curve25519-sha256
[2024-02-13 14:41:58 (00:00:01.118534)] debug1: kex: host key algorithm: ssh-ed25519
[2024-02-13 14:41:58 (00:00:01.118537)] debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: compression: none
[2024-02-13 14:41:58 (00:00:01.118540)] debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: compression: none
[2024-02-13 14:41:58 (00:00:01.120339)] debug3: send packet: type 30
[2024-02-13 14:41:58 (00:00:01.120455)] debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
[2024-02-13 14:41:58 (00:00:01.217792)] debug3: receive packet: type 31
[2024-02-13 14:41:58 (00:00:01.217937)] debug1: SSH2_MSG_KEX_ECDH_REPLY received
[2024-02-13 14:41:58 (00:00:01.217963)] debug1: Server host key: ssh-ed25519 SHA256:/+sPE/s8G+tWHHDlreMk5D5IlMTILJIsCep9dx5g
[2024-02-13 14:41:58 (00:00:01.217978)] debug3: record_hostkey: found key type ED25519 in file /home/example/.ssh/known_hosts:25
[2024-02-13 14:41:58 (00:00:01.217987)] debug3: record_hostkey: found key type RSA in file /home/example/.ssh/known_hosts:26
[2024-02-13 14:41:58 (00:00:01.218434)] debug3: record_hostkey: found key type ECDSA in file /home/example/.ssh/known_hosts:27
[2024-02-13 14:41:58 (00:00:01.218550)] debug3: load_hostkeys_file: loaded 3 keys from 1.2.3.4
[2024-02-13 14:41:58 (00:00:01.218575)] debug1: load_hostkeys: fopen /home/example/.ssh/known_hosts2: No such file or directory
[2024-02-13 14:41:58 (00:00:01.218585)] debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
[2024-02-13 14:41:58 (00:00:01.218594)] debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
[2024-02-13 14:41:58 (00:00:01.218602)] debug1: Host '1.2.3.4' is known and matches the ED25519 host key.
[2024-02-13 14:41:58 (00:00:01.218611)] debug1: Found key in /home/example/.ssh/known_hosts:25
[2024-02-13 14:41:58 (00:00:01.225878)] debug3: send packet: type 21
[2024-02-13 14:41:58 (00:00:01.225972)] debug1: ssh_packet_send2_wrapped: resetting send seqnr 3
[2024-02-13 14:41:58 (00:00:01.225980)] debug2: ssh_set_newkeys: mode 1
[2024-02-13 14:41:58 (00:00:01.225982)] debug1: rekey out after 134217728 blocks
[2024-02-13 14:41:58 (00:00:01.225985)] debug1: SSH2_MSG_NEWKEYS sent
[2024-02-13 14:41:58 (00:00:01.225987)] debug1: expecting SSH2_MSG_NEWKEYS
[2024-02-13 14:41:58 (00:00:01.225990)] debug3: receive packet: type 21
[2024-02-13 14:41:58 (00:00:01.225992)] debug1: ssh_packet_read_poll2: resetting read seqnr 3
[2024-02-13 14:41:58 (00:00:01.225994)] debug1: SSH2_MSG_NEWKEYS received
[2024-02-13 14:41:58 (00:00:01.225997)] debug2: ssh_set_newkeys: mode 0
[2024-02-13 14:41:58 (00:00:01.225999)] debug1: rekey in after 134217728 blocks
[2024-02-13 14:41:58 (00:00:01.226002)] debug1: Will attempt key: /tmp/aadsshcertit8omp_9/id_rsa.pub-aadcert.pub RSA-CERT SHA256: explicit
[2024-02-13 14:41:58 (00:00:01.226004)] debug1: Will attempt key: /tmp/aadsshcertit8omp_9/id_rsa RSA SHA256: explicit
[2024-02-13 14:41:58 (00:00:01.226006)] debug2: pubkey_prepare: done
[2024-02-13 14:41:58 (00:00:01.226009)] debug3: send packet: type 5
[2024-02-13 14:41:58 (00:00:01.226014)] debug3: receive packet: type 7
[2024-02-13 14:41:58 (00:00:01.226016)] debug1: SSH2_MSG_EXT_INFO received
[2024-02-13 14:41:58 (00:00:01.226019)] debug1: kex_input_ext_info: server-sig-algs=
[2024-02-13 14:41:58 (00:00:01.226022)] debug1: kex_input_ext_info: publickey-hostbound@openssh.com=<0>
[2024-02-13 14:41:58 (00:00:01.440643)] debug3: receive packet: type 6
[2024-02-13 14:41:58 (00:00:01.440738)] debug2: service_accept: ssh-userauth
[2024-02-13 14:41:58 (00:00:01.440754)] debug1: SSH2_MSG_SERVICE_ACCEPT received
[2024-02-13 14:41:58 (00:00:01.440760)] debug3: send packet: type 50
[2024-02-13 14:41:58 (00:00:01.475483)] debug3: receive packet: type 51
[2024-02-13 14:41:58 (00:00:01.475555)] debug1: Authentications that can continue: publickey
[2024-02-13 14:41:58 (00:00:01.475566)] debug3: start over, passed a different list publickey
[2024-02-13 14:41:58 (00:00:01.475569)] debug3: preferred gssapi-with-mic,publickey,keyboard-interactive,password
[2024-02-13 14:41:58 (00:00:01.475573)] debug3: authmethod_lookup publickey
[2024-02-13 14:41:58 (00:00:01.475576)] debug3: remaining preferred: keyboard-interactive,password
[2024-02-13 14:41:58 (00:00:01.475579)] debug3: authmethod_is_enabled publickey
[2024-02-13 14:41:58 (00:00:01.475583)] debug1: Next authentication method: publickey
[2024-02-13 14:41:58 (00:00:01.475586)] debug1: Offering public key: /tmp/aadsshcertit8omp_9/id_rsa.pub-aadcert.pub RSA-CERT SHA256: explicit
[2024-02-13 14:41:58 (00:00:01.475589)] debug3: send packet: type 50
[2024-02-13 14:41:58 (00:00:01.475594)] debug2: we sent a publickey packet, wait for reply
[2024-02-13 14:41:58 (00:00:01.586975)] debug3: receive packet: type 60
[2024-02-13 14:41:58 (00:00:01.587042)] debug1: Server accepts key: /tmp/aadsshcertit8omp_9/id_rsa.pub-aadcert.pub RSA-CERT SHA256: explicit
[2024-02-13 14:41:58 (00:00:01.587066)] debug3: sign_and_send_pubkey: using publickey-hostbound-v00@openssh.com with RSA-CERT SHA256:
[2024-02-13 14:41:58 (00:00:01.587069)] debug2: sign_and_send_pubkey: using private key "/tmp/aadsshcertit8omp_9/id_rsa" for certificate
[2024-02-13 14:41:58 (00:00:01.587072)] debug3: sign_and_send_pubkey: signing using rsa-sha2-512-cert-v01@openssh.com SHA256:
[2024-02-13 14:41:58 (00:00:01.589574)] debug3: send packet: type 50
[2024-02-13 14:41:59 (00:00:01.738777)] debug3: receive packet: type 52
[2024-02-13 14:41:59 (00:00:01.738868)] Authenticated to 1.2.3.4 ([1.2.3.4]:22) using "publickey".
[2024-02-13 14:41:59 (00:00:01.738883)] debug1: setting up multiplex master socket
[2024-02-13 14:41:59 (00:00:01.738889)] debug3: muxserver_listen: temporary control path /home/example/controlpath.TwfHHGhDFlQfOLsl
[2024-02-13 14:41:59 (00:00:01.738896)] debug2: fd 4 setting O_NONBLOCK
[2024-02-13 14:41:59 (00:00:01.738900)] debug3: fd 4 is O_NONBLOCK
[2024-02-13 14:41:59 (00:00:01.738905)] debug3: fd 4 is O_NONBLOCK
[2024-02-13 14:41:59 (00:00:01.738910)] debug1: channel 0: new [/home/example/controlpath]
[2024-02-13 14:41:59 (00:00:01.738915)] debug3: muxserver_listen: mux listener channel 0 fd 4
[2024-02-13 14:41:59 (00:00:01.738919)] debug2: fd 3 setting TCP_NODELAY
[2024-02-13 14:41:59 (00:00:01.738924)] debug3: set_sock_tos: set socket 3 IP_TOS 0x08
[2024-02-13 14:41:59 (00:00:01.738928)] debug1: control_persist_detach: backgrounding master process
[2024-02-13 14:41:59 (00:00:01.739042)] debug2: control_persist_detach: background process is 19639
[2024-02-13 14:41:59 (00:00:01.739077)] debug2: fd 4 setting O_NONBLOCK
[2024-02-13 14:41:59 (00:00:01.739430)] debug1: forking to background
[2024-02-13 14:41:59 (00:00:01.739713)] debug1: Entering interactive session.
[2024-02-13 14:41:59 (00:00:01.739760)] debug1: pledge: id
[2024-02-13 14:41:59 (00:00:01.739841)] debug2: set_control_persist_exit_time: schedule exit in 60 seconds
[2024-02-13 14:41:59 (00:00:01.739869)] debug1: multiplexing control connection
[2024-02-13 14:41:59 (00:00:01.739880)] debug2: fd 5 setting O_NONBLOCK
[2024-02-13 14:41:59 (00:00:01.739887)] debug3: fd 5 is O_NONBLOCK
[2024-02-13 14:41:59 (00:00:01.739895)] debug1: channel 1: new [mux-control]
[2024-02-13 14:41:59 (00:00:01.739902)] debug3: channel_post_mux_listener: new mux channel 1 fd 5
[2024-02-13 14:41:59 (00:00:01.739911)] debug3: mux_master_read_cb: channel 1: hello sent
[2024-02-13 14:41:59 (00:00:01.739920)] debug2: set_control_persist_exit_time: cancel scheduled exit
[2024-02-13 14:41:59 (00:00:01.740007)] debug3: mux_master_read_cb: channel 1 packet type 0x00000001 len 4
[2024-02-13 14:41:59 (00:00:01.740042)] debug2: mux_master_process_hello: channel 1 client version 4
[2024-02-13 14:41:59 (00:00:01.740055)] debug2: mux_client_hello_exchange: master version 4
[2024-02-13 14:41:59 (00:00:01.740063)] debug3: mux_client_forwards: request forwardings: 0 local, 0 remote
[2024-02-13 14:41:59 (00:00:01.740071)] debug3: mux_client_request_session: entering
[2024-02-13 14:41:59 (00:00:01.740079)] debug3: mux_client_request_alive: entering
[2024-02-13 14:41:59 (00:00:01.740145)] debug3: mux_master_read_cb: channel 1 packet type 0x10000004 len 4
[2024-02-13 14:41:59 (00:00:01.740170)] debug2: mux_master_process_alive_check: channel 1: alive check
[2024-02-13 14:41:59 (00:00:01.740326)] debug3: mux_client_request_alive: done pid = 19641
[2024-02-13 14:41:59 (00:00:01.740392)] debug3: mux_client_request_session: session request sent
[2024-02-13 14:41:59 (00:00:01.740407)] debug3: mux_master_read_cb: channel 1 packet type 0x10000002 len 70
[2024-02-13 14:41:59 (00:00:01.740415)] debug2: mux_master_process_new_session: channel 1: request tty 0, X 0, agent 0, subsys 0, term "xterm-256color", cmd "exit", env 1
[2024-02-13 14:41:59 (00:00:01.740423)] debug3: mux_master_process_new_session: got fds stdin 6, stdout 7, stderr 8
[2024-02-13 14:41:59 (00:00:01.740431)] debug1: channel 2: new [client-session]
[2024-02-13 14:41:59 (00:00:01.740467)] debug2: mux_master_process_new_session: channel_new: 2 linked to control channel 1
[2024-02-13 14:41:59 (00:00:01.740480)] debug2: channel 2: send open
[2024-02-13 14:41:59 (00:00:01.740490)] debug3: send packet: type 90
[2024-02-13 14:41:59 (00:00:01.972491)] debug3: receive packet: type 80
[2024-02-13 14:41:59 (00:00:01.972590)] debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
[2024-02-13 14:41:59 (00:00:01.972608)] debug3: client_input_hostkeys: received RSA key SHA256:
[2024-02-13 14:41:59 (00:00:01.972630)] debug3: client_input_hostkeys: received ECDSA key SHA256:
[2024-02-13 14:41:59 (00:00:01.972637)] debug3: client_input_hostkeys: received ED25519 key SHA256:
[2024-02-13 14:41:59 (00:00:01.972642)] debug1: client_input_hostkeys: searching /home/example/.ssh/known_hosts for 1.2.3.4 / (none)
[2024-02-13 14:41:59 (00:00:01.972729)] debug3: hostkeys_foreach: reading file "/home/example/.ssh/known_hosts"
[2024-02-13 14:41:59 (00:00:01.975791)] debug3: hostkeys_find: found ssh-ed25519 key at /home/example/.ssh/known_hosts:25
[2024-02-13 14:41:59 (00:00:01.975869)] debug3: hostkeys_find: found ssh-rsa key at /home/example/.ssh/known_hosts:26
[2024-02-13 14:41:59 (00:00:01.975888)] debug3: hostkeys_find: found ecdsa-sha2-nistp256 key at /home/example/.ssh/known_hosts:27
[2024-02-13 14:41:59 (00:00:01.975894)] debug1: client_input_hostkeys: searching /home/example/.ssh/known_hosts2 for 1.2.3.4 / (none)
[2024-02-13 14:41:59 (00:00:01.975900)] debug1: client_input_hostkeys: hostkeys file /home/example/.ssh/known_hosts2 does not exist
[2024-02-13 14:41:59 (00:00:01.975905)] debug3: client_input_hostkeys: 3 server keys: 0 new, 3 retained, 0 incomplete match. 0 to remove
[2024-02-13 14:41:59 (00:00:01.975910)] debug1: client_input_hostkeys: no new or deprecated keys from server
[2024-02-13 14:41:59 (00:00:01.975916)] debug3: receive packet: type 4
[2024-02-13 14:41:59 (00:00:01.975921)] debug1: Remote: /usr/sbin/aad_certhandler %u %k:1: key options: agent-forwarding port-forwarding principals pty user-rc x11-forwarding
[2024-02-13 14:41:59 (00:00:02.058638)] debug3: receive packet: type 4
[2024-02-13 14:41:59 (00:00:02.058772)] debug1: Remote: /usr/sbin/aad_certhandler %u %k:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
[2024-02-13 14:41:59 (00:00:02.058796)] debug3: receive packet: type 4
[2024-02-13 14:41:59 (00:00:02.058809)] debug1: Remote: /usr/sbin/aad_certhandler %u %k:1: key options: agent-forwarding port-forwarding principals pty user-rc x11-forwarding
[2024-02-13 14:41:59 (00:00:02.058817)] debug3: receive packet: type 4
[2024-02-13 14:41:59 (00:00:02.058825)] debug1: Remote: /usr/sbin/aad_certhandler %u %k:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
[2024-02-13 14:41:59 (00:00:02.058833)] debug3: receive packet: type 91
[2024-02-13 14:41:59 (00:00:02.058841)] debug2: channel_input_open_confirmation: channel 2: callback start
[2024-02-13 14:41:59 (00:00:02.058849)] debug2: client_session2_setup: id 2
[2024-02-13 14:41:59 (00:00:02.058856)] debug1: Sending environment.
[2024-02-13 14:41:59 (00:00:02.058864)] debug1: channel 2: setting env LANG = "C.UTF-8"
[2024-02-13 14:41:59 (00:00:02.058872)] debug2: channel 2: request env confirm 0
[2024-02-13 14:41:59 (00:00:02.058880)] debug3: send packet: type 98
[2024-02-13 14:41:59 (00:00:02.058887)] debug1: Sending command: exit
[2024-02-13 14:41:59 (00:00:02.058895)] debug2: channel 2: request exec confirm 1
[2024-02-13 14:41:59 (00:00:02.058903)] debug3: send packet: type 98
[2024-02-13 14:41:59 (00:00:02.058911)] debug3: mux_session_confirm: sending success reply
[2024-02-13 14:41:59 (00:00:02.058919)] debug2: channel_input_open_confirmation: channel 2: callback done
[2024-02-13 14:41:59 (00:00:02.058927)] debug2: channel 2: open confirm rwindow 0 rmax 32768
[2024-02-13 14:41:59 (00:00:02.058936)] debug1: mux_client_request_session: master session id: 2
[2024-02-13 14:41:59 (00:00:02.203153)] debug2: channel 2: rcvd adjust 2097152
[2024-02-13 14:41:59 (00:00:02.203286)] debug3: receive packet: type 99
[2024-02-13 14:41:59 (00:00:02.203309)] debug2: channel_input_status_confirm: type 99 id 2
[2024-02-13 14:41:59 (00:00:02.203323)] debug2: exec request accepted on channel 2
[2024-02-13 14:41:59 (00:00:02.203334)] debug3: receive packet: type 96
[2024-02-13 14:41:59 (00:00:02.203345)] debug2: channel 2: rcvd eof
[2024-02-13 14:41:59 (00:00:02.203356)] debug2: channel 2: output open -> drain
[2024-02-13 14:41:59 (00:00:02.203367)] debug2: channel 2: obuf empty
[2024-02-13 14:41:59 (00:00:02.203384)] debug2: chan_shutdown_write: channel 2: (i0 o1 sock -1 wfd 7 efd 8 [write])
[2024-02-13 14:41:59 (00:00:02.203396)] debug2: channel 2: output drain -> closed
[2024-02-13 14:41:59 (00:00:02.203408)] debug3: receive packet: type 98
[2024-02-13 14:41:59 (00:00:02.203420)] debug1: client_input_channel_req: channel 2 rtype exit-status reply 0
[2024-02-13 14:41:59 (00:00:02.203431)] debug3: mux_exit_message: channel 2: exit message, exitval 0
[2024-02-13 14:41:59 (00:00:02.203444)] debug3: receive packet: type 98
[2024-02-13 14:41:59 (00:00:02.203456)] debug1: client_input_channel_req: channel 2 rtype eow@openssh.com reply 0
[2024-02-13 14:41:59 (00:00:02.203469)] debug2: channel 2: rcvd eow
[2024-02-13 14:41:59 (00:00:02.203480)] debug2: chan_shutdown_read: channel 2: (i0 o3 sock -1 wfd 6 efd 8 [write])
[2024-02-13 14:41:59 (00:00:02.203494)] debug2: channel 2: input open -> closed
[2024-02-13 14:41:59 (00:00:02.203507)] debug3: receive packet: type 97
[2024-02-13 14:41:59 (00:00:02.203519)] debug2: channel 2: rcvd close
[2024-02-13 14:41:59 (00:00:02.203532)] debug3: channel 2: will not send data after close
[2024-02-13 14:41:59 (00:00:02.203587)] debug2: channel 2: send close
[2024-02-13 14:41:59 (00:00:02.203611)] debug3: send packet: type 97
[2024-02-13 14:41:59 (00:00:02.203628)] debug2: channel 2: is dead
[2024-02-13 14:41:59 (00:00:02.203643)] debug2: channel 2: gc: notify user
[2024-02-13 14:41:59 (00:00:02.203657)] debug3: mux_master_session_cleanup_cb: entering for channel 2
[2024-02-13 14:41:59 (00:00:02.203669)] debug2: channel 1: rcvd close
[2024-02-13 14:41:59 (00:00:02.203680)] debug2: channel 1: output open -> drain
[2024-02-13 14:41:59 (00:00:02.203692)] debug2: chan_shutdown_read: channel 1: (i0 o1 sock 5 wfd 5 efd -1 [closed])
[2024-02-13 14:41:59 (00:00:02.203704)] debug2: channel 1: input open -> closed
[2024-02-13 14:41:59 (00:00:02.203717)] debug2: channel 2: gc: user detached
[2024-02-13 14:41:59 (00:00:02.203730)] debug2: channel 2: is dead
[2024-02-13 14:41:59 (00:00:02.203741)] debug2: channel 2: garbage collecting
[2024-02-13 14:41:59 (00:00:02.203749)] debug1: channel 2: free: client-session, nchannels 3
[2024-02-13 14:41:59 (00:00:02.203757)] debug3: channel 2: status: The following connections are open:
[2024-02-13 14:41:59 (00:00:02.203765)] #1 mux-control (t16 nr0 i3/0 o1/16 e[closed]/0 fd 5/5/-1 sock 5 cc -1 io 0x03/0x00)
[2024-02-13 14:41:59 (00:00:02.203773)] #2 client-session (t4 r0 i3/0 o3/0 e[write]/0 fd -1/-1/8 sock -1 cc -1 io 0x00/0x00)
[2024-02-13 14:41:59 (00:00:02.203781)]
[2024-02-13 14:41:59 (00:00:02.203790)] debug2: channel 1: obuf empty
[2024-02-13 14:41:59 (00:00:02.203800)] debug2: chan_shutdown_write: channel 1: (i3 o1 sock 5 wfd 5 efd -1 [closed])
[2024-02-13 14:41:59 (00:00:02.203810)] debug2: channel 1: output drain -> closed
[2024-02-13 14:41:59 (00:00:02.203821)] debug2: channel 1: is dead (local)
[2024-02-13 14:41:59 (00:00:02.203832)] debug2: channel 1: gc: notify user
[2024-02-13 14:41:59 (00:00:02.203842)] debug3: mux_master_control_cleanup_cb: entering for channel 1
[2024-02-13 14:41:59 (00:00:02.203852)] debug2: channel 1: gc: user detached
[2024-02-13 14:41:59 (00:00:02.203862)] debug2: channel 1: is dead (local)
[2024-02-13 14:41:59 (00:00:02.203871)] debug2: channel 1: garbage collecting
[2024-02-13 14:41:59 (00:00:02.203882)] debug1: channel 1: free: mux-control, nchannels 2
[2024-02-13 14:41:59 (00:00:02.203893)] debug3: mux_client_read_packet: read header failed: Broken pipe
[2024-02-13 14:41:59 (00:00:02.203904)] debug2: Received exit status from master 0
[2024-02-13 14:41:59 (00:00:02.203915)] debug3: channel 1: status: The following connections are open:
[2024-02-13 14:41:59 (00:00:02.203925)] #1 mux-control (t16 nr0 i3/0 o3/0 e[closed]/0 fd 5/5/-1 sock 5 cc -1 io 0x00/0x03)
[2024-02-13 14:41:59 (00:00:02.203936)]
[2024-02-13 14:41:59 (00:00:02.203949)] debug2: set_control_persist_exit_time: schedule exit in 60 seconds
[2024-02-13 14:42:59 (00:01:02.264024)] debug1: ControlPersist timeout expired
[2024-02-13 14:42:59 (00:01:02.264157)] debug3: send packet: type 1
[2024-02-13 14:42:59 (00:01:02.264165)] debug1: channel 0: free: /home/example/controlpath, nchannels 1
[2024-02-13 14:42:59 (00:01:02.264168)] debug3: channel 0: status: The following connections are open:
[2024-02-13 14:42:59 (00:01:02.264170)]
[2024-02-13 14:42:59 (00:01:02.264173)] Transferred: sent 5604, received 4588 bytes, in 60.5 seconds
[2024-02-13 14:42:59 (00:01:02.264176)] Bytes per second: sent 92.6, received 75.8
[2024-02-13 14:42:59 (00:01:02.264179)] debug1: Exit status -1
```

### Expected behavior

I expect ssh to not hang for the duration of `ControlPersist`.

### Environment Summary

```
❯ az --version
azure-cli 2.57.0

core 2.57.0
telemetry 1.1.0

Extensions:
account 0.2.5
ssh 2.0.2

Dependencies:
msal 1.26.0
azure-mgmt-resource 23.1.0b2

Python location '/opt/az/bin/python3'
Extensions directory '/home/dwales/.azure/cliextensions'

Python (Linux) 3.11.7 (main, Jan 31 2024, 05:29:49) [GCC 11.4.0]
```

### Additional context

I'm trying to use `az ssh` with Ansible. I have created a wrapper script, but have noticed I need to exclude the Control* arguments if I want good performance.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.