Hi,
We're having a problem with ftpsshproxy on z/OS v1.9 and AIX 5.3.
Our z/OS configuration is:
o Version 1.9
o ftpsshproxy-1.0.0.pax downloaded 10 August 2010 from http://www.dovetail.com/downloads/coz/index.html into
/usr/lpp/coz/ftpsshproxy-1.0.0
o Dataset MOGREN.FTP.DATA contains:
000001 FWFRIENDLY TRUE
000002 SOCKSCONFIGFILE 'MOGREN.FTP.SOCKS.CONF'
o Dataset MOGREN.FTP.SOCKS.CONF contains:
000001 DIRECT 127.0.0.1/32
000002 SOCKD5 @=127.0.0.1 172.20.0.0/16
o Output from "java -version:"
java version "1.6.0"
Java(TM) SE Runtime Environment (build pmz3160sr4-20090219_01(SR4))
IBM J9 VM (build 2.4, J2RE 1.6.0 IBM J9 2.4 z/OS s390-31 jvmmz3160-20090215_29883 (JIT enabled, AOT enabled)
J9VM - 20090215_029883_bHdSMr
JIT - r9_20090213_2028
GC - 20090213_AA)
JCL - 20090218_01
o /u/mogren/home/.ssh/config contains:
ClearAllForwardings yes
DynamicForward 127.0.0.1:1080
ForwardAgent yes
GatewayPorts yes
LocalForward 127.0.0.1:1080
LogLevel DEBUG3
And our AIX configuration is:
o Version 5300-10-02-0943
o Environment variable SOCKS5C_CONFIG=/etc/socks5c.conf
o /etc/socks5c.conf contains:
172.20.100.77 127.0.0.1:1080
o /home/mogren/.ssh/config contains:
DynamicForward *
ForwardAgent yes
GatewayPorts yes
LocalForward *
LogLevel DEBUG3
When we FTP from 172.20.100.77 to 172.20.100.77 (z/OS to itself), we get output like this:
# ./ftpsshproxy.sh -h 127.0.0.1:1080
2010-08-10 14:45:38,561 INFO ProxyServer - Co:Z FTP-SSH Proxy - version: 1.0.0
2010-08-10 14:45:38,648 INFO ProxyServer - Copyright (C) Dovetailed Technologies, LLC. 2008. All rights reserved.
2010-08-10 14:45:38,843 INFO ProxyServer - listening on 127.0.0.1:1080
2010-08-10 14:45:49,839 INFO ProxyConnection[/127.0.0.1:6784] - proxy negotiated to /172.20.100.77:21
2010-08-10 14:45:53,574 INFO FtpControlSession[/127.0.0.1:6784] - client login accepted for userid "MOGREN"
2010-08-10 14:46:27,707 INFO FtpControlSession[/127.0.0.1:6784] - SSH control channel started to 172.20.100.77:21
2010-08-10 14:46:29,121 INFO FtpControlSession[/127.0.0.1:6784] [/172.20.100.77:21] - server login accepted for userid "MOGREN"
2010-08-10 14:46:37,971 INFO FtpControlSession[/127.0.0.1:6784] [/172.20.100.77:21] - server registered passive port: 6792
2010-08-10 14:46:38,022 INFO ProxyConnection[/127.0.0.1:6793] - proxy negotiated to /172.20.100.77:6792
2010-08-10 14:46:38,129 INFO FtpControlSession[/127.0.0.1:6793] - SSH data channel started to 172.20.100.77:6792
2010-08-10 14:46:41,986 INFO FtpControlSession[/127.0.0.1:6784] [/172.20.100.77:21] - server registered passive port: 6797
2010-08-10 14:46:42,070 INFO ProxyConnection[/127.0.0.1:6798] - proxy negotiated to /172.20.100.77:6797
2010-08-10 14:46:42,174 WARN ProxyConnection[/127.0.0.1:6798] - Uncaught exception
java.io.IOException: channel is not opened.
at com.dovetail.ftpsshproxy.ProxyConnection.runProxySession(ProxyConnection.java:141)
at com.dovetail.ftpsshproxy.ProxyConnection.doRun(ProxyConnection.java:91)
at com.dovetail.ftpsshproxy.ProxyConnection.run(ProxyConnection.java:72)
at java.lang.Thread.run(Thread.java:735)
The server registers a passive port a couple of times in response to "ls" commands in the FTP client, and then Java abends.
When we FTP from 172.20.100.77 to 172.20.128.56 (z/OS to AIX) we get output like this:
2010-08-10 13:45:03,468 INFO ProxyConnection[/127.0.0.1:6778] - proxy negotiated to /172.20.128.85:21
2010-08-10 13:45:19,564 INFO FtpControlSession[/127.0.0.1:6778] - client login accepted for userid "mogren"
2010-08-10 13:45:20,591 WARN FtpControlSession[/127.0.0.1:6778] - Exception starting SSH tunnel
com.jcraft.jsch.JSchException: Auth fail
at com.jcraft.jsch.Session.connect(Session.java:452)
at com.dovetail.ftpsshproxy.FtpControlSession.startSshTunnel(FtpControlSession.java:232)
at com.dovetail.ftpsshproxy.FtpControlSession.startConnection(FtpControlSession.java:129)
at com.dovetail.ftpsshproxy.FtpControlSession.run(FtpControlSession.java:76)
at com.dovetail.ftpsshproxy.ProxyConnection.runProxySession(ProxyConnection.java:135)
at com.dovetail.ftpsshproxy.ProxyConnection.doRun(ProxyConnection.java:91)
at com.dovetail.ftpsshproxy.ProxyConnection.run(ProxyConnection.java:72)
at java.lang.Thread.run(Thread.java:735)
2010-08-10 13:45:20,605 INFO FtpControlSession[/127.0.0.1:6778] - disconnected SSH
2010-08-10 13:45:20,613 INFO ProxyConnection[/127.0.0.1:6778] - control connection closed
You can probably tell from the above that proxies are completely foreign to me, but from what I've read they're simple once you understand what's going on. Any assistance you can give us is greatly appreciated!
Thanks!
Roy Mogren
Systems Programmer II
Clark County, NV
E-mail: mogren@co.clark.nv.us
Phone: 702-455-6424
Cell: 702-280-5585
ftpsshproxy producing java.io.IOException: channel not open
-
Roy Mogren
- Posts: 4
- Joined: Tue Aug 03, 2010 6:19 pm
So, in the first log (z/OS to itself), you can connect and do a couple of "ls" commands before you get the error? From the log, it looks like the data connection socket to FTPD is failing to connect (there is a new data connection socket created by FTP for each command or transfer).
To debug this, you can add "-d" option to your invocation of the com.dovetail.ftpsshproxy.ProxyServer class. This will produce a trace file that you can email to info@dovetail.com and we will take a look.
In the second log, (z/OS to AIX), you are getting an error earlier... starting the FTP control connection socket. The error is that the SSH port-forwarding "channel" to your FTPD server on AIX won't start. Check your AIX SSHD logs and there may be more information. One cause of this would be that the AIX SSHD server is configured so that it doesn't allow port forwarding.
To debug this, you can add "-d" option to your invocation of the com.dovetail.ftpsshproxy.ProxyServer class. This will produce a trace file that you can email to info@dovetail.com and we will take a look.
In the second log, (z/OS to AIX), you are getting an error earlier... starting the FTP control connection socket. The error is that the SSH port-forwarding "channel" to your FTPD server on AIX won't start. Check your AIX SSHD logs and there may be more information. One cause of this would be that the AIX SSHD server is configured so that it doesn't allow port forwarding.
-
Roy Mogren
- Posts: 4
- Joined: Tue Aug 03, 2010 6:19 pm
ftpsshproxy producing java.io.IOException: channel not open
Thanks for your reply!
I'm also a Java duffer. What file contains the invocation of the com.dovetail.ftpsshproxy.ProxyServer class?
Regarding port forwarding, the AIX host's sshd_config file contains "AllowTcpForwarding yes" and "GatewayPorts yes," and ssh_config contains "ForwardAgent yes." Are there other setting that I've missed?
Also, I'm doing my tests interactively. ftpsshproxy isn't a batch only utility, is it?
Thanks again!
I'm also a Java duffer. What file contains the invocation of the com.dovetail.ftpsshproxy.ProxyServer class?
Regarding port forwarding, the AIX host's sshd_config file contains "AllowTcpForwarding yes" and "GatewayPorts yes," and ssh_config contains "ForwardAgent yes." Are there other setting that I've missed?
Also, I'm doing my tests interactively. ftpsshproxy isn't a batch only utility, is it?
Thanks again!
Have you checked the AIX sshd logs (normally in syslog) for the error reason?
You can run com.dovetail.ftpsshproxy.ProxyServer class interactively, but in this case you don't need to turn on tracing for the JZOS batch launcher (LOGLVL='+D')
You can add "-d" to the Java class main args to get a trace.
You can run com.dovetail.ftpsshproxy.ProxyServer class interactively, but in this case you don't need to turn on tracing for the JZOS batch launcher (LOGLVL='+D')
You can add "-d" to the Java class main args to get a trace.
-
Roy Mogren
- Posts: 4
- Joined: Tue Aug 03, 2010 6:19 pm
Here's the command I used to start the proxy on z/OS, along with the trace that was produced when I started a z/OS to AIX FTP session:
# ./ftpsshproxy.sh -h 127.0.0.1:1080 -d
2010-08-12 13:15:59,335 INFO ProxyServer - Co:Z FTP-SSH Proxy - version: 1.0.0
2010-08-12 13:15:59,397 INFO ProxyServer - Copyright (C) Dovetailed Technologies, LLC. 2008. All rights reserved.
2010-08-12 13:15:59,631 INFO ProxyServer - listening on 127.0.0.1:1080
2010-08-12 13:16:32,474 TRACE ProxyConnection[/127.0.0.1:7616] - ->doRun()
2010-08-12 13:16:32,500 TRACE ProxyConnection[/127.0.0.1:7616] - ->doProxyExchange()
2010-08-12 13:16:32,526 DEBUG AuthNegotiationRequest[/127.0.0.1:7616] - version=5 numMethods=1 methods=[0]
2010-08-12 13:16:32,546 DEBUG AuthNegotiationResponse[/127.0.0.1:7616] - version=5 method=0
2010-08-12 13:16:32,568 DEBUG SOCKS5Request[/127.0.0.1:7616] - version=5 addressType=1 command=1 destAddress=/172.20.128.85 destHostname=172.20.128.85 destPort=21
2010-08-12 13:16:32,593 DEBUG SOCKS5Response[/127.0.0.1:7616] - version=5 replyCode==0 boundAddress=/172.20.128.85 boundPort=21
2010-08-12 13:16:32,608 INFO ProxyConnection[/127.0.0.1:7616] - proxy negotiated to /172.20.128.85:21
2010-08-12 13:16:32,616 TRACE ProxyConnection[/127.0.0.1:7616] - <-doProxyExchange()
2010-08-12 13:16:32,675 DEBUG FtpControlSession[/127.0.0.1:7616] - C< 220 (Co:Z FtpSshProxy)
2010-08-12 13:16:37,095 DEBUG FtpControlSession[/127.0.0.1:7616] - C> USER mogren
2010-08-12 13:16:37,107 DEBUG FtpControlSession[/127.0.0.1:7616] - C< 331 Please specify the password.
***2010-08-12 13:16:44,599 DEBUG FtpControlSession[/127.0.0.1:7616] - C> PASS í***
2010-08-12 13:16:44,610 INFO FtpControlSession[/127.0.0.1:7616] - client login accepted for userid "mogren"
2010-08-12 13:17:18,794 WARN FtpControlSession[/127.0.0.1:7616] - Exception starting SSH tunnel
com.jcraft.jsch.JSchException: Auth fail
at com.jcraft.jsch.Session.connect(Session.java:452)
at com.dovetail.ftpsshproxy.FtpControlSession.startSshTunnel(FtpControlSession.java:232)
at com.dovetail.ftpsshproxy.FtpControlSession.startConnection(FtpControlSession.java:129)
at com.dovetail.ftpsshproxy.FtpControlSession.run(FtpControlSession.java:76)
at com.dovetail.ftpsshproxy.ProxyConnection.runProxySession(ProxyConnection.java:135)
at com.dovetail.ftpsshproxy.ProxyConnection.doRun(ProxyConnection.java:91)
at com.dovetail.ftpsshproxy.ProxyConnection.run(ProxyConnection.java:72)
at java.lang.Thread.run(Thread.java:735)
2010-08-12 13:17:18,832 DEBUG FtpControlSession[/127.0.0.1:7616] - C< 530 Auth fail
2010-08-12 13:17:18,866 INFO FtpControlSession[/127.0.0.1:7616] - disconnected SSH
2010-08-12 13:17:18,875 TRACE ProxyConnection[/127.0.0.1:7616] - <-doRun()
2010-08-12 13:17:18,890 INFO ProxyConnection[/127.0.0.1:7616] - control connection closed
I see that the password in the "***...***" line above starts with a "í" character. That's the next hurdle on the path to an AIX connection as that character is not part of my password, and I'll bet it's causing these entries in auth.log (didn't find anything useful in syslog.log):
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
When I tried to ftp from z/OS to z/OS, the connection succeeded and I discovered that it's not really abending as I reported initially. Instead, an ls command displays the list of files, and then there is a two minute wait for the "Command:" prompt to appear (you can see it after the Java IO exception). Here's the trace:
2010-08-12 15:41:32,449 TRACE ProxyConnection[/127.0.0.1:7636] - ->doRun()
2010-08-12 15:41:32,499 TRACE ProxyConnection[/127.0.0.1:7636] - ->doProxyExchange()
2010-08-12 15:41:32,514 DEBUG AuthNegotiationRequest[/127.0.0.1:7636] - version=5 numMethods=1 methods=[0]
2010-08-12 15:41:32,522 DEBUG AuthNegotiationResponse[/127.0.0.1:7636] - version=5 method=0
2010-08-12 15:41:32,530 DEBUG SOCKS5Request[/127.0.0.1:7636] - version=5 addressType=1 command=1 destAddress=/172.20.100.77 destHostname=172.20.100.77 destPort=21
2010-08-12 15:41:32,539 DEBUG SOCKS5Response[/127.0.0.1:7636] - version=5 replyCode==0 boundAddress=/172.20.100.77 boundPort=21
2010-08-12 15:41:32,551 INFO ProxyConnection[/127.0.0.1:7636] - proxy negotiated to /172.20.100.77:21
2010-08-12 15:41:32,558 TRACE ProxyConnection[/127.0.0.1:7636] - <-doProxyExchange()
2010-08-12 15:41:32,568 DEBUG FtpControlSession[/127.0.0.1:7636] - C< 220 (Co:Z FtpSshProxy)
2010-08-12 15:41:34,455 DEBUG FtpControlSession[/127.0.0.1:7636] - C> USER MOGREN
2010-08-12 15:41:34,464 DEBUG FtpControlSession[/127.0.0.1:7636] - C< 331 Please specify the password.
2010-08-12 15:41:39,858 DEBUG FtpControlSession[/127.0.0.1:7636] - C> PASS
2010-08-12 15:41:39,866 INFO FtpControlSession[/127.0.0.1:7636] - client login accepted for userid "MOGREN"
2010-08-12 15:41:42,405 INFO FtpControlSession[/127.0.0.1:7636] - SSH control channel started to 172.20.100.77:21
2010-08-12 15:41:43,308 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 220-FTPD1 IBM FTP CS V1R9 at BLUETEST.CO.CLARK.NV.US, 22:41:43 on 2010-08-12.
2010-08-12 15:41:43,326 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S> USER MOGREN
2010-08-12 15:41:43,341 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 220 Connection will close if idle for more than 5 minutes.
2010-08-12 15:41:44,299 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 331 Send password please.
2010-08-12 15:41:44,312 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S> PASS
2010-08-12 15:41:45,309 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 230 MOGREN is logged on. Working directory is "MOGREN.".
2010-08-12 15:41:45,317 INFO FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - server login accepted for userid "MOGREN"
2010-08-12 15:41:45,342 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C< 230 MOGREN is logged on. Working directory is "MOGREN.".
2010-08-12 15:41:50,388 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C> PASV
2010-08-12 15:41:50,400 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S> PASV
2010-08-12 15:41:50,413 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 227 Entering Passive Mode (127,0,0,1,29,217)
2010-08-12 15:41:50,421 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - pasv response addr: "127,0,0,1,29,217" countTokens=6
2010-08-12 15:41:50,434 DEBUG ProxyServer[/127.0.0.1:7636] [/172.20.100.77:21] - registered /172.20.100.77:7641
2010-08-12 15:41:50,440 INFO FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - server registered passive port: 7641
2010-08-12 15:41:50,446 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C< 227 Entering Passive Mode (172,20,100,77,29,217)
2010-08-12 15:41:50,454 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C> NLST
2010-08-12 15:41:50,464 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S> NLST
2010-08-12 15:41:50,470 TRACE ProxyConnection[/127.0.0.1:7642] - ->doRun()
2010-08-12 15:41:50,485 TRACE ProxyConnection[/127.0.0.1:7642] - ->doProxyExchange()
2010-08-12 15:41:50,495 DEBUG AuthNegotiationRequest[/127.0.0.1:7642] - version=5 numMethods=1 methods=[0]
2010-08-12 15:41:50,502 DEBUG AuthNegotiationResponse[/127.0.0.1:7642] - version=5 method=0
2010-08-12 15:41:50,524 DEBUG SOCKS5Request[/127.0.0.1:7642] - version=5 addressType=1 command=1 destAddress=/172.20.100.77 destHostname=172.20.100.77 destPort=7641
2010-08-12 15:41:50,545 DEBUG SOCKS5Response[/127.0.0.1:7642] - version=5 replyCode==0 boundAddress=/172.20.100.77 boundPort=7641
2010-08-12 15:41:50,563 INFO ProxyConnection[/127.0.0.1:7642] - proxy negotiated to /172.20.100.77:7641
2010-08-12 15:41:50,568 TRACE ProxyConnection[/127.0.0.1:7642] - <-doProxyExchange()
2010-08-12 15:41:50,621 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 125 List started OK
2010-08-12 15:41:50,627 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C< 125 List started OK
2010-08-12 15:41:50,641 WARN ProxyConnection[/127.0.0.1:7642] - Uncaught exception
java.io.IOException: channel is not opened.
at com.dovetail.ftpsshproxy.ProxyConnection.runProxySession(ProxyConnection.java:141)
at com.dovetail.ftpsshproxy.ProxyConnection.doRun(ProxyConnection.java:91)
at com.dovetail.ftpsshproxy.ProxyConnection.run(ProxyConnection.java:72)
at java.lang.Thread.run(Thread.java:735)
2010-08-12 15:43:50,628 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 250 List completed successfully.
2010-08-12 15:43:50,633 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C< 250 List completed successfully.
# ./ftpsshproxy.sh -h 127.0.0.1:1080 -d
2010-08-12 13:15:59,335 INFO ProxyServer - Co:Z FTP-SSH Proxy - version: 1.0.0
2010-08-12 13:15:59,397 INFO ProxyServer - Copyright (C) Dovetailed Technologies, LLC. 2008. All rights reserved.
2010-08-12 13:15:59,631 INFO ProxyServer - listening on 127.0.0.1:1080
2010-08-12 13:16:32,474 TRACE ProxyConnection[/127.0.0.1:7616] - ->doRun()
2010-08-12 13:16:32,500 TRACE ProxyConnection[/127.0.0.1:7616] - ->doProxyExchange()
2010-08-12 13:16:32,526 DEBUG AuthNegotiationRequest[/127.0.0.1:7616] - version=5 numMethods=1 methods=[0]
2010-08-12 13:16:32,546 DEBUG AuthNegotiationResponse[/127.0.0.1:7616] - version=5 method=0
2010-08-12 13:16:32,568 DEBUG SOCKS5Request[/127.0.0.1:7616] - version=5 addressType=1 command=1 destAddress=/172.20.128.85 destHostname=172.20.128.85 destPort=21
2010-08-12 13:16:32,593 DEBUG SOCKS5Response[/127.0.0.1:7616] - version=5 replyCode==0 boundAddress=/172.20.128.85 boundPort=21
2010-08-12 13:16:32,608 INFO ProxyConnection[/127.0.0.1:7616] - proxy negotiated to /172.20.128.85:21
2010-08-12 13:16:32,616 TRACE ProxyConnection[/127.0.0.1:7616] - <-doProxyExchange()
2010-08-12 13:16:32,675 DEBUG FtpControlSession[/127.0.0.1:7616] - C< 220 (Co:Z FtpSshProxy)
2010-08-12 13:16:37,095 DEBUG FtpControlSession[/127.0.0.1:7616] - C> USER mogren
2010-08-12 13:16:37,107 DEBUG FtpControlSession[/127.0.0.1:7616] - C< 331 Please specify the password.
***2010-08-12 13:16:44,599 DEBUG FtpControlSession[/127.0.0.1:7616] - C> PASS í***
2010-08-12 13:16:44,610 INFO FtpControlSession[/127.0.0.1:7616] - client login accepted for userid "mogren"
2010-08-12 13:17:18,794 WARN FtpControlSession[/127.0.0.1:7616] - Exception starting SSH tunnel
com.jcraft.jsch.JSchException: Auth fail
at com.jcraft.jsch.Session.connect(Session.java:452)
at com.dovetail.ftpsshproxy.FtpControlSession.startSshTunnel(FtpControlSession.java:232)
at com.dovetail.ftpsshproxy.FtpControlSession.startConnection(FtpControlSession.java:129)
at com.dovetail.ftpsshproxy.FtpControlSession.run(FtpControlSession.java:76)
at com.dovetail.ftpsshproxy.ProxyConnection.runProxySession(ProxyConnection.java:135)
at com.dovetail.ftpsshproxy.ProxyConnection.doRun(ProxyConnection.java:91)
at com.dovetail.ftpsshproxy.ProxyConnection.run(ProxyConnection.java:72)
at java.lang.Thread.run(Thread.java:735)
2010-08-12 13:17:18,832 DEBUG FtpControlSession[/127.0.0.1:7616] - C< 530 Auth fail
2010-08-12 13:17:18,866 INFO FtpControlSession[/127.0.0.1:7616] - disconnected SSH
2010-08-12 13:17:18,875 TRACE ProxyConnection[/127.0.0.1:7616] - <-doRun()
2010-08-12 13:17:18,890 INFO ProxyConnection[/127.0.0.1:7616] - control connection closed
I see that the password in the "***...***" line above starts with a "í" character. That's the next hurdle on the path to an AIX connection as that character is not part of my password, and I'll bet it's causing these entries in auth.log (didn't find anything useful in syslog.log):
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
Aug 12 13:19:26 ccentsyst01u auth|security:info sshd[1081474]: Failed password for mogren from 172.20.100.77 port 7617 ssh2
Aug 12 13:19:26 ccentsyst01u auth|security:info syslog: ssh: failed login attempt for mogren from bluetest.co.clark.nv.us
When I tried to ftp from z/OS to z/OS, the connection succeeded and I discovered that it's not really abending as I reported initially. Instead, an ls command displays the list of files, and then there is a two minute wait for the "Command:" prompt to appear (you can see it after the Java IO exception). Here's the trace:
2010-08-12 15:41:32,449 TRACE ProxyConnection[/127.0.0.1:7636] - ->doRun()
2010-08-12 15:41:32,499 TRACE ProxyConnection[/127.0.0.1:7636] - ->doProxyExchange()
2010-08-12 15:41:32,514 DEBUG AuthNegotiationRequest[/127.0.0.1:7636] - version=5 numMethods=1 methods=[0]
2010-08-12 15:41:32,522 DEBUG AuthNegotiationResponse[/127.0.0.1:7636] - version=5 method=0
2010-08-12 15:41:32,530 DEBUG SOCKS5Request[/127.0.0.1:7636] - version=5 addressType=1 command=1 destAddress=/172.20.100.77 destHostname=172.20.100.77 destPort=21
2010-08-12 15:41:32,539 DEBUG SOCKS5Response[/127.0.0.1:7636] - version=5 replyCode==0 boundAddress=/172.20.100.77 boundPort=21
2010-08-12 15:41:32,551 INFO ProxyConnection[/127.0.0.1:7636] - proxy negotiated to /172.20.100.77:21
2010-08-12 15:41:32,558 TRACE ProxyConnection[/127.0.0.1:7636] - <-doProxyExchange()
2010-08-12 15:41:32,568 DEBUG FtpControlSession[/127.0.0.1:7636] - C< 220 (Co:Z FtpSshProxy)
2010-08-12 15:41:34,455 DEBUG FtpControlSession[/127.0.0.1:7636] - C> USER MOGREN
2010-08-12 15:41:34,464 DEBUG FtpControlSession[/127.0.0.1:7636] - C< 331 Please specify the password.
2010-08-12 15:41:39,858 DEBUG FtpControlSession[/127.0.0.1:7636] - C> PASS
2010-08-12 15:41:39,866 INFO FtpControlSession[/127.0.0.1:7636] - client login accepted for userid "MOGREN"
2010-08-12 15:41:42,405 INFO FtpControlSession[/127.0.0.1:7636] - SSH control channel started to 172.20.100.77:21
2010-08-12 15:41:43,308 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 220-FTPD1 IBM FTP CS V1R9 at BLUETEST.CO.CLARK.NV.US, 22:41:43 on 2010-08-12.
2010-08-12 15:41:43,326 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S> USER MOGREN
2010-08-12 15:41:43,341 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 220 Connection will close if idle for more than 5 minutes.
2010-08-12 15:41:44,299 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 331 Send password please.
2010-08-12 15:41:44,312 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S> PASS
2010-08-12 15:41:45,309 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 230 MOGREN is logged on. Working directory is "MOGREN.".
2010-08-12 15:41:45,317 INFO FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - server login accepted for userid "MOGREN"
2010-08-12 15:41:45,342 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C< 230 MOGREN is logged on. Working directory is "MOGREN.".
2010-08-12 15:41:50,388 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C> PASV
2010-08-12 15:41:50,400 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S> PASV
2010-08-12 15:41:50,413 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 227 Entering Passive Mode (127,0,0,1,29,217)
2010-08-12 15:41:50,421 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - pasv response addr: "127,0,0,1,29,217" countTokens=6
2010-08-12 15:41:50,434 DEBUG ProxyServer[/127.0.0.1:7636] [/172.20.100.77:21] - registered /172.20.100.77:7641
2010-08-12 15:41:50,440 INFO FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - server registered passive port: 7641
2010-08-12 15:41:50,446 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C< 227 Entering Passive Mode (172,20,100,77,29,217)
2010-08-12 15:41:50,454 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C> NLST
2010-08-12 15:41:50,464 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S> NLST
2010-08-12 15:41:50,470 TRACE ProxyConnection[/127.0.0.1:7642] - ->doRun()
2010-08-12 15:41:50,485 TRACE ProxyConnection[/127.0.0.1:7642] - ->doProxyExchange()
2010-08-12 15:41:50,495 DEBUG AuthNegotiationRequest[/127.0.0.1:7642] - version=5 numMethods=1 methods=[0]
2010-08-12 15:41:50,502 DEBUG AuthNegotiationResponse[/127.0.0.1:7642] - version=5 method=0
2010-08-12 15:41:50,524 DEBUG SOCKS5Request[/127.0.0.1:7642] - version=5 addressType=1 command=1 destAddress=/172.20.100.77 destHostname=172.20.100.77 destPort=7641
2010-08-12 15:41:50,545 DEBUG SOCKS5Response[/127.0.0.1:7642] - version=5 replyCode==0 boundAddress=/172.20.100.77 boundPort=7641
2010-08-12 15:41:50,563 INFO ProxyConnection[/127.0.0.1:7642] - proxy negotiated to /172.20.100.77:7641
2010-08-12 15:41:50,568 TRACE ProxyConnection[/127.0.0.1:7642] - <-doProxyExchange()
2010-08-12 15:41:50,621 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 125 List started OK
2010-08-12 15:41:50,627 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C< 125 List started OK
2010-08-12 15:41:50,641 WARN ProxyConnection[/127.0.0.1:7642] - Uncaught exception
java.io.IOException: channel is not opened.
at com.dovetail.ftpsshproxy.ProxyConnection.runProxySession(ProxyConnection.java:141)
at com.dovetail.ftpsshproxy.ProxyConnection.doRun(ProxyConnection.java:91)
at com.dovetail.ftpsshproxy.ProxyConnection.run(ProxyConnection.java:72)
at java.lang.Thread.run(Thread.java:735)
2010-08-12 15:43:50,628 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - S< 250 List completed successfully.
2010-08-12 15:43:50,633 DEBUG FtpControlSession[/127.0.0.1:7636] [/172.20.100.77:21] - C< 250 List completed successfully.
In the z/OS -> AIX connection, the following trace line:
C> PASS í
... is what the proxy receives from your z/OS FTP client.
(All traces lines "C> ..." are for input received by the proxy from the z/OS FTP client).
This password provided by your z/OS FTP client is used to login to the remote SSHD server (which is failing) and after that it is used to tunnel through SSH and login to the remote FTP server.
So, in the AIX trace, the password given by the z/OS FTP client is failing to login to SSHD on AIX.
For the z/OS -> z/OS trace, there is a failure creating the tunneled data connection through SSH to the local z/OS sshd server. Check the z/OS sshd logs to see if you can find the cause.
C> PASS í
... is what the proxy receives from your z/OS FTP client.
(All traces lines "C> ..." are for input received by the proxy from the z/OS FTP client).
This password provided by your z/OS FTP client is used to login to the remote SSHD server (which is failing) and after that it is used to tunnel through SSH and login to the remote FTP server.
So, in the AIX trace, the password given by the z/OS FTP client is failing to login to SSHD on AIX.
For the z/OS -> z/OS trace, there is a failure creating the tunneled data connection through SSH to the local z/OS sshd server. Check the z/OS sshd logs to see if you can find the cause.
-
Roy Mogren
- Posts: 4
- Joined: Tue Aug 03, 2010 6:19 pm
I finally remembered that the EBCDIC-to-ASCII translation works for most, but not all, characters. I had some characters in my AIX password that z/OS wasn't able to translate correctly, and that's what was causing the z/OS-to-AIX connection failure.
As for z/OS-to-z/OS, I monitored the log files for sshd activity and collected entries like these:
Aug 13 14:07:09 BLUETEST sshd[16777377]: Port of Entry information retained for uid:0 pid:16777377.
Aug 13 14:07:32 BLUETEST sshd[16777377]: Accepted password for MOGREN from 172.20.100.77 port 8151 ssh2
Aug 13 14:07:44 BLUETEST sshd[50331810]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:07:48 BLUETEST FSUM1221 syslogd: last message repeated 2 times
Aug 13 14:09:59 BLUETEST sshd[50331810]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:23:57 BLUETEST sshd[166]: Port of Entry information retained for uid:0 pid:166.
Aug 13 14:23:58 BLUETEST sshd[166]: Accepted password for MOGREN from 172.20.100.77 port 8218 ssh2
Aug 13 14:26:15 BLUETEST sshd[16777383]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:36:09 BLUETEST sshd[33554598]: Port of Entry information retained for uid:0 pid:33554598.
Aug 13 14:36:10 BLUETEST sshd[33554598]: Accepted password for MOGREN from 172.20.100.77 port 8229 ssh2
Aug 13 14:36:25 BLUETEST sshd[50331815]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:38:31 BLUETEST sshd[50331815]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:39:46 BLUETEST sshd[50331814]: Port of Entry information retained for uid:0 pid:50331814.
Aug 13 14:39:48 BLUETEST sshd[50331814]: Accepted password for mogren from 172.20.100.77 port 8245 ssh2
Aug 13 14:42:53 BLUETEST sshd[83886247]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:43:43 BLUETEST sshd[83886247]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:45:54 BLUETEST sshd[83886247]: error: select: EDC5113I Bad file descriptor.
In spite of the bad file descriptor, the software does work (the I/O exception in the previous traces isn't an abend after all; the connection restarts after a two minute wait for a timeout), and we can use cozsftp instead of ftp for z/OS -> z/OS transfers.
At this point, I think we can call it good and move on. Thanks for your help!
As for z/OS-to-z/OS, I monitored the log files for sshd activity and collected entries like these:
Aug 13 14:07:09 BLUETEST sshd[16777377]: Port of Entry information retained for uid:0 pid:16777377.
Aug 13 14:07:32 BLUETEST sshd[16777377]: Accepted password for MOGREN from 172.20.100.77 port 8151 ssh2
Aug 13 14:07:44 BLUETEST sshd[50331810]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:07:48 BLUETEST FSUM1221 syslogd: last message repeated 2 times
Aug 13 14:09:59 BLUETEST sshd[50331810]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:23:57 BLUETEST sshd[166]: Port of Entry information retained for uid:0 pid:166.
Aug 13 14:23:58 BLUETEST sshd[166]: Accepted password for MOGREN from 172.20.100.77 port 8218 ssh2
Aug 13 14:26:15 BLUETEST sshd[16777383]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:36:09 BLUETEST sshd[33554598]: Port of Entry information retained for uid:0 pid:33554598.
Aug 13 14:36:10 BLUETEST sshd[33554598]: Accepted password for MOGREN from 172.20.100.77 port 8229 ssh2
Aug 13 14:36:25 BLUETEST sshd[50331815]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:38:31 BLUETEST sshd[50331815]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:39:46 BLUETEST sshd[50331814]: Port of Entry information retained for uid:0 pid:50331814.
Aug 13 14:39:48 BLUETEST sshd[50331814]: Accepted password for mogren from 172.20.100.77 port 8245 ssh2
Aug 13 14:42:53 BLUETEST sshd[83886247]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:43:43 BLUETEST sshd[83886247]: error: select: EDC5113I Bad file descriptor.
Aug 13 14:45:54 BLUETEST sshd[83886247]: error: select: EDC5113I Bad file descriptor.
In spite of the bad file descriptor, the software does work (the I/O exception in the previous traces isn't an abend after all; the connection restarts after a two minute wait for a timeout), and we can use cozsftp instead of ftp for z/OS -> z/OS transfers.
At this point, I think we can call it good and move on. Thanks for your help!