Bug 3047

Summary: while do the sftp from openssh 6.6.1 to openssh 7.4 "Received message too long " error appear
Product: Portable OpenSSH Reporter: Karthikeyan <clkarthikeyan>
Component: sftp-serverAssignee: Assigned to nobody <unassigned-bugs>
Status: NEW ---    
Severity: enhancement CC: djm
Priority: P5    
Version: 7.4p1   
Hardware: Other   
OS: Linux   
Attachments:
Description Flags
sftp debug file none

Description Karthikeyan 2019-07-30 21:11:28 AEST 
sftp -oPort=60001 -oIdentityFile=/opt/evit/ev_wkup/batch/config/id_rsa -oHostKeyAlias=sfxsv801.qa.jp.nissan.biz username@localhost
Authorized uses only. All activity may be monitored and reported.
 
 
Received message too long 1416128883
 
---------------------Issue----------
#console 2
hpadmin@tdsapos3% date
Tue Jul 30 07:09:14 UTC 2019
hpadmin@tdsapos3% sftp -vvv -oPort=60001 -oIdentityFile=/opt/evit/ev_wkup/batch/ config/id_rsa -oHostKeyAlias=sfxsv801.com  username@localhost
OpenSSH_6.6.1, OpenSSL 1.0.1e-fips 11 Feb 2013
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 56: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to localhost [127.0.0.1] port 60001.
debug1: Connection established.
debug3: Incorrect RSA1 identifier
debug3: Could not load "/opt/evit/ev_wkup/batch/config/id_rsa" as a RSA1 public key
debug1: identity file /opt/evit/ev_wkup/batch/config/id_rsa type -1
debug1: identity file /opt/evit/ev_wkup/batch/config/id_rsa-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1
debug1: Remote protocol version 2.0, remote software version OpenSSH_7.4
debug1: match: OpenSSH_7.4 pat OpenSSH* compat 0x04000000
debug2: fd 3 setting O_NONBLOCK
debug1: using hostkeyalias: sfxsv801.qa.jp.nissan.biz
debug3: load_hostkeys: loading entries for host "sfxsv801.qa.jp.nissan.biz" from file "/home/hpadmin/.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /home/hpadmin/.ssh/known_hosts:7
debug3: load_hostkeys: loaded 1 keys
debug3: order_hostkeyalgs: prefer hostkeyalgs: ssh-rsa-cert-v01@openssh.com,ssh-rsa-cert-v00@openssh.com,ssh-rsa
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa-cert-v01@openssh.com,ssh-rsa-cert-v00@openssh.com,ssh-rsa,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ssh-ed25519-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-dss-cert-v00@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-sha1,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-sha1,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: kex_parse_kexinit: 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-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519
debug2: kex_parse_kexinit: aes256-ctr,aes192-ctr,aes128-ctr
debug2: kex_parse_kexinit: aes256-ctr,aes192-ctr,aes128-ctr
debug2: kex_parse_kexinit: 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
debug2: kex_parse_kexinit: 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
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: mac_setup: setup hmac-sha1-etm@openssh.com
debug1: kex: server->client aes128-ctr hmac-sha1-etm@openssh.com none
debug2: mac_setup: setup hmac-sha1-etm@openssh.com
debug1: kex: client->server aes128-ctr hmac-sha1-etm@openssh.com none
debug1: kex: curve25519-sha256@libssh.org need=20 dh_need=20
debug1: kex: curve25519-sha256@libssh.org need=20 dh_need=20
debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: RSA 84:71:08:11:14:a7:fb:7e:ae:f5:e1:ea:e8:ee:9e:6e
debug3: put_host_port: [127.0.0.1]:60001
debug1: using hostkeyalias: sfxsv801.qa.jp.nissan.biz
debug3: load_hostkeys: loading entries for host "sfxsv801.qa.jp.nissan.biz" from file "/home/hpadmin/.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /home/hpadmin/.ssh/known_hosts:7
debug3: load_hostkeys: loaded 1 keys
debug1: Host 'sfxsv801.qa.jp.nissan.biz' is known and matches the RSA host key.
debug1: Found key in /home/hpadmin/.ssh/known_hosts:7
debug1: ssh_rsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /opt/evit/ev_wkup/batch/config/id_rsa ((nil)), explicit
debug3: input_userauth_banner
Authorized uses only. All activity may be monitored and reported.


debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug3: start over, passed a different list publickey,gssapi-keyex,gssapi-with-mic,password
debug3: preferred gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup gssapi-keyex
debug3: remaining preferred: gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-keyex
debug1: Next authentication method: gssapi-keyex
debug1: No valid Key exchange context
debug2: we did not send a packet, disable method
debug3: authmethod_lookup gssapi-with-mic
debug3: remaining preferred: publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-with-mic
debug1: Next authentication method: gssapi-with-mic
debug1: Unspecified GSS failure.  Minor code may provide more information
No Kerberos credentials available

debug1: Unspecified GSS failure.  Minor code may provide more information
No Kerberos credentials available

debug1: Unspecified GSS failure.  Minor code may provide more information


debug1: Unspecified GSS failure.  Minor code may provide more information
No Kerberos credentials available

debug2: we did not send a packet, disable method
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Trying private key: /opt/evit/ev_wkup/batch/config/id_rsa
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type RSA
debug3: sign_and_send_pubkey: RSA 84:0a:ca:54:32:6c:94:02:8b:c1:1c:c7:8f:ed:a6:5b
debug2: we sent a publickey packet, wait for reply
debug1: Authentication succeeded (publickey).
Authenticated to localhost ([127.0.0.1]:60001).
debug2: fd 4 setting O_NONBLOCK
debug3: fd 5 is O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: packet_set_tos: set IP_TOS 0x08
debug2: client_session2_setup: id 0
debug1: Sending environment.
debug3: Ignored env TOMCAT_HOME
debug3: Ignored env XDG_SESSION_ID
debug3: Ignored env HOSTNAME
debug3: Ignored env SHELL
debug3: Ignored env TERM
debug3: Ignored env CATALINA_HOME
debug3: Ignored env HISTSIZE
debug3: Ignored env JRE_HOME
debug3: Ignored env USER
debug3: Ignored env LS_COLORS
debug3: Ignored env MAIL
debug3: Ignored env PATH
debug3: Ignored env PWD
debug3: Ignored env JAVA_HOME
debug1: Sending env LANG = en_US.UTF-8
debug2: channel 0: request env confirm 0
debug3: Ignored env PS1
debug3: Ignored env HISTCONTROL
debug3: Ignored env SHLVL
debug3: Ignored env HOME
debug3: Ignored env LOGNAME
debug3: Ignored env CLASSPATH
debug3: Ignored env LESSOPEN
debug3: Ignored env _
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
Received message too long 1416128883
debug2: channel 0: rcvd eof
debug2: channel 0: output open -> drain
debug2: channel 0: obuf empty
debug2: channel 0: close_write
debug2: channel 0: output drain -> closed
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: client_input_channel_req: channel 0 rtype eow@openssh.com reply 0
debug2: channel 0: rcvd eow
debug2: channel 0: close_read
debug2: channel 0: input open -> closed
debug2: channel 0: rcvd close
debug3: channel 0: will not send data after close
debug2: channel 0: almost dead
debug2: channel 0: gc: notify user
debug2: channel 0: gc: user detached
debug2: channel 0: send close
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: client-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i3/0 o3/0 fd -1/-1 cc -1)

debug1: fd 0 clearing O_NONBLOCK
debug3: fd 1 is not O_NONBLOCK
Transferred: sent 3032, received 2196 bytes, in 0.0 seconds
Bytes per second: sent 99166.6, received 71823.9
debug1: Exit status 1
Comment 1 Karthikeyan 2019-07-30 21:13:03 AEST 
Created attachment 3304 [details]
sftp debug file
Comment 2 Karthikeyan 2019-07-30 21:14:14 AEST 
if i block the banner in /etc/ssh/sshd_config file it may not accure while do the sftp from openssh 6.6.1 to 7.4 server.
Comment 3 Damien Miller 2019-07-30 21:20:35 AEST 
These problems are usually caused by shell initialisation scripts (e.g. .bashrc) that produce output for non-interactive shells. You can test this using:

ssh [options] user@host true 2>/dev/null

If this produces any output then that is your problem.
Comment 4 Damien Miller 2019-07-30 21:26:06 AEST 
1416128883 = 0x54686973

0x54, 0x68, 0x69, 0x73 = "This"

It seems very likely that the remote system is producing a banner on stdout that is interfering with sftp.