jsch icon indicating copy to clipboard operation
jsch copied to clipboard

Published 20 hours ago • verified publisher icon mwiede

error in channel connection

Open luca-ma opened this issue 1 year ago • 7 comments

I'm working with the original Jsch library (com.jcraft.jsch v. 0.1.55) to send and receive files to an sftp server

I switched to the library (com.github.mwiede.jsch, v. 0.2.16) but I've an error in channel connection

This is my code

	JSch jsch = new JSch();
    Session session = null;
    Channel channel = null;
	
	session = jsch.getSession(
				"username",
				"server", 
				port);
	java.util.Properties config = new java.util.Properties(); 
	config.put("StrictHostKeyChecking", "no");
	session.setConfig(config);
		
	session.setPassword(System.getProperty("password"));
		
    session.connect(60*1000);
		
    channel = session.openChannel("sftp");
    boolean closed = channel.isClosed();  //prints false
    boolean connected = channel.isConnected();//prints false
    channel.connect(60000); //here raise com.jcraft.jsch.JSchException: channel is not opened.

Can anyone give me a suggestion?

luca-ma avatar Jan 20 '24 09:01 luca-ma

Please use one of the loggers to show the output of the logs. My first guess is that you use ssh-rsa which is deactivated by default in the fork.

mwiede avatar Jan 20 '24 12:01 mwiede

I'm sorry I don't understand which logs you are referring to and, if so, how to activate them can you give an example? thank you very much

luca-ma avatar Jan 20 '24 12:01 luca-ma

The fork includes a few built-in loggers for various frameworks, see JplLogger, JulLogger, Log4j2Logger & Slf4jLogger. Any of the above loggers can be enabled with the JSch.setLogger(), JSch.setInstanceLogger() or Session.setLogger() methods.

mwiede avatar Jan 20 '24 13:01 mwiede

Ok I've added JplLogger private final static Logger log = new JplLogger(); .... JSch.setLogger(log);

and my test logs are as follows:

Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Connecting to xx.yyy.it port 8022 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Connection established Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Remote version string: SSH-2.0-SSHD Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Local version string: SSH-2.0-JSCH_0.2.16 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: CheckCiphers: [email protected] Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: CheckKexes: [email protected],curve25519-sha256,[email protected],curve448-sha512 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: [email protected] is not available. Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: CheckSignatures: ssh-ed25519,ssh-ed448 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: ssh-ed25519 is not available. Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: ssh-ed448 is not available. Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_KEXINIT sent Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_KEXINIT received Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: ext-info messaging supported by server Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: KEX algorithms: rsa2048-sha256,diffie-hellman-group18-sha512,diffie-hellman-group17-sha512,diffie-hellman-group16-sha512,diffie-hellman-group15-sha512,diffie-hellman-group14-sha256,diffie-hellman-group-exchange-sha256,ecdh-sha2-nistp384,curve25519-sha256,[email protected],ecdh-sha2-nistp521,ecdh-sha2-nistp256,ext-info-s Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: ciphers c2s: aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: ciphers s2c: aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: MACs c2s: hmac-sha2-256,[email protected],hmac-sha2-512,[email protected] Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: MACs s2c: hmac-sha2-256,[email protected],hmac-sha2-512,[email protected] Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: compression c2s: none,zlib Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: compression s2c: none,zlib Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: languages c2s: Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server proposal: languages s2c: Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: KEX algorithms: curve25519-sha256,[email protected],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,ext-info-c,[email protected] Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: host key algorithms: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: ciphers c2s: aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: ciphers s2c: aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: MACs c2s: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: MACs s2c: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: compression c2s: none Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: compression s2c: none Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: languages c2s: Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: client proposal: languages s2c: Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: kex: algorithm: curve25519-sha256 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: kex: host key algorithm: rsa-sha2-512 Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: kex: server->client cipher: aes128-ctr MAC: [email protected] compression: none Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: kex: client->server cipher: aes128-ctr MAC: [email protected] compression: none Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_KEX_ECDH_INIT sent Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: expecting SSH_MSG_KEX_ECDH_REPLY Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: ssh_rsa_verify: rsa-sha2-512 signature true Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log WARNING: Permanently added '[xx.yy.it]:8022' (RSA) to the list of known hosts. Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_NEWKEYS sent Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_NEWKEYS received Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_EXT_INFO sent Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_SERVICE_REQUEST sent Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_EXT_INFO received Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: server-sig-algs=<ssh-rsa,x509v3-rsa2048-sha256,rsa-sha2-256,rsa-sha2-512> Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: SSH_MSG_SERVICE_ACCEPT received Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Authentications that can continue: publickey,keyboard-interactive,password Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Next authentication method: publickey Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Authentications that can continue: keyboard-interactive,password Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Next authentication method: keyboard-interactive Jan 20, 2024 5:00:12 PM com.jcraft.jsch.JplLogger log INFO: Authentication succeeded (keyboard-interactive). [24-01-20 17:00:12.424] {RMI TCP Connection(4)-192.168.56.1} Connecting to xx.yyy.it port 8022 [24-01-20 17:00:12.459] {RMI TCP Connection(4)-192.168.56.1} Connection established [24-01-20 17:00:12.469] {RMI TCP Connection(4)-192.168.56.1} Remote version string: SSH-2.0-SSHD [24-01-20 17:00:12.470] {RMI TCP Connection(4)-192.168.56.1} Local version string: SSH-2.0-JSCH_0.2.16 [24-01-20 17:00:12.470] {RMI TCP Connection(4)-192.168.56.1} CheckCiphers: [email protected] [24-01-20 17:00:12.471] {RMI TCP Connection(4)-192.168.56.1} CheckKexes: [email protected],curve25519-sha256,[email protected],curve448-sha512 [24-01-20 17:00:12.509] {RMI TCP Connection(4)-192.168.56.1} [email protected] is not available. [24-01-20 17:00:12.509] {RMI TCP Connection(4)-192.168.56.1} CheckSignatures: ssh-ed25519,ssh-ed448 [24-01-20 17:00:12.514] {RMI TCP Connection(4)-192.168.56.1} ssh-ed25519 is not available. [24-01-20 17:00:12.514] {RMI TCP Connection(4)-192.168.56.1} ssh-ed448 is not available. [24-01-20 17:00:12.518] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_KEXINIT sent [24-01-20 17:00:12.519] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_KEXINIT received [24-01-20 17:00:12.519] {RMI TCP Connection(4)-192.168.56.1} ext-info messaging supported by server [24-01-20 17:00:12.519] {RMI TCP Connection(4)-192.168.56.1} server proposal: KEX algorithms: rsa2048-sha256,diffie-hellman-group18-sha512,diffie-hellman-group17-sha512,diffie-hellman-group16-sha512,diffie-hellman-group15-sha512,diffie-hellman-group14-sha256,diffie-hellman-group-exchange-sha256,ecdh-sha2-nistp384,curve25519-sha256,[email protected],ecdh-sha2-nistp521,ecdh-sha2-nistp256,ext-info-s [24-01-20 17:00:12.520] {RMI TCP Connection(4)-192.168.56.1} server proposal: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256 [24-01-20 17:00:12.520] {RMI TCP Connection(4)-192.168.56.1} server proposal: ciphers c2s: aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [24-01-20 17:00:12.520] {RMI TCP Connection(4)-192.168.56.1} server proposal: ciphers s2c: aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [24-01-20 17:00:12.520] {RMI TCP Connection(4)-192.168.56.1} server proposal: MACs c2s: hmac-sha2-256,[email protected],hmac-sha2-512,[email protected] [24-01-20 17:00:12.520] {RMI TCP Connection(4)-192.168.56.1} server proposal: MACs s2c: hmac-sha2-256,[email protected],hmac-sha2-512,[email protected] [24-01-20 17:00:12.521] {RMI TCP Connection(4)-192.168.56.1} server proposal: compression c2s: none,zlib [24-01-20 17:00:12.521] {RMI TCP Connection(4)-192.168.56.1} server proposal: compression s2c: none,zlib [24-01-20 17:00:12.521] {RMI TCP Connection(4)-192.168.56.1} server proposal: languages c2s: [24-01-20 17:00:12.522] {RMI TCP Connection(4)-192.168.56.1} server proposal: languages s2c: [24-01-20 17:00:12.522] {RMI TCP Connection(4)-192.168.56.1} client proposal: KEX algorithms: curve25519-sha256,[email protected],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,ext-info-c,[email protected] [24-01-20 17:00:12.523] {RMI TCP Connection(4)-192.168.56.1} client proposal: host key algorithms: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256 [24-01-20 17:00:12.523] {RMI TCP Connection(4)-192.168.56.1} client proposal: ciphers c2s: aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [24-01-20 17:00:12.523] {RMI TCP Connection(4)-192.168.56.1} client proposal: ciphers s2c: aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [24-01-20 17:00:12.524] {RMI TCP Connection(4)-192.168.56.1} client proposal: MACs c2s: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [24-01-20 17:00:12.524] {RMI TCP Connection(4)-192.168.56.1} client proposal: MACs s2c: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [24-01-20 17:00:12.524] {RMI TCP Connection(4)-192.168.56.1} client proposal: compression c2s: none [24-01-20 17:00:12.524] {RMI TCP Connection(4)-192.168.56.1} client proposal: compression s2c: none [24-01-20 17:00:12.525] {RMI TCP Connection(4)-192.168.56.1} client proposal: languages c2s: [24-01-20 17:00:12.525] {RMI TCP Connection(4)-192.168.56.1} client proposal: languages s2c: [24-01-20 17:00:12.527] {RMI TCP Connection(4)-192.168.56.1} kex: algorithm: curve25519-sha256 [24-01-20 17:00:12.527] {RMI TCP Connection(4)-192.168.56.1} kex: host key algorithm: rsa-sha2-512 [24-01-20 17:00:12.527] {RMI TCP Connection(4)-192.168.56.1} kex: server->client cipher: aes128-ctr MAC: [email protected] compression: none [24-01-20 17:00:12.527] {RMI TCP Connection(4)-192.168.56.1} kex: client->server cipher: aes128-ctr MAC: [email protected] compression: none [24-01-20 17:00:12.530] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_KEX_ECDH_INIT sent [24-01-20 17:00:12.530] {RMI TCP Connection(4)-192.168.56.1} expecting SSH_MSG_KEX_ECDH_REPLY [24-01-20 17:00:12.556] {RMI TCP Connection(4)-192.168.56.1} ssh_rsa_verify: rsa-sha2-512 signature true [24-01-20 17:00:12.556] {RMI TCP Connection(4)-192.168.56.1} Permanently added '[xx.yy.it]:8022' (RSA) to the list of known hosts. [24-01-20 17:00:12.557] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_NEWKEYS sent [24-01-20 17:00:12.557] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_NEWKEYS received [24-01-20 17:00:12.570] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_EXT_INFO sent [24-01-20 17:00:12.571] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_SERVICE_REQUEST sent [24-01-20 17:00:12.572] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_EXT_INFO received [24-01-20 17:00:12.572] {RMI TCP Connection(4)-192.168.56.1} server-sig-algs=<ssh-rsa,x509v3-rsa2048-sha256,rsa-sha2-256,rsa-sha2-512> [24-01-20 17:00:12.581] {RMI TCP Connection(4)-192.168.56.1} SSH_MSG_SERVICE_ACCEPT received [24-01-20 17:00:12.591] {RMI TCP Connection(4)-192.168.56.1} Authentications that can continue: publickey,keyboard-interactive,password [24-01-20 17:00:12.591] {RMI TCP Connection(4)-192.168.56.1} Next authentication method: publickey [24-01-20 17:00:12.592] {RMI TCP Connection(4)-192.168.56.1} Authentications that can continue: keyboard-interactive,password [24-01-20 17:00:12.592] {RMI TCP Connection(4)-192.168.56.1} Next authentication method: keyboard-interactive [24-01-20 17:00:12.659] {RMI TCP Connection(4)-192.168.56.1} Authentication succeeded (keyboard-interactive). Jan 20, 2024 5:00:49 PM com.caucho.util.AlarmClock dispatch WARNING: AlarmClock slow alarm Alarm[alarm[com.caucho.server.distcache.DataStore$DeleteAlarm@4f7c0be3]] 52749ms coordinator-delta 63382ms [24-01-20 17:00:49.353] {CoordinatorThread[]-3} AlarmClock slow alarm Alarm[alarm[com.caucho.server.distcache.DataStore$DeleteAlarm@4f7c0be3]] 52749ms coordinator-delta 63382ms Jan 20, 2024 5:00:49 PM com.caucho.util.AlarmClock dispatch WARNING: AlarmClock slow alarm Alarm[alarm[SessionManager[/xxx]]] 45831ms coordinator-delta 63383ms [24-01-20 17:00:49.354] {CoordinatorThread[]-3} AlarmClock slow alarm Alarm[alarm[SessionManager[/xx]]] 45831ms coordinator-delta 63383ms Jan 20, 2024 5:00:49 PM com.caucho.util.AlarmClock dispatch WARNING: AlarmClock slow alarm Alarm[alarm[ServletService[id=default,cluster=]]] 43473ms coordinator-delta 63384ms [24-01-20 17:00:49.354] {CoordinatorThread[]-3} AlarmClock slow alarm Alarm[alarm[ServletService[id=default,cluster=]]] 43473ms coordinator-delta 63384ms Jan 20, 2024 5:00:49 PM com.caucho.util.AlarmClock dispatch WARNING: AlarmClock slow alarm Alarm[alarm[DeployControllerAlarm[null]]] 43473ms coordinator-delta 63384ms [24-01-20 17:00:49.355] {CoordinatorThread[]-3} AlarmClock slow alarm Alarm[alarm[DeployControllerAlarm[null]]] 43473ms coordinator-delta 63384ms Jan 20, 2024 5:00:49 PM com.caucho.util.AlarmClock dispatch WARNING: AlarmClock slow alarm Alarm[alarm[com.caucho.network.listen.TcpPort$SuspendReaper@4d228131]] 43458ms coordinator-delta 63385ms [24-01-20 17:00:49.356] {CoordinatorThread[]-3} AlarmClock slow alarm Alarm[alarm[com.caucho.network.listen.TcpPort$SuspendReaper@4d228131]] 43458ms coordinator-delta 63385ms Jan 20, 2024 5:00:49 PM com.caucho.util.AlarmClock dispatch WARNING: AlarmClock slow alarm Alarm[alarm[DeployControllerAlarm[null]]] 43440ms coordinator-delta 63386ms [24-01-20 17:00:49.356] {CoordinatorThread[]-3} AlarmClock slow alarm Alarm[alarm[DeployControllerAlarm[null]]] 43440ms coordinator-delta 63386ms com.jcraft.jsch.JSchException: channel is not opened. at com.jcraft.jsch.Channel.sendChannelOpen(Channel.java:832) at com.jcraft.jsch.Channel.connect(Channel.java:161)

thanks

luca-ma avatar Jan 20 '24 16:01 luca-ma

let me know if you need any other log or any other information for analyzing my problem

luca-ma avatar Jan 22 '24 07:01 luca-ma

are you sure, that the issue comes from switching the library? When looking at google results, it seems, it's a popular issue which is caused by timeout and server workload.

does it occur always or just sometimes? have you looked at the server logs?

mwiede avatar Jan 22 '24 07:01 mwiede

yes you're right I get the same error even with the original library, there must be a reachability problem... Thank you

luca-ma avatar Jan 23 '24 09:01 luca-ma