[
https://issues.apache.org/jira/browse/VFS-766?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17085415#comment-17085415
]
Kevin Hollenshead commented on VFS-766:
---------------------------------------
Using 2.6 and JSch 0.1.55
I had this same issue and was able to narrow it down to JSch usage under the
covers in my situation. In
org.apache.commons.vfs2.provider.sftp.SftpFileSystem, the constructor has a
call to detectExecDisabled(), which attempts to use the exec channel to
determine if it is enabled and calls getUid(). getUid() attempts to execute "id
-u" and get the response. In my case, this is where it hung up (confirmed on an
RHEL server and locally in Windows running in the Eclipse debugger).
My organization normally locks down sftp accounts so that they do not have
interactive login capabilities. Every time I try with one of these accounts, I
get past password negotiation and then hang at this point. When I switched to
my normal login on the same server that does have interactive access, it worked
just fine and there was no delay.
I have been digging around in the source looking for a toggle/default way to
set execDisabled without having to make a call. I went so far as to clone the
code temporarily, hardcode the boolean to false and remove the call and re-ran
it. Lo and behold, it worked.
I can't say that this is related but the symptoms are the same. I would love to
contribute some mechanism to either skip the exec check or force a default to
false for cases where I know the exec channel is disabled. Since I'm new to the
codebase, not sure where to being here or what the best way might be.
> SftpClientFactory hangs at FileSystemManager.resolveFile(...)
> -------------------------------------------------------------
>
> Key: VFS-766
> URL: https://issues.apache.org/jira/browse/VFS-766
> Project: Commons VFS
> Issue Type: Bug
> Affects Versions: 2.5.0, 2.6.0
> Reporter: Jasper Teng
> Priority: Critical
>
> Issue: When trying to sftp, it hangs inside
> FileSystemManager.resolveFile(...).
>
> Libs in classpath used for testing:
> * commons-vfs2-2.6.0.jar / commons-vfs2-2.5.0.jar
> * commons-vfs2-jackrabbit2-2.5.0.jar
> * jackrabbit-webdav-2.20.0.jar
>
> Issue Log file (2.5.0 + Server X):
> {noformat}
> 25 Mar, 20:00:37,825 INFO main [SftpClientFactory$JSchLogger.log()]
> [65017ms] Connection established
> 25 Mar, 20:00:38,013 INFO main [SftpClientFactory$JSchLogger.log()]
> [65205ms] Remote version string: SSH-2.0-ProVide
> 25 Mar, 20:00:38,017 INFO main [SftpClientFactory$JSchLogger.log()]
> [65209ms] Local version string: SSH-2.0-JSCH-0.1.52
> ...snip...
> 25 Mar, 20:01:02,802 INFO main [SftpClientFactory$JSchLogger.log()]
> [89994ms] kex: server->client aes128-ctr hmac-md5 none
> 25 Mar, 20:01:02,809 INFO main [SftpClientFactory$JSchLogger.log()]
> [90001ms] kex: client->server aes128-ctr hmac-md5 none
> 25 Mar, 20:01:06,359 INFO main [SftpClientFactory$JSchLogger.log()]
> [93551ms] SSH_MSG_KEXDH_INIT sent
> 25 Mar, 20:01:06,363 INFO main [SftpClientFactory$JSchLogger.log()]
> [93555ms] expecting SSH_MSG_KEXDH_REPLY
> 25 Mar, 20:01:10,410 INFO main [SftpClientFactory$JSchLogger.log()]
> [97602ms] ssh_rsa_verify: signature true
> 25 Mar, 20:01:10,427 WARN main [SftpClientFactory$JSchLogger.log()]
> [97619ms] Permanently added 'mask.mask.mask' (RSA) to the list of known hosts.
> 25 Mar, 20:01:10,438 INFO main [SftpClientFactory$JSchLogger.log()]
> [97630ms] SSH_MSG_NEWKEYS sent
> 25 Mar, 20:01:10,625 INFO main [SftpClientFactory$JSchLogger.log()]
> [97817ms] SSH_MSG_NEWKEYS received
> 25 Mar, 20:01:10,709 INFO main [SftpClientFactory$JSchLogger.log()]
> [97901ms] SSH_MSG_SERVICE_REQUEST sent
> 25 Mar, 20:01:10,897 INFO main [SftpClientFactory$JSchLogger.log()]
> [98089ms] SSH_MSG_SERVICE_ACCEPT received
> 25 Mar, 20:01:11,098 INFO main [SftpClientFactory$JSchLogger.log()]
> [98290ms] Authentications that can continue:
> publickey,keyboard-interactive,password
> 25 Mar, 20:01:11,102 INFO main [SftpClientFactory$JSchLogger.log()]
> [98294ms] Next authentication method: publickey
> 25 Mar, 20:01:11,114 INFO main [SftpClientFactory$JSchLogger.log()]
> [98306ms] Authentications that can continue: password
> 25 Mar, 20:01:11,119 INFO main [SftpClientFactory$JSchLogger.log()]
> [98311ms] Next authentication method: password
> 25 Mar, 20:01:11,735 INFO main [SftpClientFactory$JSchLogger.log()]
> [98927ms] Authentication succeeded (password).{noformat}
>
> Issue Log file (2.6.0 + Server X):
> {noformat}
> 26 Mar, 09:42:07,781 INFO main [SftpClientFactory$JSchLogger.log()]
> [20400ms] Connection established
> 26 Mar, 09:42:07,971 INFO main [SftpClientFactory$JSchLogger.log()]
> [20590ms] Remote version string: SSH-2.0-ProVide
> 26 Mar, 09:42:07,975 INFO main [SftpClientFactory$JSchLogger.log()]
> [20594ms] Local version string: SSH-2.0-JSCH-0.1.52
> ...snip...
> 26 Mar, 09:42:33,250 INFO main [SftpClientFactory$JSchLogger.log()]
> [45869ms] kex: server->client aes128-ctr hmac-md5 none
> 26 Mar, 09:42:33,258 INFO main [SftpClientFactory$JSchLogger.log()]
> [45877ms] kex: client->server aes128-ctr hmac-md5 none
> 26 Mar, 09:42:36,710 INFO main [SftpClientFactory$JSchLogger.log()]
> [49329ms] SSH_MSG_KEXDH_INIT sent
> 26 Mar, 09:42:36,716 INFO main [SftpClientFactory$JSchLogger.log()]
> [49335ms] expecting SSH_MSG_KEXDH_REPLY
> 26 Mar, 09:42:40,635 INFO main [SftpClientFactory$JSchLogger.log()]
> [53254ms] ssh_rsa_verify: signature true
> 26 Mar, 09:42:40,653 INFO main [SftpClientFactory$JSchLogger.log()]
> [53272ms] Host 'mask.mask.mask' is known and matches the RSA host key
> 26 Mar, 09:42:40,660 INFO main [SftpClientFactory$JSchLogger.log()]
> [53279ms] SSH_MSG_NEWKEYS sent
> 26 Mar, 09:42:40,845 INFO main [SftpClientFactory$JSchLogger.log()]
> [53464ms] SSH_MSG_NEWKEYS received
> 26 Mar, 09:42:40,953 INFO main [SftpClientFactory$JSchLogger.log()]
> [53572ms] SSH_MSG_SERVICE_REQUEST sent
> 26 Mar, 09:42:41,153 INFO main [SftpClientFactory$JSchLogger.log()]
> [53772ms] SSH_MSG_SERVICE_ACCEPT received
> 26 Mar, 09:42:41,356 INFO main [SftpClientFactory$JSchLogger.log()]
> [53975ms] Authentications that can continue:
> publickey,keyboard-interactive,password
> 26 Mar, 09:42:41,359 INFO main [SftpClientFactory$JSchLogger.log()]
> [53978ms] Next authentication method: publickey
> 26 Mar, 09:42:41,370 INFO main [SftpClientFactory$JSchLogger.log()]
> [53989ms] Authentications that can continue: password
> 26 Mar, 09:42:41,374 INFO main [SftpClientFactory$JSchLogger.log()]
> [53993ms] Next authentication method: password
> 26 Mar, 09:42:42,388 INFO main [SftpClientFactory$JSchLogger.log()]
> [55007ms] Authentication succeeded (password).
> {noformat}
>
> Additional Important Notes:
> * commons-vfs2-2.4.1.jar works
> * issues can only be reproduced on certain sftp servers
>
> Non issue log file (2.4.1 + Server X):
> {noformat}
> 26 Mar, 09:56:29,747 INFO main [SftpClientFactory$JSchLogger.log()]
> [25083ms] Connection established
> 26 Mar, 09:56:29,948 INFO main [SftpClientFactory$JSchLogger.log()]
> [25284ms] Remote version string: SSH-2.0-ProVide
> 26 Mar, 09:56:29,961 INFO main [SftpClientFactory$JSchLogger.log()]
> [25297ms] Local version string: SSH-2.0-JSCH-0.1.52
> ...snip...
> 26 Mar, 09:56:57,870 INFO main [SftpClientFactory$JSchLogger.log()]
> [53206ms] kex: server->client aes128-ctr hmac-md5 none
> 26 Mar, 09:56:57,874 INFO main [SftpClientFactory$JSchLogger.log()]
> [53210ms] kex: client->server aes128-ctr hmac-md5 none
> 26 Mar, 09:57:01,314 INFO main [SftpClientFactory$JSchLogger.log()]
> [56650ms] SSH_MSG_KEXDH_INIT sent
> 26 Mar, 09:57:01,318 INFO main [SftpClientFactory$JSchLogger.log()]
> [56654ms] expecting SSH_MSG_KEXDH_REPLY
> 26 Mar, 09:57:05,237 INFO main [SftpClientFactory$JSchLogger.log()]
> [60573ms] ssh_rsa_verify: signature true
> 26 Mar, 09:57:05,253 INFO main [SftpClientFactory$JSchLogger.log()]
> [60589ms] Host 'mask.mask.mask' is known and matches the RSA host key
> 26 Mar, 09:57:05,258 INFO main [SftpClientFactory$JSchLogger.log()]
> [60594ms] SSH_MSG_NEWKEYS sent
> 26 Mar, 09:57:05,444 INFO main [SftpClientFactory$JSchLogger.log()]
> [60780ms] SSH_MSG_NEWKEYS received
> 26 Mar, 09:57:05,526 INFO main [SftpClientFactory$JSchLogger.log()]
> [60862ms] SSH_MSG_SERVICE_REQUEST sent
> 26 Mar, 09:57:05,713 INFO main [SftpClientFactory$JSchLogger.log()]
> [61049ms] SSH_MSG_SERVICE_ACCEPT received
> 26 Mar, 09:57:05,911 INFO main [SftpClientFactory$JSchLogger.log()]
> [61247ms] Authentications that can continue:
> publickey,keyboard-interactive,password
> 26 Mar, 09:57:05,915 INFO main [SftpClientFactory$JSchLogger.log()]
> [61251ms] Next authentication method: publickey
> 26 Mar, 09:57:05,927 INFO main [SftpClientFactory$JSchLogger.log()]
> [61263ms] Authentications that can continue: password
> 26 Mar, 09:57:05,931 INFO main [SftpClientFactory$JSchLogger.log()]
> [61267ms] Next authentication method: password
> 26 Mar, 09:57:06,567 INFO main [SftpClientFactory$JSchLogger.log()]
> [61903ms] Authentication succeeded (password).{noformat}
> Non issue log file (2.6.0 + Server A):
> {noformat}
> 26 Mar, 09:47:39,035 INFO main [SftpClientFactory$JSchLogger.log()] [1778ms]
> Connection established
> 26 Mar, 09:47:39,045 INFO main [SftpClientFactory$JSchLogger.log()] [1788ms]
> Remote version string: SSH-2.0-OpenSSH_6.2
> 26 Mar, 09:47:39,045 INFO main [SftpClientFactory$JSchLogger.log()] [1788ms]
> Local version string: SSH-2.0-JSCH-0.1.52
> ...snip...
> 26 Mar, 09:47:41,603 INFO main [SftpClientFactory$JSchLogger.log()] [4346ms]
> kex: server->client aes128-ctr hmac-md5 none
> 26 Mar, 09:47:41,604 INFO main [SftpClientFactory$JSchLogger.log()] [4347ms]
> kex: client->server aes128-ctr hmac-md5 none
> 26 Mar, 09:47:41,607 INFO main [SftpClientFactory$JSchLogger.log()] [4350ms]
> SSH_MSG_KEXDH_INIT sent
> 26 Mar, 09:47:41,607 INFO main [SftpClientFactory$JSchLogger.log()] [4350ms]
> expecting SSH_MSG_KEXDH_REPLY
> 26 Mar, 09:47:41,615 INFO main [SftpClientFactory$JSchLogger.log()] [4358ms]
> ssh_rsa_verify: signature true
> 26 Mar, 09:47:41,616 INFO main [SftpClientFactory$JSchLogger.log()] [4359ms]
> Host 'mask.mask.mask' is known and matches the RSA host key
> 26 Mar, 09:47:41,616 INFO main [SftpClientFactory$JSchLogger.log()] [4359ms]
> SSH_MSG_NEWKEYS sent
> 26 Mar, 09:47:41,616 INFO main [SftpClientFactory$JSchLogger.log()] [4359ms]
> SSH_MSG_NEWKEYS received
> 26 Mar, 09:47:41,621 INFO main [SftpClientFactory$JSchLogger.log()] [4364ms]
> SSH_MSG_SERVICE_REQUEST sent
> 26 Mar, 09:47:41,621 INFO main [SftpClientFactory$JSchLogger.log()] [4364ms]
> SSH_MSG_SERVICE_ACCEPT received
> 26 Mar, 09:47:41,626 INFO main [SftpClientFactory$JSchLogger.log()] [4369ms]
> Authentications that can continue: publickey,keyboard-interactive,password
> 26 Mar, 09:47:41,626 INFO main [SftpClientFactory$JSchLogger.log()] [4369ms]
> Next authentication method: publickey
> 26 Mar, 09:47:41,627 INFO main [SftpClientFactory$JSchLogger.log()] [4370ms]
> Authentications that can continue: keyboard-interactive,password
> 26 Mar, 09:47:41,627 INFO main [SftpClientFactory$JSchLogger.log()] [4370ms]
> Next authentication method: keyboard-interactive
> 26 Mar, 09:47:41,635 INFO main [SftpClientFactory$JSchLogger.log()] [4378ms]
> Authentication succeeded (keyboard-interactive).{noformat}
>
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
