Archived Forum Post
Index of archived forum posts
Question:
Archived Forum PostQuestion:
I have a remote client that for some reason fails to connect to our FTP server. All other remote clients using the same agent are able to connect successfully.
However with this remote client I'm not able to see why it's failing. I do not have access to the the remote client system. Below is the redacted client and server logs.
On the FTP server I can see in the log where the control channel was opened and that an AUTH 234 as sent, and then 60 seconds later that the control channel is closed.
Any help in determining where the error is or even where to start looking would be appreciated.
Client Log:
2012-11-12-03:55:29 --> OpenConnection
2012-11-12-03:55:29 --> FTP Connection:xxx.yyy.com:21
2012-11-12-03:55:29 --> ChilkatLog:
2012-11-12-03:55:29 --> UnlockComponent:
2012-11-12-03:55:29 --> DllDate: Nov 3 2012
2012-11-12-03:55:29 --> UnlockPrefix: xxxxxxx
2012-11-12-03:55:29 --> Username: xxxxxxxx
2012-11-12-03:55:29 --> Architecture: Little Endian; 32-bit
2012-11-12-03:55:29 --> Language: .NET 2.0
2012-11-12-03:55:29 --> VerboseLogging: 0
2012-11-12-03:55:29 --> component: Ftp2
2012-11-12-03:55:29 --> unlockCode: xxxxxxxx
2012-11-12-03:55:29 --> RegKey:
2012-11-12-03:55:29 --> LibDate: Oct 18 2012
2012-11-12-03:55:29 --> requiresPerm: 0
2012-11-12-03:55:29 --> re-parsing expire date...
2012-11-12-03:55:29 --> Component successfully unlocked using permanent unlock code.
2012-11-12-03:55:29 --> --RegKey
2012-11-12-03:55:29 --> --UnlockComponent
2012-11-12-03:55:29 --> --ChilkatLog
2012-11-12-03:55:29 -->
2012-11-12-03:55:29 --> FTPSecurityProtocol= AuthTls = True
2012-11-12-03:55:29 --> FTPConnectTimeout= 60
2012-11-12-03:55:29 --> FTP Connect xxx.yyy.com
2012-11-12-03:55:29 --> ftp_OnProgressInfo: SocketConnect :xxx.yyy.com:21
2012-11-12-03:55:29 --> ftp_OnProgressInfo: HostnameResolve : xxx.yyy.com
2012-11-12-03:55:29 --> ftp_OnProgressInfo: ResolvedToIp : xxx.yyy.com.zzz
2012-11-12-03:55:30 --> ftp_OnProgressInfo: SocketConnected : xxx.yyy.com:21
2012-11-12-03:55:30 --> ftp_OnProgressInfo: FtpCmdResp : 220 Microsoft FTP Service
2012-11-12-03:55:30 --> ftp_OnProgressInfo: FtpCmdSent : AUTH TLS
2012-11-12-03:55:30 --> ftp_OnProgressInfo: FtpCmdResp : 234 AUTH command ok. Expecting TLS Negotiation.
2012-11-12-03:55:30 --> ftp_OnProgressInfo: SslHandshake : Starting
2012-11-12-03:56:30 --> FTP Open Error: FTP.Connect Error:ChilkatLog:
2012-11-12-03:56:30 --> Connect_Ftp2:
2012-11-12-03:56:30 --> DllDate: Nov 3 2012
2012-11-12-03:56:30 --> UnlockPrefix: xxx
2012-11-12-03:56:30 --> Username: xxx
2012-11-12-03:56:30 --> Architecture: Little Endian; 32-bit
2012-11-12-03:56:30 --> Language: .NET 2.0
2012-11-12-03:56:30 --> VerboseLogging: 1
2012-11-12-03:56:30 --> ProgressMonitoring:
2012-11-12-03:56:30 --> enabled: yes
2012-11-12-03:56:30 --> heartbeatMs: 0
2012-11-12-03:56:30 --> sendBufferSize: 65536
2012-11-12-03:56:30 --> --ProgressMonitoring
2012-11-12-03:56:30 --> ImplicitSsl: 0
2012-11-12-03:56:30 --> AuthTls: 1
2012-11-12-03:56:30 --> AuthSsl: 0
2012-11-12-03:56:30 --> Hostname: xxx.yyy.com
2012-11-12-03:56:30 --> Port: 21
2012-11-12-03:56:30 --> IdleTimeoutMs: 60000
2012-11-12-03:56:30 --> ConnectTimeout: 60
2012-11-12-03:56:30 --> HeartbeatMs: 0
2012-11-12-03:56:30 --> ConnectTimeoutMs_1: 60000
2012-11-12-03:56:30 --> calling ConnectSocket2
2012-11-12-03:56:30 --> IPV6 enabled connect with NO heartbeat.
2012-11-12-03:56:30 --> connectingTo: xxx.yyy.com
2012-11-12-03:56:30 --> resolveHostname1:
2012-11-12-03:56:30 --> dnsCacheLookup: xxx.yyy.com
2012-11-12-03:56:30 --> Resolving domain name (IPV4)
2012-11-12-03:56:30 --> --resolveHostname1
2012-11-12-03:56:30 --> GetHostByNameHB_ipv4: Elapsed time: 109 millisec
2012-11-12-03:56:30 --> myIP_1: xxx.yyy.com.zzz
2012-11-12-03:56:30 --> myPort_1: 4182
2012-11-12-03:56:30 --> connect successful (1)
2012-11-12-03:56:30 --> Turning on TCP_NODELAY.
2012-11-12-03:56:30 --> socketOptions:
2012-11-12-03:56:30 --> SO_SNDBUF: 8192
2012-11-12-03:56:30 --> SO_RCVBUF: 8192
2012-11-12-03:56:30 --> TCP_NODELAY: 1
2012-11-12-03:56:30 --> --socketOptions
2012-11-12-03:56:30 --> initialStatus: 220
2012-11-12-03:56:30 --> initialResponse: 220 Microsoft FTP Service
2012-11-12-03:56:30 --> converting to secure connection...
2012-11-12-03:56:30 --> ssl_protocol_3: default
2012-11-12-03:56:30 --> ConvertToTls_4:
2012-11-12-03:56:30 --> establishChannel2_1:
2012-11-12-03:56:30 --> clientHandshake:
2012-11-12-03:56:30 --> clientHelloMajorMinorVersion: 3.1
2012-11-12-03:56:30 --> buildClientHello:
2012-11-12-03:56:30 --> majorVersion: 3
2012-11-12-03:56:30 --> minorVersion: 1
2012-11-12-03:56:30 --> numRandomBytes: 32
2012-11-12-03:56:30 --> sessionIdSize: 0
2012-11-12-03:56:30 --> numCipherSuites: 10
2012-11-12-03:56:30 --> numCompressionMethods: 1
2012-11-12-03:56:30 --> --buildClientHello
2012-11-12-03:56:30 --> Timeout waiting to read socket or accept connection
2012-11-12-03:56:30 --> timeoutMs: 60000
2012-11-12-03:56:30 --> Timed out waiting for incoming SSL/TLS messages.
2012-11-12-03:56:30 --> timeoutMs: 60000
2012-11-12-03:56:30 --> Expected ServerHello but did not receive it.
2012-11-12-03:56:30 --> --clientHandshake
2012-11-12-03:56:30 --> Client handshake failed. (1)
2012-11-12-03:56:30 --> connectionClosed: 0
2012-11-12-03:56:30 --> --establishChannel2_1
2012-11-12-03:56:30 --> --ConvertToTls_4
2012-11-12-03:56:30 --> Failed to convert channel to SSL/TLS
2012-11-12-03:56:30 --> Failed to connect to FTP server.
2012-11-12-03:56:30 --> Failed.
2012-11-12-03:56:30 --> --Connect_Ftp2
2012-11-12-03:56:30 --> --ChilkatLog
2012-11-12-03:56:30 -->
2012-11-12-03:56:30 --> SetProcessComplete()
2012-11-12-03:56:30 --> Sending Email
2012-11-12-03:56:36 --> AutoExit enabled. Complete
Server log:
2012-11-12 20:56:07 100.100.6.158 41079 - 200.200.126.250 21 ControlChannelOpened - - 0 0 0 000fc106-45f3-4ea9-9a6d-74511f2e323f -
2012-11-12 20:56:07 100.100.6.158 41079 - 200.200.126.250 21 AUTH TLS 234 0 0 10 000fc106-45f3-4ea9-9a6d-74511f2e323f -
2012-11-12 20:58:14 100.100.6.158 41079 - 200.200.126.250 21 ControlChannelClosed - - 258 0 0 000fc106-45f3-4ea9-9a6d-74511f2e323f -
The LastErrorText indicates that the server never responds to the ClientHello message which is what begins the SSL/TLS handshake. It should respond with a ServerHello. If this server is on an IP that I can access, then please provide the IP address. Testing would not require a login because we are only testing the establishment of the SSL/TLS channel, which comes before authentication.
I gave it a try and it worked fine for me. Here's my LastErrorText followed by the SessionLog
ChilkatLog:
ConnectOnly_Ftp2:
DllDate: Nov 12 2012
UnlockPrefix: UNTTSTFTP
Username: CK2007:Chilkat
Architecture: Little Endian; 32-bit
Language: .NET 2.0
VerboseLogging: 0
ProgressMonitoring:
enabled: yes
heartbeatMs: 0
sendBufferSize: 65536
--ProgressMonitoring
ImplicitSsl: 0
AuthTls: 1
AuthSsl: 0
Hostname: 173.192.126.250
Port: 21
IdleTimeoutMs: 60000
ConnectTimeout: 60
HeartbeatMs: 0
ConnectTimeoutMs_1: 60000
calling ConnectSocket2
IPV6 enabled connect with NO heartbeat.
This is an IPV4 numeric address...
AddrInfoList:
AddrInfo:
ai_flags: 4
ai_family: 2
ai_socktype: 1
ai_protocol: 0
ai_addrlen: 16
ai_canonname: (NULL)
--AddrInfo
--AddrInfoList
Connect using IPV4.
ipAddress1: 173.192.126.250
myIP_3: 192.168.1.115
myPort_3: 3822
connect successful (2)
Turning on TCP_NODELAY.
socketOptions:
SO_SNDBUF: 8192
SO_RCVBUF: 8192
TCP_NODELAY: 1
--socketOptions
initialStatus: 220
initialResponse: 220 Microsoft FTP Service
converting to secure connection...
sentCommand: AUTH TLS
receivedResponse: 234 AUTH command ok. Expecting TLS Negotiation.
ssl_protocol_3: default
ConvertToTls_4:
establishChannel2_1:
clientHandshake:
clientHelloMajorMinorVersion: 3.1
buildClientHello:
majorVersion: 3
minorVersion: 1
numRandomBytes: 32
sessionIdSize: 0
numCipherSuites: 10
numCompressionMethods: 1
--buildClientHello
handshakeMessageType: ServerHello
handshakeMessageLen: 0x46
processHandshakeMessage:
MessageType: ServerHello
Processing ServerHello...
ServerHello:
MajorVersion: 3
MinorVersion: 1
SessionIdLen: 32
CipherSuite: RSA_WITH_AES_128_CBC_SHA
CipherSuite: 00,2f
CompressionMethod: 0
Queueing ServerHello message.
ServerHello is OK.
--ServerHello
--processHandshakeMessage
handshakeMessageType: Certificate
handshakeMessageLen: 0x88b
processHandshakeMessage:
MessageType: Certificate
ProcessCertificates:
Certificate:
derSize: 1189
certSubjectCN: posbackup1.aptidata.com
certSerial: 017177
certIssuerCN: GeoTrust SSL CA
--Certificate
Certificate:
derSize: 989
certSubjectCN: GeoTrust SSL CA
certSerial: 0236D0
certIssuerCN: GeoTrust Global CA
--Certificate
NumCertificates: 2
Queueing Certificates message...
--ProcessCertificates
--processHandshakeMessage
handshakeMessageType: ServerHelloDone
handshakeMessageLen: 0x0
processHandshakeMessage:
MessageType: ServerHelloDone
Queueing HelloDone message.
--processHandshakeMessage
HandshakeQueue:
MessageType: ServerHello
MessageType: Certificate
MessageType: ServerHelloDone
--HandshakeQueue
Dequeued ServerHello message.
Dequeued Certificate message.
DequeuedMessageType: ServerHelloDone
OK to ServerHelloDone!
No client certificate required by the server.
Encrypted pre-master secret with server certificate RSA public key is OK.
Sending ClientKeyExchange...
Sent ClientKeyExchange message.
Sending ChangeCipherSpec...
Sent ChangeCipherSpec message.
Derived keys.
Installed new outgoing security params.
Sending FINISHED message..
algorithm: aes
keyLength: 128
Sent FINISHED message..
ccsProtocolType: 1
handshakeMessageType: HandshakeFinished
handshakeMessageLen: 0xc
processHandshakeMessage:
MessageType: HandshakeFinished
FinishedMsgLen: 12
Queueing Finished message.
--processHandshakeMessage
Dequeue the FINISHED message...
Dequeued Finished message.
Handshake completed successfully.
--clientHandshake
Secure Channel Established.
--establishChannel2_1
--ConvertToTls_4
isConnected: 1
successfully converted to secure connection...
Success.
--ConnectOnly_Ftp2
--ChilkatLog
220 Microsoft FTP Service
.
AUTH TLS
234 AUTH command ok. Expecting TLS Negotiation.
.
PBSZ 0
200 PBSZ command successful.
.
PROT P
200 PROT command successful.
Ok, could it be a firewall issue on the client restricting high port numbers for incoming requests? So that the FTP server is unable to respond with the 'hello' message?
Probably a firewall issue, or some sort of software on your client-side that blocks the communications. (If the problem was on the server-side, I'd experience the same issue.) It shouldn't be a port number issue. The FTP control connection to port 21 on the server was established. "Explicit SSL/TLS" means the unencrypted (normal) TCP connection is first established. (And that is successful in your case.) The next step is to convert the connection to SSL/TLS. The "AUTH TLS" command is sent to tell the server of the client's desire to do this, and the SSL/TLS connection handshake begins. The client sends the "ClientHello" and then expects to receive the server's "ServerHello", but it's getting blocked and the client times out