Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
daviewales opened this issue Feb 13, 2024 · 7 comments
Assignees
Labels
Auto-Assign Auto assign by bot bug This issue requires a change to an existing behavior in the product in order to be resolved. customer-reported Issues that are reported by GitHub users external to the Azure organization. Service Attention This issue is responsible by Azure service team. VM SSH

Comments

@daviewales
Copy link

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:

az ssh vm --ip 1.2.3.4 -- exit

While this takes 63.3 seconds.

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 '[email protected]'
[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 [email protected], 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,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,[email protected],diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-c,[email protected]
[2024-02-13 14:41:28 (00:00:01.830492)] debug2: host key algorithms: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],[email protected],rsa-sha2-512,rsa-sha2-256
[2024-02-13 14:41:28 (00:00:01.830509)] debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
[2024-02-13 14:41:28 (00:00:01.830525)] debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
[2024-02-13 14:41:28 (00:00:01.830541)] debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:28 (00:00:01.830556)] debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:28 (00:00:01.830577)] debug2: compression ctos: none,[email protected],zlib
[2024-02-13 14:41:28 (00:00:01.830592)] debug2: compression stoc: none,[email protected],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,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,[email protected],diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,[email protected]
[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: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
[2024-02-13 14:41:28 (00:00:01.830727)] debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
[2024-02-13 14:41:28 (00:00:01.830742)] debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:28 (00:00:01.830761)] debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:28 (00:00:01.830775)] debug2: compression ctos: none,[email protected]
[2024-02-13 14:41:28 (00:00:01.830790)] debug2: compression stoc: none,[email protected]
[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: [email protected] MAC: <implicit> compression: none
[2024-02-13 14:41:28 (00:00:01.830917)] debug1: kex: client->server cipher: [email protected] MAC: <implicit> 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:<redacted>/+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:<redacted>/amun9vc explicit
[2024-02-13 14:41:28 (00:00:01.976493)] debug1: Will attempt key: /tmp/aadsshcertwkuqc7gy/id_rsa RSA SHA256:<redacted>/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=<ssh-ed25519,[email protected],ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],[email protected]>
[2024-02-13 14:41:28 (00:00:01.976510)] debug1: kex_input_ext_info: [email protected]=<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:<redacted>/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:<redacted>/amun9vc explicit
[2024-02-13 14:41:28 (00:00:02.307732)] debug3: sign_and_send_pubkey: using [email protected] with RSA-CERT SHA256:<redacted>/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 [email protected] SHA256:<redacted>/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 [email protected] want_reply 0
[2024-02-13 14:41:29 (00:00:03.040995)] debug3: client_input_hostkeys: received RSA key SHA256:<redacted>/x35FolY
[2024-02-13 14:41:29 (00:00:03.041082)] debug3: client_input_hostkeys: received ECDSA key SHA256:<redacted>
[2024-02-13 14:41:29 (00:00:03.041108)] debug3: client_input_hostkeys: received ED25519 key SHA256:<redacted>/+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 [email protected] 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 '[email protected]'
[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 [email protected], 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,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,[email protected],diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-c,[email protected]
[2024-02-13 14:41:58 (00:00:01.118453)] debug2: host key algorithms: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],[email protected],rsa-sha2-512,rsa-sha2-256
[2024-02-13 14:41:58 (00:00:01.118457)] debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
[2024-02-13 14:41:58 (00:00:01.118460)] debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
[2024-02-13 14:41:58 (00:00:01.118464)] debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:58 (00:00:01.118467)] debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:58 (00:00:01.118470)] debug2: compression ctos: none,[email protected],zlib
[2024-02-13 14:41:58 (00:00:01.118473)] debug2: compression stoc: none,[email protected],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,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,[email protected],diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,[email protected]
[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: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
[2024-02-13 14:41:58 (00:00:01.118500)] debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
[2024-02-13 14:41:58 (00:00:01.118503)] debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:58 (00:00:01.118506)] debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2024-02-13 14:41:58 (00:00:01.118509)] debug2: compression ctos: none,[email protected]
[2024-02-13 14:41:58 (00:00:01.118512)] debug2: compression stoc: none,[email protected]
[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: [email protected] MAC: <implicit> compression: none
[2024-02-13 14:41:58 (00:00:01.118540)] debug1: kex: client->server cipher: [email protected] MAC: <implicit> 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:<redacted>/+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:<redacted> explicit
[2024-02-13 14:41:58 (00:00:01.226004)] debug1: Will attempt key: /tmp/aadsshcertit8omp_9/id_rsa RSA SHA256:<redacted> 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=<ssh-ed25519,[email protected],ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],[email protected]>
[2024-02-13 14:41:58 (00:00:01.226022)] debug1: kex_input_ext_info: [email protected]=<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:<redacted> 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:<redacted> explicit
[2024-02-13 14:41:58 (00:00:01.587066)] debug3: sign_and_send_pubkey: using [email protected] with RSA-CERT SHA256:<redacted>
[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 [email protected] SHA256:<redacted>
[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 [email protected] want_reply 0
[2024-02-13 14:41:59 (00:00:01.972608)] debug3: client_input_hostkeys: received RSA key SHA256:<redacted>
[2024-02-13 14:41:59 (00:00:01.972630)] debug3: client_input_hostkeys: received ECDSA key SHA256:<redacted>
[2024-02-13 14:41:59 (00:00:01.972637)] debug3: client_input_hostkeys: received ED25519 key SHA256:<redacted>
[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 [email protected] 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.

@daviewales daviewales added the bug This issue requires a change to an existing behavior in the product in order to be resolved. label Feb 13, 2024
@microsoft-github-policy-service microsoft-github-policy-service bot added question The issue doesn't require a change to the product in order to be resolved. Most issues start as that customer-reported Issues that are reported by GitHub users external to the Azure organization. Auto-Assign Auto assign by bot VM SSH Service Attention This issue is responsible by Azure service team. labels Feb 13, 2024
@yonzhan
Copy link
Collaborator

yonzhan commented Feb 13, 2024

Thank you for opening this issue, we will look into it.

@yonzhan yonzhan removed the question The issue doesn't require a change to the product in order to be resolved. Most issues start as that label Feb 13, 2024
@konstruktoid
Copy link

Isn't this a working expected behaviour?

ControlPersist:  When used in conjunction with ControlMaster, specifies that the master connection should remain open in the
background [...]
If set to a time in seconds, or a  time in any of the formats documented in sshd_config(5), then the backgrounded master connection will automatically terminate after it has remained idle (with no client connections) for the specified time.

@daviewales
Copy link
Author

@konstruktoid, it's expected that the background master connection will remain open for the specified time, not that the ssh command itself will hang for the duration.

@konstruktoid
Copy link

@daviewales, yeah you're absolutely correct.

@vthiebaut10
Copy link
Contributor

Does this happen only when you try to connect using the az ssh command, or does the same behavior happen any time you try to connect to that target using ssh? Also, what are the operating systems in the target and the client machines?

@konstruktoid
Copy link

~$ time ssh [email protected] -p2222 -i [...] -o ControlMaster=auto -o ControlPath=/tmp/control -o ControlPersist=60s exit

real    0m0.020s
user    0m0.009s
sys     0m0.006s

@daviewales
Copy link
Author

@vthiebaut10, It's the az ssh command. The remote system is an Azure Linux VM running Ubuntu 22.04.4. The local system is Ubuntu 22.04.3 in WSL.

With az ssh vm:

time az ssh vm --ip 1.2.3.4 -- -o ControlMaster=auto -o ControlPath=/tmp/controlpath -o ControlPersist=60s exit
OpenSSH_8.9p1 Ubuntu-3ubuntu0.6, OpenSSL 3.0.2 15 Mar 2022
Transferred: sent 5604, received 4588 bytes, in 60.7 seconds
Bytes per second: sent 92.3, received 75.6
az ssh vm --ip 1.2.3.4 -- -o ControlMaster=auto -o  -o ControlPersist=60s   0.99s user 0.10s system 1% cpu 1:03.28 total

With regular ssh:

time ssh -o ControlMaster=auto -o ControlPath=/tmp/control -o ControlPersist=60s [email protected]@1.2.3.4 exit
ssh -o ControlMaster=auto -o ControlPath=/tmp/control -o ControlPersist=60s    0.00s user 0.00s system 1% cpu 0.201 total

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Auto-Assign Auto assign by bot bug This issue requires a change to an existing behavior in the product in order to be resolved. customer-reported Issues that are reported by GitHub users external to the Azure organization. Service Attention This issue is responsible by Azure service team. VM SSH
Projects
None yet
Development

No branches or pull requests

4 participants