why so s-l-o-w to one particular site?

jim_h

2008-06-02 21:17:57

I recently switched to a new internet provider and immediately began having great difficulty with FTP to one particular site, which used to present no problems. Nothing else in my system has changed - just a new ISP and network carrier.

The transfer eventually completes, but very, very slowly - in bursts of about 40k every 30 seconds. Transfers to and from other servers are fine. Can someone at least give me a starting point for debugging this?

[16:07:05] The operation has been added to the Transfer Queue. Check the Transfer Queue for the status.
[16:07:36] NOOP
[16:07:36] 200 noop
[16:08:06] NOOP
[16:08:06] 200 noop
[16:08:20] MLST DSC_0137.jpg
[16:08:20] 250-MLST listing for DSC_0137.jpg
[16:08:20] size=41400;type=file;perm=fdrwa;create=20080602210812;modify=20080529191753; DSC_0137.jpg
[16:08:20] 250 end
[16:08:50] NOOP
[16:08:50] 200 noop
[16:08:51] MLST DSC_0137.jpg
[16:08:51] 250-MLST listing for DSC_0137.jpg
[16:08:51] size=82800;type=file;perm=fdrwa;create=20080602210812;modify=20080529191753; DSC_0137.jpg
[16:08:51] 250 end
[16:09:22] NOOP
[16:09:22] 200 noop
[16:09:22] MLST DSC_0137.jpg
[16:09:22] 250-MLST listing for DSC_0137.jpg
[16:09:22] size=124200;type=file;perm=fdrwa;create=20080602210812;modify=20080529191753; DSC_0137.jpg
[16:09:23] 250 end
[16:09:53] NOOP
[16:09:53] 200 noop
[16:09:53] MLST DSC_0137.jpg
[16:09:53] 250-MLST listing for DSC_0137.jpg
[16:09:53] size=166980;type=file;perm=fdrwa;create=20080602210812;modify=20080529191753; DSC_0137.jpg
[16:09:53] 250 end
[16:10:24] NOOP
[16:10:24] 200 noop
[16:10:27] MLST DSC_0137.jpg
[16:10:27] 250-MLST listing for DSC_0137.jpg
[16:10:27] size=208380;type=file;perm=fdrwa;create=20080602210812;modify=20080529191753; DSC_0137.jpg
[16:10:27] 250 end
[16:10:57] NOOP
[16:10:57] 200 noop
[16:10:58] MLST DSC_0137.jpg
[16:10:58] 250-MLST listing for DSC_0137.jpg
[16:10:59] size=269100;type=file;perm=fdrwa;create=20080602210812;modify=20080529191753; DSC_0137.jpg
[16:10:59] 250 end

2008-06-02 23:13:25

Post the log from the transfer queue item.

jim_h

2008-06-03 00:53:42

Post the log from the transfer queue item.

[2008-06-02T19:49:32] Log opened
[2008-06-02T19:49:32] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:49:32] Resolving host name "ftp.whcc.com"
[2008-06-02T19:49:32] Connecting to 208.42.68.51 Port: 21
[2008-06-02T19:49:32] Connected to ftp.whcc.com.
[2008-06-02T19:49:32] 220 ftpserver.lab.whcc.com X2 WS_FTP Server 5.0.1 (3297913375)
[2008-06-02T19:49:32] USER 33216
[2008-06-02T19:49:32] 331 Password required
[2008-06-02T19:49:32] PASS (hidden)
[2008-06-02T19:49:32] 230 user logged in
[2008-06-02T19:49:32] SYST
[2008-06-02T19:49:32] 215 UNIX
[2008-06-02T19:49:32] Detected Server Type: UNIX
[2008-06-02T19:49:32] FEAT
[2008-06-02T19:49:32] 211-Extensions supported
[2008-06-02T19:49:32] SIZE
[2008-06-02T19:49:32] MDTM
[2008-06-02T19:49:32] MLST size*;type*;perm*;create*;modify*;
[2008-06-02T19:49:32] LANG EN*
[2008-06-02T19:49:32] REST STREAM
[2008-06-02T19:49:32] TVFS
[2008-06-02T19:49:32] UTF8
[2008-06-02T19:49:32] AUTH SSL;TLS-P;
[2008-06-02T19:49:32] PBSZ
[2008-06-02T19:49:32] PROT C;P;
[2008-06-02T19:49:32] 211 end
[2008-06-02T19:49:32] Detected Server Software: WS_FTP Server
[2008-06-02T19:49:32] OPTS UTF8 ON
[2008-06-02T19:49:32] 501 invalid option
[2008-06-02T19:49:32] SITE UTF8
[2008-06-02T19:49:33] 200 UTF8 encoding forced.
[2008-06-02T19:49:33] PWD
[2008-06-02T19:49:33] 257 "/33216" is current directory
[2008-06-02T19:49:33] CWD /33216/PROCESSING/test
[2008-06-02T19:49:33] 250 CWD successful
[2008-06-02T19:49:33] PWD
[2008-06-02T19:49:33] 257 "/33216/PROCESSING/test" is current directory
[2008-06-02T19:49:33] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:49:33] MLST DSC_0137.jpg
[2008-06-02T19:49:33] 550 no file
[2008-06-02T19:49:33] TYPE I
[2008-06-02T19:49:33] 200 Type set to IMAGE.
[2008-06-02T19:49:33] PASV
[2008-06-02T19:49:33] 227 Entering Passive Mode (208,42,68,51,10,46).
[2008-06-02T19:49:33] Opening data connection to 208.42.68.51 Port: 2606
[2008-06-02T19:49:33] STOR DSC_0137.jpg
[2008-06-02T19:49:33] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:49:33] 425 transfer canceled
[2008-06-02T19:49:33] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:49:33] 200 action completed
[2008-06-02T19:49:33] Transfer failed.
[2008-06-02T19:49:33] Log closed
[2008-06-02T19:50:03] Log opened
[2008-06-02T19:50:03] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:50:03] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:50:03] MLST DSC_0137.jpg
[2008-06-02T19:50:03] 250-MLST listing for DSC_0137.jpg
[2008-06-02T19:50:03] size=41400;type=file;perm=fdrwa;create=20080603004926;modify=20080529191753; DSC_0137.jpg
[2008-06-02T19:50:03] 250 end
[2008-06-02T19:50:03] Source File: Size=1897474, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Exact
[2008-06-02T19:50:03] Destination File: Size=41400, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Not Exact
[2008-06-02T19:50:03] RecentTime=2008-06-03T00:49:33
[2008-06-02T19:50:03] Rule "IF Destination Time=Recent AND Size=Smaller AND Transfer=No Matter THEN Resume" matched. Action="Resume".
[2008-06-02T19:50:03] PASV
[2008-06-02T19:50:03] 227 Entering Passive Mode (208,42,68,51,10,87).
[2008-06-02T19:50:03] Opening data connection to 208.42.68.51 Port: 2647
[2008-06-02T19:50:03] REST 41400
[2008-06-02T19:50:03] 350 setting restart marker to 41400
[2008-06-02T19:50:03] STOR DSC_0137.jpg
[2008-06-02T19:50:03] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:50:04] 425 transfer canceled
[2008-06-02T19:50:04] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:50:04] 200 action completed
[2008-06-02T19:50:04] Transfer failed.
[2008-06-02T19:50:04] Log closed
[2008-06-02T19:50:34] Log opened
[2008-06-02T19:50:34] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:50:34] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:50:34] MLST DSC_0137.jpg
[2008-06-02T19:50:34] 250-MLST listing for DSC_0137.jpg
[2008-06-02T19:50:34] size=82800;type=file;perm=fdrwa;create=20080603004926;modify=20080529191753; DSC_0137.jpg
[2008-06-02T19:50:34] 250 end
[2008-06-02T19:50:34] Source File: Size=1897474, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Exact
[2008-06-02T19:50:34] Destination File: Size=82800, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Not Exact
[2008-06-02T19:50:34] RecentTime=2008-06-03T00:50:04
[2008-06-02T19:50:34] Rule "IF Destination Time=Recent AND Size=Smaller AND Transfer=No Matter THEN Resume" matched. Action="Resume".
[2008-06-02T19:50:34] PASV
[2008-06-02T19:50:34] 227 Entering Passive Mode (208,42,68,51,10,123).
[2008-06-02T19:50:34] Opening data connection to 208.42.68.51 Port: 2683
[2008-06-02T19:50:34] REST 82800
[2008-06-02T19:50:34] 350 setting restart marker to 82800
[2008-06-02T19:50:34] STOR DSC_0137.jpg
[2008-06-02T19:50:34] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:50:35] 425 transfer canceled
[2008-06-02T19:50:35] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:50:35] 200 action completed
[2008-06-02T19:50:35] Transfer failed.
[2008-06-02T19:50:35] Log closed
[2008-06-02T19:51:05] Log opened
[2008-06-02T19:51:05] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:51:05] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:51:05] MLST DSC_0137.jpg
[2008-06-02T19:51:05] 250-MLST listing for DSC_0137.jpg
[2008-06-02T19:51:05] size=124200;type=file;perm=fdrwa;create=20080603004926;modify=20080529191753; DSC_0137.jpg
[2008-06-02T19:51:05] 250 end
[2008-06-02T19:51:05] Source File: Size=1897474, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Exact
[2008-06-02T19:51:05] Destination File: Size=124200, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Not Exact
[2008-06-02T19:51:05] RecentTime=2008-06-03T00:50:35
[2008-06-02T19:51:05] Rule "IF Destination Time=Recent AND Size=Smaller AND Transfer=No Matter THEN Resume" matched. Action="Resume".
[2008-06-02T19:51:05] PASV
[2008-06-02T19:51:05] 227 Entering Passive Mode (208,42,68,51,10,160).
[2008-06-02T19:51:05] Opening data connection to 208.42.68.51 Port: 2720
[2008-06-02T19:51:05] REST 124200
[2008-06-02T19:51:05] 350 setting restart marker to 124200
[2008-06-02T19:51:05] STOR DSC_0137.jpg
[2008-06-02T19:51:05] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:51:09] 425 transfer canceled
[2008-06-02T19:51:09] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:51:09] 200 action completed
[2008-06-02T19:51:09] Transfer failed.
[2008-06-02T19:51:09] Log closed
[2008-06-02T19:51:09] Log opened
[2008-06-02T19:51:09] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:51:09] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:51:09] MLST DSC_0137.jpg
[2008-06-02T19:51:09] 250-MLST listing for DSC_0137.jpg
[2008-06-02T19:51:09] size=289800;type=file;perm=fdrwa;create=20080603004926;modify=20080529191753; DSC_0137.jpg
[2008-06-02T19:51:09] 250 end
[2008-06-02T19:51:09] Source File: Size=1897474, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Exact
[2008-06-02T19:51:09] Destination File: Size=289800, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Not Exact
[2008-06-02T19:51:09] RecentTime=2008-06-03T00:51:09
[2008-06-02T19:51:09] Rule "IF Destination Time=Recent AND Size=Smaller AND Transfer=No Matter THEN Resume" matched. Action="Resume".
[2008-06-02T19:51:09] PASV
[2008-06-02T19:51:09] 227 Entering Passive Mode (208,42,68,51,10,165).
[2008-06-02T19:51:09] Opening data connection to 208.42.68.51 Port: 2725
[2008-06-02T19:51:09] REST 289800
[2008-06-02T19:51:09] 350 setting restart marker to 289800
[2008-06-02T19:51:09] STOR DSC_0137.jpg
[2008-06-02T19:51:09] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:51:10] 425 transfer canceled
[2008-06-02T19:51:10] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:51:10] 200 action completed
[2008-06-02T19:51:10] Transfer failed.
[2008-06-02T19:51:10] Log closed
[2008-06-02T19:51:40] Log opened
[2008-06-02T19:51:40] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:51:40] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:51:40] MLST DSC_0137.jpg
[2008-06-02T19:51:40] 250-MLST listing for DSC_0137.jpg
[2008-06-02T19:51:40] size=333960;type=file;perm=fdrwa;create=20080603004926;modify=20080529191753; DSC_0137.jpg
[2008-06-02T19:51:40] 250 end
[2008-06-02T19:51:40] Source File: Size=1897474, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Exact
[2008-06-02T19:51:40] Destination File: Size=333960, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Not Exact
[2008-06-02T19:51:40] RecentTime=2008-06-03T00:51:10
[2008-06-02T19:51:40] Rule "IF Destination Time=Recent AND Size=Smaller AND Transfer=No Matter THEN Resume" matched. Action="Resume".
[2008-06-02T19:51:40] PASV
[2008-06-02T19:51:40] 227 Entering Passive Mode (208,42,68,51,10,209).
[2008-06-02T19:51:40] Opening data connection to 208.42.68.51 Port: 2769
[2008-06-02T19:51:40] REST 333960
[2008-06-02T19:51:40] 350 setting restart marker to 333960
[2008-06-02T19:51:40] STOR DSC_0137.jpg
[2008-06-02T19:51:40] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:51:41] 425 transfer canceled
[2008-06-02T19:51:41] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:51:41] 200 action completed
[2008-06-02T19:51:41] Transfer failed.
[2008-06-02T19:51:41] Log closed
[2008-06-02T19:52:11] Log opened
[2008-06-02T19:52:11] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:52:11] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:52:11] MLST DSC_0137.jpg
[2008-06-02T19:52:11] 250-MLST listing for DSC_0137.jpg
[2008-06-02T19:52:11] size=375360;type=file;perm=fdrwa;create=20080603004926;modify=20080529191753; DSC_0137.jpg
[2008-06-02T19:52:11] 250 end
[2008-06-02T19:52:11] Source File: Size=1897474, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Exact
[2008-06-02T19:52:11] Destination File: Size=375360, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Not Exact
[2008-06-02T19:52:11] RecentTime=2008-06-03T00:51:41
[2008-06-02T19:52:11] Rule "IF Destination Time=Recent AND Size=Smaller AND Transfer=No Matter THEN Resume" matched. Action="Resume".
[2008-06-02T19:52:11] PASV
[2008-06-02T19:52:11] 227 Entering Passive Mode (208,42,68,51,10,249).
[2008-06-02T19:52:11] Opening data connection to 208.42.68.51 Port: 2809
[2008-06-02T19:52:11] REST 375360
[2008-06-02T19:52:11] 350 setting restart marker to 375360
[2008-06-02T19:52:11] STOR DSC_0137.jpg
[2008-06-02T19:52:11] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:52:12] 425 transfer canceled
[2008-06-02T19:52:12] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:52:12] 200 action completed
[2008-06-02T19:52:12] Transfer failed.
[2008-06-02T19:52:12] Log closed
[2008-06-02T19:52:42] Log opened
[2008-06-02T19:52:42] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:52:42] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:52:42] MLST DSC_0137.jpg
[2008-06-02T19:52:42] 250-MLST listing for DSC_0137.jpg
[2008-06-02T19:52:42] size=418140;type=file;perm=fdrwa;create=20080603004926;modify=20080529191753; DSC_0137.jpg
[2008-06-02T19:52:42] 250 end
[2008-06-02T19:52:42] Source File: Size=1897474, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Exact
[2008-06-02T19:52:42] Destination File: Size=418140, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Not Exact
[2008-06-02T19:52:42] RecentTime=2008-06-03T00:52:12
[2008-06-02T19:52:42] Rule "IF Destination Time=Recent AND Size=Smaller AND Transfer=No Matter THEN Resume" matched. Action="Resume".
[2008-06-02T19:52:42] PASV
[2008-06-02T19:52:42] 227 Entering Passive Mode (208,42,68,51,11,38).
[2008-06-02T19:52:42] Opening data connection to 208.42.68.51 Port: 2854
[2008-06-02T19:52:42] REST 418140
[2008-06-02T19:52:42] 350 setting restart marker to 418140
[2008-06-02T19:52:42] STOR DSC_0137.jpg
[2008-06-02T19:52:42] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:52:43] 425 transfer canceled
[2008-06-02T19:52:43] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:52:43] 200 action completed
[2008-06-02T19:52:43] Transfer failed.
[2008-06-02T19:52:43] Log closed
[2008-06-02T19:53:13] Log opened
[2008-06-02T19:53:13] Initializing. Transfer Queue v1.0.9.13.
[2008-06-02T19:53:13] Remote file exist check: "DSC_0137.jpg".
[2008-06-02T19:53:13] MLST DSC_0137.jpg
[2008-06-02T19:53:13] 250-MLST listing for DSC_0137.jpg
[2008-06-02T19:53:13] size=460920;type=file;perm=fdrwa;create=20080603004926;modify=20080529191753; DSC_0137.jpg
[2008-06-02T19:53:13] 250 end
[2008-06-02T19:53:13] Source File: Size=1897474, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Exact
[2008-06-02T19:53:13] Destination File: Size=460920, SizeUnit=Byte, Time=2008-05-29T19:17:53, TimeFormat=Not Exact
[2008-06-02T19:53:13] RecentTime=2008-06-03T00:52:43
[2008-06-02T19:53:13] Rule "IF Destination Time=Recent AND Size=Smaller AND Transfer=No Matter THEN Resume" matched. Action="Resume".
[2008-06-02T19:53:13] PASV
[2008-06-02T19:53:13] 227 Entering Passive Mode (208,42,68,51,11,68).
[2008-06-02T19:53:13] Opening data connection to 208.42.68.51 Port: 2884
[2008-06-02T19:53:13] REST 460920
[2008-06-02T19:53:13] 350 setting restart marker to 460920
[2008-06-02T19:53:13] STOR DSC_0137.jpg
[2008-06-02T19:53:13] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:53:14] 425 transfer canceled
[2008-06-02T19:53:14] MDTM 20080529191753 DSC_0137.jpg
[2008-06-02T19:53:14] 200 action completed
[2008-06-02T19:53:14] Transfer failed.
[2008-06-02T19:53:14] Log closed

2008-06-03 01:08:07

The transfer gets canceled for some reason:
2008-06-02T19:50:34] STOR DSC_0137.jpg
[2008-06-02T19:50:34] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:50:35] 425 transfer canceled

Please contact your web hosting provider or the server administrator for assistance.

Regards,
Mat

jim_h

2008-06-03 02:34:03

The transfer gets canceled for some reason:
2008-06-02T19:50:34] STOR DSC_0137.jpg
[2008-06-02T19:50:34] 150 Opening BINARY data connection for DSC_0137.jpg
[2008-06-02T19:50:35] 425 transfer canceled

Please contact your web hosting provider or the server administrator for assistance.

Regards,
Mat

That much I can see from the log.

No one is available, or able, to help, at the server end - it's a photo printing company. The carrier (U.S. Internet Wireless) will only say that they aren't blocking anything and they see no reason for the problem. I was hoping that someone with FTP expertise could offer a clue or a suggestion for gathering more information.

2008-06-03 03:47:58

It's a server problem. I don't think you can do anything about it. If you would like our technical support to look at your problem in more detail please purchase a license at:
https://www.smartftp.com/buy.php

Regards,
Mat