FTP upload/download (cache?) bug

[thims]

To reproduce:
1. Connect to FTP on one panel
2. Create test.txt empty file on other panel (any local disk)
3. F5 (upload) test.txt from local disk to FTP panel
4. Edit test.txt file so it contains something on local disk
5. Repeat step 3 telling TC to overwrite.

As for me: I get error "Transfer failed, continue operation?". After saying "Yes" I see that file size is changed on FTP panel BUT if I F3 it with Lister, I get old content. I can change local file and re-upload it any number of times. Each time file size on FTP panel changes, but downloading it provides old content. This is VERY annoying.

[ghisler(Author)]

Could you check what is reported by the server (ftp log), please?

[petermad]

I just did step 1-5 and I have no problems seeing the new content in Lister after re-uploading the modified text.txt.

Most likely a server problem, or the editor used on the local file is still open AND blocking the file from being uploaded.

2thims What editor are you using, and are you closing it before the second upload?

[ghisler(Author)]

That's why I asked thims for more information...

[thims]

This log was taken after reproducing all steps including F3 after step 5. I used windows notepad as editor and closed it before uploading file. I believe this is something wrong with local cached copy of a file.

Code: Select all

220 Microsoft FTP Service
USER user
331 Password required for user.
PASS ***********
230 User user logged in.
SYST
215 Windows_NT
FEAT
211-FEAT
    SIZE
    MDTM
211 END
HELP SITE
214 Syntax: SITE (site-specific commands)
OPTS UTF8 ON
501 option not supported
CWD httpdocs
250 CWD command successful.
Connect ok!
PWD
257 "/httpdocs" is current directory.
Get directory
TYPE A
200 Type set to A.
PASV
227 Entering Passive Mode.
LIST
125 Data connection already open; Transfer starting.
Download
Waiting for server...
226 Transfer complete.
TYPE I
200 Type set to I.
PASV
227 Entering Passive Mode.
STOR test.txt
125 Data connection already open; Transfer starting.
Upload
226 Transfer complete.
SIZE test.txt
213 0
Copied (20.12.2010 23:02:06): d:\test.txt -> ftp://server/httpdocs/test.txt
Get directory
TYPE A
200 Type set to A.
PASV
227 Entering Passive Mode.
LIST
125 Data connection already open; Transfer starting.
Download
Waiting for server...
226 Transfer complete.
TYPE I
200 Type set to I.
PASV
227 Entering Passive Mode.
STOR test.txt
125 Data connection already open; Transfer starting.
Upload: 3 bytes
226 Transfer complete.
SIZE test.txt
213 0
Upload size mismatch!
Copied (20.12.2010 23:02:15): d:\test.txt -> ftp://server/httpdocs/test.txt 3 bytes, 0 bytes/s
Get directory
TYPE A
200 Type set to A.
PASV
227 Entering Passive Mode.
LIST
125 Data connection already open; Transfer starting.
Download
Waiting for server...
226 Transfer complete.
TYPE I
200 Type set to I.
PASV
227 Entering Passive Mode.
RETR test.txt
125 Data connection already open; Transfer starting.
Download
Waiting for server...
226 Transfer complete.
SIZE test.txt
213 0
Copied (20.12.2010 23:02:22): ftp://server/httpdocs/test.txt -> C:\Users\THIMS\AppData\Local\Temp\_tc\test.txt

[ghisler(Author)]

STOR test.txt
125 Data connection already open; Transfer starting.
Upload: 3 bytes
226 Transfer complete.
SIZE test.txt
213 0

It seems to be a sever problem: As you can see, the server reports that the transfer was complete, TC sent 3 bytes. Still when TC checks via SIZE command, the size is still 0.

[thims]

We're working hard with FTP server's admin to resolve this issue. For now we have the following situation: all other FTP clients like FAR Manager's, FileZilla and so on work flawless. TC's does not. SpecialFlags=32 setting just removes error on step 5. But after downloading we still have old file content. And only after reconnection I can download a new file.

This is FAR Manager's FTP log:

Code: Select all

1 2010.12.24 13:34:08:0377 3490|<-220 Microsoft FTP Service
1 2010.12.24 13:34:08:0377 0000|->USER user
1 2010.12.24 13:34:08:0423 0046|<-331 Password required for user.
1 2010.12.24 13:34:08:0423 0000|->PASS *hidden*
1 2010.12.24 13:34:08:0485 0062|<-230 User user logged in.
1 2010.12.24 13:34:08:0485 0000|->SYST
1 2010.12.24 13:34:08:0547 0062|<-215 Windows_NT
1 2010.12.24 13:34:08:0547 0000|->PWD
1 2010.12.24 13:34:08:0593 0046|<-257 "/" is current directory.
1 2010.12.24 13:34:08:0593 0000|->TYPE I
1 2010.12.24 13:34:08:0655 0062|<-200 Type set to I.
1 2010.12.24 13:34:08:0655 0000|->REST 0
1 2010.12.24 13:34:08:0701 0046|<-350 Restarting at 0.
1 2010.12.24 13:34:08:0701 0000|->CWD /httpdocs
1 2010.12.24 13:34:08:0763 0062|<-250 CWD command successful.
1 2010.12.24 13:34:08:0763 0000|->PWD
1 2010.12.24 13:34:08:0809 0046|<-257 "/httpdocs" is current directory.
1 2010.12.24 13:34:08:0809 0000|->PWD
1 2010.12.24 13:34:08:0871 0062|<-257 "/httpdocs" is current directory.
1 2010.12.24 13:34:08:0871 0000|->PASV
1 2010.12.24 13:34:08:0933 0062|<-227 Entering Passive Mode.
1 2010.12.24 13:34:08:0933 0000|->TYPE A
1 2010.12.24 13:34:08:0979 0046|<-200 Type set to A.
1 2010.12.24 13:34:09:0041 0062|->LIST
1 2010.12.24 13:34:09:0087 0046|<-125 Data connection already open; Transfer starting.
1 2010.12.24 13:34:09:0350 0263|<-226 Transfer complete.
1 2010.12.24 13:34:09:0350 0000|->TYPE I
1 2010.12.24 13:34:09:0396 0046|<-200 Type set to I.
1 2010.12.24 13:34:12:0453 3057|->PASV
1 2010.12.24 13:34:12:0500 0047|<-227 Entering Passive Mode.
1 2010.12.24 13:34:12:0500 0000|->TYPE A
1 2010.12.24 13:34:12:0577 0077|<-200 Type set to A.
1 2010.12.24 13:34:12:0623 0046|->LIST /httpdocs/test.txt
1 2010.12.24 13:34:12:0685 0062|<-125 Data connection already open; Transfer starting.
1 2010.12.24 13:34:12:0932 0247|<-550 /httpdocs/test.txt: The system cannot find the file specified. 
1 2010.12.24 13:34:12:0932 0000|->TYPE I
1 2010.12.24 13:34:12:0994 0062|<-200 Type set to I.
1 2010.12.24 13:34:12:0994 0000|->SIZE /httpdocs/test.txt
1 2010.12.24 13:34:13:0040 0046|<-550 /httpdocs/test.txt: The system cannot find the file specified. 
1 2010.12.24 13:34:13:0040 0000|->TYPE I
1 2010.12.24 13:34:13:0102 0062|<-200 Type set to I.
1 2010.12.24 13:34:13:0102 0000|->PASV
1 2010.12.24 13:34:13:0148 0046|<-227 Entering Passive Mode.
1 2010.12.24 13:34:13:0210 0062|->STOR /httpdocs/test.txt
1 2010.12.24 13:34:13:0256 0046|<-125 Data connection already open; Transfer starting.
1 2010.12.24 13:34:13:0534 0278|<-226 Transfer complete.
1 2010.12.24 13:34:13:0534 0000|->PASV
1 2010.12.24 13:34:13:0596 0062|<-227 Entering Passive Mode.
1 2010.12.24 13:34:13:0596 0000|->TYPE A
1 2010.12.24 13:34:13:0642 0046|<-200 Type set to A.
1 2010.12.24 13:34:13:0704 0062|->LIST
1 2010.12.24 13:34:13:0750 0046|<-125 Data connection already open; Transfer starting.
1 2010.12.24 13:34:14:0013 0263|<-226 Transfer complete.
1 2010.12.24 13:34:14:0013 0000|->TYPE I
1 2010.12.24 13:34:14:0059 0046|<-200 Type set to I.
1 2010.12.24 13:34:20:0236 6177|->PASV
1 2010.12.24 13:34:20:0282 0046|<-227 Entering Passive Mode.
1 2010.12.24 13:34:20:0282 0000|->TYPE A
1 2010.12.24 13:34:20:0344 0062|<-200 Type set to A.
1 2010.12.24 13:34:20:0390 0046|->LIST /httpdocs/test.txt
1 2010.12.24 13:34:20:0452 0062|<-125 Data connection already open; Transfer starting.
1 2010.12.24 13:34:20:0714 0262|<-226 Transfer complete.
1 2010.12.24 13:34:20:0714 0000|->TYPE I
1 2010.12.24 13:34:20:0776 0062|<-200 Type set to I.
1 2010.12.24 13:34:21:0487 0711|->TYPE I
1 2010.12.24 13:34:21:0533 0046|<-200 Type set to I.
1 2010.12.24 13:34:21:0533 0000|->PASV
1 2010.12.24 13:34:21:0595 0062|<-227 Entering Passive Mode.
1 2010.12.24 13:34:21:0641 0046|->STOR /httpdocs/test.txt
1 2010.12.24 13:34:21:0703 0062|<-125 Data connection already open; Transfer starting.
1 2010.12.24 13:34:21:0965 0262|<-226 Transfer complete.
1 2010.12.24 13:34:21:0965 0000|->PASV
1 2010.12.24 13:34:22:0027 0062|<-227 Entering Passive Mode.
1 2010.12.24 13:34:22:0027 0000|->TYPE A
1 2010.12.24 13:34:22:0073 0046|<-200 Type set to A.
1 2010.12.24 13:34:22:0135 0062|->LIST
1 2010.12.24 13:34:22:0181 0046|<-125 Data connection already open; Transfer starting.
1 2010.12.24 13:34:22:0444 0263|<-226 Transfer complete.
1 2010.12.24 13:34:22:0444 0000|->TYPE I
1 2010.12.24 13:34:22:0490 0046|<-200 Type set to I.
1 2010.12.24 13:34:32:0882 10392|->TYPE I
1 2010.12.24 13:34:32:0929 0047|<-200 Type set to I.
1 2010.12.24 13:34:32:0929 0000|->PASV
1 2010.12.24 13:34:32:0990 0061|<-227 Entering Passive Mode.
1 2010.12.24 13:34:33:0037 0047|->RETR /httpdocs/test.txt
1 2010.12.24 13:34:33:0098 0061|<-125 Data connection already open; Transfer starting.
1 2010.12.24 13:34:33:0361 0263|<-226 Transfer complete.

And this is FileZilla's log:

Code: Select all

Response:	220 Microsoft FTP Service
Command:	USER user
Response:	331 Password required for user.
Command:	PASS ***********
Response:	230 User user logged in.
Status:	Connected
Status:	Starting upload of D:\test.txt
Command:	CWD /httpdocs
Response:	250 CWD command successful.
Command:	TYPE A
Response:	200 Type set to A.
Command:	PASV
Response:	227 Entering Passive Mode.
Command:	STOR test.txt
Response:	125 Data connection already open; Transfer starting.
Response:	226 Transfer complete.
Status:	File transfer successful, transferred 0 bytes in 1 second
Status:	Retrieving directory listing...
Command:	TYPE I
Response:	200 Type set to I.
Command:	PASV
Response:	227 Entering Passive Mode.
Command:	LIST
Response:	125 Data connection already open; Transfer starting.
Response:	226 Transfer complete.
Status:	Directory listing successful
Status:	Starting upload of D:\test.txt
Command:	TYPE A
Response:	200 Type set to A.
Command:	PASV
Response:	227 Entering Passive Mode.
Command:	STOR test.txt
Response:	125 Data connection already open; Transfer starting.
Response:	226 Transfer complete.
Status:	File transfer successful, transferred 1 byte in 1 second
Status:	Retrieving directory listing...
Command:	TYPE I
Response:	200 Type set to I.
Command:	PASV
Response:	227 Entering Passive Mode.
Command:	LIST
Response:	125 Data connection already open; Transfer starting.
Response:	226 Transfer complete.
Status:	Directory listing successful
Status:	Starting download of /httpdocs/test.txt
Command:	TYPE A
Response:	200 Type set to A.
Command:	PASV
Response:	227 Entering Passive Mode.
Command:	RETR test.txt
Response:	125 Data connection already open; Transfer starting.
Response:	226 Transfer complete.
Status:	File transfer successful, transferred 1 byte in 1 second

[Sob]

TC claims that those few bytes were sent. Server seems to deny that by reporting zero sized file. Who's telling the truth? It's time for good old packet sniffing! :) Capture the whole session and it should get clear.

[thims]

Why do you need to sniff anything when ALL other FTP clients including even ftp.exe work without any troubles?
As you can see, other FTP clients do not use SIZE command at all but work flawless. I clearly understand that this is some MS FTP Server's issue. But there should be a workaround since other FTP clients work.

Looks like the problem is in SIZE command itself. It somehow locks file on a server so it cannot be updated until IIS is restarted. It will be greate to have some SpecialFlags or so to disable TC's SIZE command usage at all.

[Sob]

It will be greate to have some SpecialFlags or so to disable TC's SIZE command usage at all.

That's exactly what SpecialFlags=32 does. Set it and TC won't send SIZE command after file upload.

If it won't help, then there's one more difference between TC and FZ. TC uses TYPE I for file transfer, while FZ uses TYPE A. You should be able to force TC to also use TYPE A, see the combobox next to Disconnect button.

Then both TC and FZ will do exactly the same, without any differences.

And if it still won't help, then some other hidden bug causing something else going over the wire, than reported in log, is the only explanation.

[thims]

Just found the problem!
For some reason TC does not respect SpecialFlags=32 if I use F4 (edit) right on FTP panel and sends SIZE command.
If I download/upload (F5) file, everything is fine with SpecialFlags=32 and MS FTP as well as view (F3).

So the bug is in TC which sends SIZE command regardless on SpecialFlags value.

[ghisler(Author)]

Strange, I will check that, thanks for the info!