Page MenuHomePhabricator

Getting unexpected `remote channel is closed` after executing remote command
Open, Needs TriagePublic

Description

Hi wondering if you can help.

i'm on ubuntu 18.04 trying to run a command on a proxy'd machine, ie ProxyCommand is being used to ssh to machine 3 via machine 2 from machine 1 and then running a command and getting the stdout of that command.

Not randomly, but inexplicably, sometimes the remote session will be closed before I can get the results of stdout.

when i say not randomly it can be things like running ls fails but ls -l is ok

it seems pretty weird to me, i have this debug log and i wonder if you can shed any light that might help :) thanks

[2019/10/09 21:44:59.805065, 3] ssh_config_parse_file:  Reading configuration data from /home/david/.ssh/config
[2019/10/09 21:44:59.805500, 2] ssh_config_parse_line:  Unapplicable option: ControlMaster, line: 4
[2019/10/09 21:44:59.805654, 2] ssh_config_parse_line:  Unapplicable option: ControlPath, line: 5
[2019/10/09 21:44:59.805795, 2] ssh_config_parse_line:  Unapplicable option: ControlPersist, line: 6
[2019/10/09 21:44:59.805937, 2] ssh_config_parse_line:  Unapplicable option: ControlMaster, line: 11
[2019/10/09 21:44:59.806080, 2] ssh_config_parse_line:  Unapplicable option: ControlPath, line: 12
[2019/10/09 21:44:59.806219, 2] ssh_config_parse_line:  Unapplicable option: ControlPersist, line: 13
[2019/10/09 21:44:59.806359, 1] ssh_config_parse_line:  Unsupported option: IdentitiesOnly, line: 19
[2019/10/09 21:44:59.806498, 1] ssh_config_parse_line:  Unsupported option: ForwardAgent, line: 24
[2019/10/09 21:44:59.806642, 2] ssh_config_parse_line:  Unapplicable option: ControlPersist, line: 34
[2019/10/09 21:44:59.806796, 1] ssh_config_parse_line:  Unsupported option: ForwardAgent, line: 40
[2019/10/09 21:44:59.806939, 2] ssh_config_parse_line:  Unapplicable option: ControlMaster, line: 43
[2019/10/09 21:44:59.807081, 2] ssh_config_parse_line:  Unapplicable option: ControlPath, line: 44
[2019/10/09 21:44:59.807220, 2] ssh_config_parse_line:  Unapplicable option: ControlPersist, line: 45
[2019/10/09 21:44:59.807360, 1] ssh_config_parse_line:  Unsupported option: PreferredAuthentications, line: 49
[2019/10/09 21:44:59.807614, 3] ssh_config_parse_file:  Reading configuration data from /etc/ssh/ssh_config
[2019/10/09 21:44:59.807777, 2] ssh_config_parse_line:  Unapplicable option: SendEnv, line: 49
[2019/10/09 21:44:59.807917, 1] ssh_config_parse_line:  Unsupported option: HashKnownHosts, line: 50
[2019/10/09 21:44:59.808095, 2] ssh_connect:  libssh 0.9.0 (c) 2003-2019 Aris Adamantiadis, Andreas Schneider and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_pthread
[2019/10/09 21:44:59.808251, 2] ssh_socket_connect_proxycommand:  Executing proxycommand 'ssh -W [ip_redacted]:22 bastion'
[2019/10/09 21:44:59.811932, 2] ssh_socket_connect_proxycommand:  ProxyCommand connection pipe: [9,10]
[2019/10/09 21:44:59.812168, 1] socket_callback_connected:  Socket connection callback: 1 (0)
[2019/10/09 21:44:59.812330, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:44:59.812481, 2] ssh_connect:  Socket connecting, now waiting for the callbacks to work
[2019/10/09 21:44:59.812627, 3] ssh_connect:  Actual timeout : 10000
[2019/10/09 21:44:59.812807, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.270492, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.270820, 3] callback_receive_banner:  Received banner: SSH-2.0-OpenSSH_7.6p1 Ubuntu-4ubuntu0.3
[2019/10/09 21:45:00.271079, 2] ssh_client_connection_callback:  SSH server banner: SSH-2.0-OpenSSH_7.6p1 Ubuntu-4ubuntu0.3
[2019/10/09 21:45:00.271216, 2] ssh_analyze_banner:  Analyzing banner: SSH-2.0-OpenSSH_7.6p1 Ubuntu-4ubuntu0.3
[2019/10/09 21:45:00.271385, 2] ssh_analyze_banner:  We are talking to an OpenSSH client version: 7.6 (70600)
[2019/10/09 21:45:00.271929, 1] ssh_known_hosts_read_entries:  Failed to open the known_hosts file '/etc/ssh/ssh_known_hosts': No such file or directory
[2019/10/09 21:45:00.272110, 4] ssh_list_kex:  kex algos: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group18-sha512,diffie-hellman-group16-sha512,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,ext-info-c
[2019/10/09 21:45:00.272247, 4] ssh_list_kex:  server host key algo: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss
[2019/10/09 21:45:00.272382, 4] ssh_list_kex:  encryption client->server: aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc
[2019/10/09 21:45:00.272515, 4] ssh_list_kex:  encryption server->client: aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc
[2019/10/09 21:45:00.272656, 4] ssh_list_kex:  mac algo client->server: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2019/10/09 21:45:00.272789, 4] ssh_list_kex:  mac algo server->client: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2019/10/09 21:45:00.272922, 4] ssh_list_kex:  compression algo client->server: none
[2019/10/09 21:45:00.273054, 4] ssh_list_kex:  compression algo server->client: none
[2019/10/09 21:45:00.273186, 4] ssh_list_kex:  languages client->server: 
[2019/10/09 21:45:00.273318, 4] ssh_list_kex:  languages server->client: 
[2019/10/09 21:45:00.273495, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.273742, 3] packet_send2:  packet: wrote [type=20, len=1228, padding_size=10, comp=1217, payload=1217]
[2019/10/09 21:45:00.273895, 3] ssh_send_kex:  SSH_MSG_KEXINIT sent
[2019/10/09 21:45:00.274041, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.274175, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.274310, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.294443, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.294748, 3] ssh_packet_socket_callback:  packet: read type 20 [len=1076,padding=6,comp=1069,payload=1069]
[2019/10/09 21:45:00.294920, 3] ssh_packet_process:  Dispatching handler for packet type 20
[2019/10/09 21:45:00.295090, 4] ssh_list_kex:  kex algos: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1
[2019/10/09 21:45:00.295231, 4] ssh_list_kex:  server host key algo: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519
[2019/10/09 21:45:00.295368, 4] ssh_list_kex:  encryption client->server: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2019/10/09 21:45:00.295504, 4] ssh_list_kex:  encryption server->client: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
[2019/10/09 21:45:00.295643, 4] ssh_list_kex:  mac algo client->server: 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
[2019/10/09 21:45:00.295780, 4] ssh_list_kex:  mac algo server->client: 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
[2019/10/09 21:45:00.295917, 4] ssh_list_kex:  compression algo client->server: none,zlib@openssh.com
[2019/10/09 21:45:00.296053, 4] ssh_list_kex:  compression algo server->client: none,zlib@openssh.com
[2019/10/09 21:45:00.296188, 4] ssh_list_kex:  languages client->server: 
[2019/10/09 21:45:00.296323, 4] ssh_list_kex:  languages server->client: 
[2019/10/09 21:45:00.296472, 2] ssh_kex_select_methods:  Negotiated curve25519-sha256,ssh-ed25519,aes256-gcm@openssh.com,aes256-gcm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-256-etm@openssh.com,none,none,,
[2019/10/09 21:45:00.302403, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.302561, 3] packet_send2:  packet: wrote [type=30, len=44, padding_size=6, comp=37, payload=37]
[2019/10/09 21:45:00.302721, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.302859, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.302995, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.330020, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.330859, 3] ssh_packet_socket_callback:  packet: read type 31 [len=188,padding=8,comp=179,payload=179]
[2019/10/09 21:45:00.331486, 3] ssh_packet_process:  Dispatching handler for packet type 31
[2019/10/09 21:45:00.349617, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.349979, 3] packet_send2:  packet: wrote [type=21, len=12, padding_size=10, comp=1, payload=1]
[2019/10/09 21:45:00.350229, 4] ssh_packet_set_newkeys:  called, direction = OUT 
[2019/10/09 21:45:00.350612, 3] crypt_set_algorithms2:  Set output algorithm to aes256-gcm@openssh.com
[2019/10/09 21:45:00.350870, 3] crypt_set_algorithms2:  Set HMAC output algorithm to aead-gcm
[2019/10/09 21:45:00.351111, 3] crypt_set_algorithms2:  Set input algorithm to aes256-gcm@openssh.com
[2019/10/09 21:45:00.351350, 3] crypt_set_algorithms2:  Set HMAC input algorithm to aead-gcm
[2019/10/09 21:45:00.351600, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2019/10/09 21:45:00.351846, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2019/10/09 21:45:00.352144, 2] ssh_packet_client_curve25519_reply:  SSH_MSG_NEWKEYS sent
[2019/10/09 21:45:00.352386, 3] ssh_packet_socket_callback:  Processing 196 bytes left in socket buffer
[2019/10/09 21:45:00.352636, 3] ssh_packet_socket_callback:  packet: read type 21 [len=12,padding=10,comp=1,payload=1]
[2019/10/09 21:45:00.353135, 3] ssh_packet_process:  Dispatching handler for packet type 21
[2019/10/09 21:45:00.353484, 2] ssh_packet_newkeys:  Received SSH_MSG_NEWKEYS
[2019/10/09 21:45:00.353773, 4] ssh_pki_signature_verify:  Going to verify a ssh-ed25519 type signature
[2019/10/09 21:45:00.369354, 2] ssh_packet_newkeys:  Signature verified and valid
[2019/10/09 21:45:00.369594, 4] ssh_packet_set_newkeys:  called, direction = IN 
[2019/10/09 21:45:00.369737, 3] ssh_packet_socket_callback:  Processing 180 bytes left in socket buffer
[2019/10/09 21:45:00.369908, 3] ssh_packet_socket_callback:  packet: read type 7 [len=160,padding=18,comp=141,payload=141]
[2019/10/09 21:45:00.370047, 3] ssh_packet_process:  Dispatching handler for packet type 7
[2019/10/09 21:45:00.370184, 3] ssh_packet_ext_info:  Received SSH_MSG_EXT_INFO
[2019/10/09 21:45:00.370325, 3] ssh_packet_ext_info:  Follows 1 extensions
[2019/10/09 21:45:00.370471, 3] ssh_packet_ext_info:  Extension: server-sig-algs=<ssh-ed25519,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521>
[2019/10/09 21:45:00.370615, 3] ssh_connect:  current state : 7
[2019/10/09 21:45:00.370960, 4] agent_talk:  Request length: 1
[2019/10/09 21:45:00.387674, 4] agent_talk:  Response length: 2429
[2019/10/09 21:45:00.388940, 1] ssh_agent_get_ident_count:  Answer type: 12, expected answer: 12
[2019/10/09 21:45:00.389133, 3] ssh_agent_get_ident_count:  Agent count: 7
[2019/10/09 21:45:00.389313, 3] ssh_userauth_agent:  Trying identity blah
[2019/10/09 21:45:00.389457, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.389590, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.389847, 3] packet_send2:  packet: wrote [type=5, len=32, padding_size=14, comp=17, payload=17]
[2019/10/09 21:45:00.389984, 3] ssh_service_request:  Sent SSH_MSG_SERVICE_REQUEST (service ssh-userauth)
[2019/10/09 21:45:00.390125, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 52
[2019/10/09 21:45:00.390263, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.390488, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.390635, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.390833, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.411500, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.411767, 3] ssh_packet_socket_callback:  packet: read type 6 [len=32,padding=14,comp=17,payload=17]
[2019/10/09 21:45:00.411909, 3] ssh_packet_process:  Dispatching handler for packet type 6
[2019/10/09 21:45:00.412075, 3] ssh_packet_service_accept:  Received SSH_MSG_SERVICE_ACCEPT
[2019/10/09 21:45:00.412244, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.412412, 3] packet_send2:  packet: wrote [type=50, len=608, padding_size=4, comp=603, payload=603]
[2019/10/09 21:45:00.412570, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.412703, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.412835, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.435475, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.435994, 3] ssh_packet_socket_callback:  packet: read type 53 [len=176,padding=4,comp=171,payload=171]
[2019/10/09 21:45:00.436218, 3] ssh_packet_process:  Dispatching handler for packet type 53
[2019/10/09 21:45:00.436359, 3] ssh_packet_userauth_banner:  Received SSH_USERAUTH_BANNER packet
[2019/10/09 21:45:00.436578, 3] ssh_packet_socket_callback:  Processing 52 bytes left in socket buffer
[2019/10/09 21:45:00.436764, 3] ssh_packet_socket_callback:  packet: read type 51 [len=32,padding=16,comp=15,payload=15]
[2019/10/09 21:45:00.436912, 3] ssh_packet_process:  Dispatching handler for packet type 51
[2019/10/09 21:45:00.437046, 1] ssh_packet_userauth_failure:  Access denied for 'publickey'. Authentication that can continue: publickey
[2019/10/09 21:45:00.437180, 2] ssh_packet_userauth_failure:  Access denied for 'publickey'. Authentication that can continue: publickey
[2019/10/09 21:45:00.437315, 3] ssh_userauth_agent:  Public key of blah refused by server
[2019/10/09 21:45:00.437495, 3] ssh_userauth_agent:  Trying identity imported-openssh-key
[2019/10/09 21:45:00.437631, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.437766, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.437925, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.438063, 3] packet_send2:  packet: wrote [type=50, len=352, padding_size=4, comp=347, payload=347]
[2019/10/09 21:45:00.438206, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.438340, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.438475, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.459707, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.459980, 3] ssh_packet_socket_callback:  packet: read type 51 [len=32,padding=16,comp=15,payload=15]
[2019/10/09 21:45:00.460143, 3] ssh_packet_process:  Dispatching handler for packet type 51
[2019/10/09 21:45:00.460294, 1] ssh_packet_userauth_failure:  Access denied for 'publickey'. Authentication that can continue: publickey
[2019/10/09 21:45:00.460439, 2] ssh_packet_userauth_failure:  Access denied for 'publickey'. Authentication that can continue: publickey
[2019/10/09 21:45:00.460573, 3] ssh_userauth_agent:  Public key of imported-openssh-key refused by server
[2019/10/09 21:45:00.460721, 3] ssh_userauth_agent:  Trying identity GitLab
[2019/10/09 21:45:00.460855, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.461109, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.461297, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.461496, 3] packet_send2:  packet: wrote [type=50, len=608, padding_size=4, comp=603, payload=603]
[2019/10/09 21:45:00.461670, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.461804, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.461937, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.483088, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.483364, 3] ssh_packet_socket_callback:  packet: read type 51 [len=32,padding=16,comp=15,payload=15]
[2019/10/09 21:45:00.483535, 3] ssh_packet_process:  Dispatching handler for packet type 51
[2019/10/09 21:45:00.483707, 1] ssh_packet_userauth_failure:  Access denied for 'publickey'. Authentication that can continue: publickey
[2019/10/09 21:45:00.483859, 2] ssh_packet_userauth_failure:  Access denied for 'publickey'. Authentication that can continue: publickey
[2019/10/09 21:45:00.483995, 3] ssh_userauth_agent:  Public key of GitLab refused by server
[2019/10/09 21:45:00.484140, 3] ssh_userauth_agent:  Trying identity dhewson
[2019/10/09 21:45:00.484276, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.484410, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.484572, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.484758, 3] packet_send2:  packet: wrote [type=50, len=352, padding_size=4, comp=347, payload=347]
[2019/10/09 21:45:00.484901, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.485050, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.485196, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.506178, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.506427, 3] ssh_packet_socket_callback:  packet: read type 51 [len=32,padding=16,comp=15,payload=15]
[2019/10/09 21:45:00.506577, 3] ssh_packet_process:  Dispatching handler for packet type 51
[2019/10/09 21:45:00.506721, 1] ssh_packet_userauth_failure:  Access denied for 'publickey'. Authentication that can continue: publickey
[2019/10/09 21:45:00.506861, 2] ssh_packet_userauth_failure:  Access denied for 'publickey'. Authentication that can continue: publickey
[2019/10/09 21:45:00.507007, 3] ssh_userauth_agent:  Public key of dhewson refused by server
[2019/10/09 21:45:00.507157, 3] ssh_userauth_agent:  Trying identity me_key.key
[2019/10/09 21:45:00.507298, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.507437, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.507600, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.507743, 3] packet_send2:  packet: wrote [type=50, len=352, padding_size=4, comp=347, payload=347]
[2019/10/09 21:45:00.507893, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.508036, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.508174, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.529296, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.529582, 3] ssh_packet_socket_callback:  packet: read type 60 [len=320,padding=19,comp=300,payload=300]
[2019/10/09 21:45:00.529759, 3] ssh_packet_process:  Dispatching handler for packet type 60
[2019/10/09 21:45:00.529909, 4] ssh_packet_userauth_pk_ok:  Received SSH_USERAUTH_PK_OK/INFO_REQUEST/GSSAPI_RESPONSE
[2019/10/09 21:45:00.530048, 4] ssh_packet_userauth_pk_ok:  Assuming SSH_USERAUTH_PK_OK
[2019/10/09 21:45:00.530184, 3] ssh_userauth_agent:  Public key of me_key.key accepted by server
[2019/10/09 21:45:00.530325, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.530460, 3] ssh_key_algorithm_allowed:  Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2019/10/09 21:45:00.530646, 4] agent_talk:  Request length: 675
[2019/10/09 21:45:00.540836, 4] agent_talk:  Response length: 276
[2019/10/09 21:45:00.541127, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.541276, 3] packet_send2:  packet: wrote [type=50, len=640, padding_size=17, comp=622, payload=622]
[2019/10/09 21:45:00.541425, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.541560, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.541694, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.562744, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.563170, 3] ssh_packet_socket_callback:  packet: read type 52 [len=16,padding=14,comp=1,payload=1]
[2019/10/09 21:45:00.563336, 3] ssh_packet_process:  Dispatching handler for packet type 52
[2019/10/09 21:45:00.563498, 3] ssh_packet_userauth_success:  Authentication successful
[2019/10/09 21:45:00.563697, 4] ssh_packet_userauth_success:  Received SSH_USERAUTH_SUCCESS
[2019/10/09 21:45:00.563905, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=176, in_blocks=37
[2019/10/09 21:45:00.564078, 2] channel_open:  Creating a channel 43 with 64000 window and 32768 max packet
[2019/10/09 21:45:00.564215, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=177, in_blocks=38
[2019/10/09 21:45:00.564367, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.564536, 3] packet_send2:  packet: wrote [type=90, len=32, padding_size=7, comp=24, payload=24]
[2019/10/09 21:45:00.564685, 3] channel_open:  Sent a SSH_MSG_CHANNEL_OPEN type session for channel 43
[2019/10/09 21:45:00.564829, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.564962, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.565094, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.706247, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.706565, 3] ssh_packet_socket_callback:  packet: read type 80 [len=928,padding=15,comp=912,payload=912]
[2019/10/09 21:45:00.706768, 3] ssh_packet_process:  Dispatching handler for packet type 80
[2019/10/09 21:45:00.706967, 2] ssh_packet_global_request:  Received SSH_MSG_GLOBAL_REQUEST packet
[2019/10/09 21:45:00.707150, 2] ssh_packet_global_request:  UNKNOWN SSH_MSG_GLOBAL_REQUEST hostkeys-00@openssh.com, want_reply = 0
[2019/10/09 21:45:00.707315, 3] ssh_packet_global_request:  The requester doesn't want to know the request failed!
[2019/10/09 21:45:00.707477, 1] ssh_packet_global_request:  Invalid SSH_MSG_GLOBAL_REQUEST packet
[2019/10/09 21:45:00.707640, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=177, in_blocks=94
[2019/10/09 21:45:00.766641, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.767078, 3] ssh_packet_socket_callback:  packet: read type 91 [len=32,padding=14,comp=17,payload=17]
[2019/10/09 21:45:00.767272, 3] ssh_packet_process:  Dispatching handler for packet type 91
[2019/10/09 21:45:00.767501, 3] ssh_packet_channel_open_conf:  Received SSH2_MSG_CHANNEL_OPEN_CONFIRMATION
[2019/10/09 21:45:00.767694, 2] ssh_packet_channel_open_conf:  Received a CHANNEL_OPEN_CONFIRMATION for channel 43:0
[2019/10/09 21:45:00.767875, 2] ssh_packet_channel_open_conf:  Remote window : 0, maxpacket : 32768
[2019/10/09 21:45:00.768051, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=177, in_blocks=95
[2019/10/09 21:45:00.768255, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=180, in_blocks=98
[2019/10/09 21:45:00.768462, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.768643, 3] packet_send2:  packet: wrote [type=98, len=80, padding_size=18, comp=61, payload=61]
[2019/10/09 21:45:00.768832, 3] channel_request:  Sent a SSH_MSG_CHANNEL_REQUEST exec
[2019/10/09 21:45:00.769023, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 0
[2019/10/09 21:45:00.769199, 4] ssh_socket_pollcallback:  sending control flow event
[2019/10/09 21:45:00.769375, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/10/09 21:45:00.789752, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.790085, 3] ssh_packet_socket_callback:  packet: read type 93 [len=16,padding=6,comp=9,payload=9]
[2019/10/09 21:45:00.790349, 3] ssh_packet_process:  Dispatching handler for packet type 93
[2019/10/09 21:45:00.790536, 2] channel_rcv_change_window:  Adding 2097152 bytes to channel (43:0) (from 0 bytes)
[2019/10/09 21:45:00.790713, 3] ssh_packet_socket_callback:  Processing 36 bytes left in socket buffer
[2019/10/09 21:45:00.790890, 3] ssh_packet_socket_callback:  packet: read type 99 [len=16,padding=10,comp=5,payload=5]
[2019/10/09 21:45:00.791063, 3] ssh_packet_process:  Dispatching handler for packet type 99
[2019/10/09 21:45:00.791279, 3] ssh_packet_channel_success:  Received SSH_CHANNEL_SUCCESS on channel (43:0)
[2019/10/09 21:45:00.791459, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=180, in_blocks=95
[2019/10/09 21:45:00.791635, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=180, in_blocks=95
[2019/10/09 21:45:00.791811, 2] channel_request:  Channel request exec success
[2019/10/09 21:45:00.850348, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLIN ), out buffer 0
[2019/10/09 21:45:00.850623, 3] ssh_packet_socket_callback:  packet: read type 96 [len=16,padding=10,comp=5,payload=5]
[2019/10/09 21:45:00.850799, 3] ssh_packet_process:  Dispatching handler for packet type 96
[2019/10/09 21:45:00.850968, 3] channel_rcv_eof:  Received eof on channel (43:0)
[2019/10/09 21:45:00.851155, 3] ssh_packet_socket_callback:  Processing 88 bytes left in socket buffer
[2019/10/09 21:45:00.851363, 3] ssh_packet_socket_callback:  packet: read type 98 [len=32,padding=6,comp=25,payload=25]
[2019/10/09 21:45:00.851500, 3] ssh_packet_process:  Dispatching handler for packet type 98
[2019/10/09 21:45:00.851639, 3] channel_rcv_request:  received exit-status 0
[2019/10/09 21:45:00.851773, 3] ssh_packet_socket_callback:  Processing 36 bytes left in socket buffer
[2019/10/09 21:45:00.851908, 3] ssh_packet_socket_callback:  packet: read type 97 [len=16,padding=10,comp=5,payload=5]
[2019/10/09 21:45:00.852043, 3] ssh_packet_process:  Dispatching handler for packet type 97
[2019/10/09 21:45:00.852207, 3] channel_rcv_close:  Received close on channel (43:0)
[2019/10/09 21:45:00.852377, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=180, in_blocks=96
[2019/10/09 21:45:00.852512, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=180, in_blocks=96
[2019/10/09 21:45:00.852672, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=180, in_blocks=96
[2019/10/09 21:45:00.852869, 3] ssh_channel_read_timeout:  Read (32) buffered : 0 bytes. Window: 64000
[2019/10/09 21:45:00.853006, 1] ssh_channel_read_timeout:  Remote channel is closed.
[2019/10/09 21:45:00.853174, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=180, in_blocks=96
[2019/10/09 21:45:00.853466, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/10/09 21:45:00.853629, 3] packet_send2:  packet: wrote [type=96, len=16, padding_size=10, comp=5, payload=5]
[2019/10/09 21:45:00.853764, 3] ssh_channel_send_eof:  Sent a EOF on client channel (43:0)
[2019/10/09 21:45:00.853902, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=180, in_blocks=96
[2019/10/09 21:45:00.854120, 3] packet_send2:  packet: wrote [type=97, len=16, padding_size=10, comp=5, payload=5]
[2019/10/09 21:45:00.854303, 3] ssh_channel_close:  Sent a close on client channel (43:0)
[2019/10/09 21:45:00.854522, 4] ssh_socket_pollcallback:  Poll callback on socket 10 (POLLOUT ), out buffer 36
[2019/10/09 21:45:00.854707, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket

Event Timeline

dten created this task.Oct 9 2019, 10:58 PM
dten created this object with edit policy "dten (David Hewson)".
dten updated the task description. (Show Details)
dten updated the task description. (Show Details)Oct 9 2019, 11:23 PM
dten added a comment.Oct 9 2019, 11:26 PM

i have a theory about this now :)

the commands that gave the error all produce no stdout or stderr upon success. when the process finishes the remote session closes and so sends close, channel_rcv_close gets that and see that there is no content in stdout or stderr and so does not delay the close. then when i come to ask for the contents of stdout to confirm that it was empty i am instead told SSH_ERR

i am going to take that plus a successful exit code to mean that they were both empty. it's not ideal though :D

Jakuje added a subscriber: Jakuje.Oct 10 2019, 11:59 AM

Theory sounds right. Were you able to confirm this theory and fix your code to handle empty responses?

dten added a comment.Oct 10 2019, 7:33 PM

I have something working. If the theory holds and that's a reasonable check then I'll do that.

dten added a comment.Oct 10 2019, 7:35 PM

There's a side issue of the proxy commands is being left open. Still looking into that