Re: Can't get verbose logs from the server...
I'm sorry, but I do not know how to help you further atm.
- martin
Post a reply
Before posting, please read how to report bug or request support effectively.
Bug reports without an attached log file are usually useless.
Topic review
- Zolaerla
Can't get verbose logs from the server...
Unfortunately, the server is on the "doomed" CentOS 8, which is being supported by pretty much nothing. It is going to be some effort to migrate to a different OS. The version of pureftpd that added decent logging support (v1.1.x) is later than I can get on it (v1.0.x). No amount of configuration generates any more results than one-liners about storing/retrieving files.
- martin
Re: Got a full log of the Delete variation of the problem
Are you able to check server-side log file to see why it disconnects the session?
- Zolaerla
Got a full log of the Delete variation of the problem
Just to let you know, between the previous messages and now, I have updated WinSCP to the latest public version: v5.19.3
I reuploaded and mass-deleted a bunch of old code to try to get the delete intermittent problem to occur, disconnecting and reconnecting between them, to try to get a complete log of the delete variation. After 5 attempts, it failed. Attached is the log for it... it's pretty long.
The file it failed on is:
/Temp/Test2/v3.0/Binary/Originals/22-s365.bin
to help you find where the errors show up in the log file.
I kept logging back in and continuing the delete in the log as well. You can see that that file does not show up again, because it actually was deleted successfully, even though WinSCP reported that it failed to delete it.
I do not know if it is the same issue as the file upload issue, but it seems to be related. I cannot readily cause the upload issue... I uploaded several thousand files since creating this post and have not had the problem again.
I reuploaded and mass-deleted a bunch of old code to try to get the delete intermittent problem to occur, disconnecting and reconnecting between them, to try to get a complete log of the delete variation. After 5 attempts, it failed. Attached is the log for it... it's pretty long.
The file it failed on is:
/Temp/Test2/v3.0/Binary/Originals/22-s365.bin
to help you find where the errors show up in the log file.
I kept logging back in and continuing the delete in the log as well. You can see that that file does not show up again, because it actually was deleted successfully, even though WinSCP reported that it failed to delete it.
I do not know if it is the same issue as the file upload issue, but it seems to be related. I cannot readily cause the upload issue... I uploaded several thousand files since creating this post and have not had the problem again.
- Zolaerla
Intermittent Problem...
Please explain what a "complete" log entails. From log in to log out? That is not going to be possible.
This is truly an intermittent problem, and seems to be a "Chicken Before the Egg" kind of sync issue. I'm connected locally to a very fast server, and it seems that sometimes the reaction to requests by WinSCP happen before WinSCP expects it, causing things to jam up regularly.
I have not been able to cause it with a file upload again, but get it numerous times doing file deletions. I try to delete a list of files, then WinSCP fails with that, throws an error about the file no longer existing (well, of course not, it just told the FTP to delete it), then disconnects and asks if I want to reconnect to the server. Sometimes it happens on the last file in the list, and I'm good and can continue after the interruption and totally pointless server reconnect. Sometimes, I have to try again and hope it doesn't fail again. Again, this is never a problem in Filezilla with the same connection on the same server, but I far prefer WinSCP's UI.
This is truly an intermittent problem, and seems to be a "Chicken Before the Egg" kind of sync issue. I'm connected locally to a very fast server, and it seems that sometimes the reaction to requests by WinSCP happen before WinSCP expects it, causing things to jam up regularly.
I have not been able to cause it with a file upload again, but get it numerous times doing file deletions. I try to delete a list of files, then WinSCP fails with that, throws an error about the file no longer existing (well, of course not, it just told the FTP to delete it), then disconnects and asks if I want to reconnect to the server. Sometimes it happens on the last file in the list, and I'm good and can continue after the interruption and totally pointless server reconnect. Sometimes, I have to try again and hope it doesn't fail again. Again, this is never a problem in Filezilla with the same connection on the same server, but I far prefer WinSCP's UI.
- martin
Re: Filezilla log...
WinSCP log was indeed verbose enough. But I need a complete one. And a complete verbose log from FileZilla too. Thanks.
- Zolaerla
Filezilla log...
I have no idea how to get more verbose logs from WinSCP. The logs I already have included were set to "Debug 2" when I created them.
Today, I found that I can cause the type 1 error to happen fairly reliably by manually deleting a file, then trying to upload it right afterwards. At this time, standard uploads are working again, but nothing has changed, not even a reboot on either system. I can try to cause the problem again, though having projects crash due to uploads failing is not fun when trying to get some work done.
The Filezilla FTP log is:
Today, I found that I can cause the type 1 error to happen fairly reliably by manually deleting a file, then trying to upload it right afterwards. At this time, standard uploads are working again, but nothing has changed, not even a reboot on either system. I can try to cause the problem again, though having projects crash due to uploads failing is not fun when trying to get some work done.
The Filezilla FTP log is:
2021-10-07 11:09:51 14236 2 Status: Starting upload of E:\Internet\MeMSO\!Generic\!PHP v4.0\Plugin\Commerce\Checkout-Payment.php
2021-10-07 11:09:51 14236 2 Trace: CFtpChangeDirOpData::Send() in state 0
2021-10-07 11:09:51 14236 2 Trace: CFtpChangeDirOpData::Send() in state 2
2021-10-07 11:09:51 14236 2 Command: CWD /GolfRack/Plugin/Commerce
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::OnReceive()
2021-10-07 11:09:51 14236 2 Response: 250 OK. Current directory is /GolfRack/Plugin/Commerce
2021-10-07 11:09:51 14236 2 Trace: CFtpChangeDirOpData::ParseResponse() in state 2
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::SendNextCommand()
2021-10-07 11:09:51 14236 2 Trace: CFtpChangeDirOpData::Send() in state 3
2021-10-07 11:09:51 14236 2 Command: PWD
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::OnReceive()
2021-10-07 11:09:51 14236 2 Response: 257 "/GolfRack/Plugin/Commerce" is your current location
2021-10-07 11:09:51 14236 2 Trace: CFtpChangeDirOpData::ParseResponse() in state 3
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::ResetOperation(0)
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::ResetOperation(0)
2021-10-07 11:09:51 14236 2 Trace: CFtpChangeDirOpData::Reset(0) in state 3
2021-10-07 11:09:51 14236 2 Trace: CFtpFileTransferOpData::SubcommandResult(0) in state 1
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::SetAsyncRequestReply
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::SendNextCommand()
2021-10-07 11:09:51 14236 2 Trace: CFtpFileTransferOpData::Send() in state 5
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::Send() in state 0
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::Send() in state 1
2021-10-07 11:09:51 14236 2 Command: TYPE I
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::OnReceive()
2021-10-07 11:09:51 14236 2 Response: 200 TYPE is now 8-bit binary
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::ParseResponse() in state 1
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::SendNextCommand()
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::Send() in state 2
2021-10-07 11:09:51 14236 2 Command: PASV
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::OnReceive()
2021-10-07 11:09:51 14236 2 Response: 227 Entering Passive Mode (50,243,106,2,118,131)
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::ParseResponse() in state 2
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::SendNextCommand()
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::Send() in state 4
2021-10-07 11:09:51 14236 2 Trace: Binding data connection source IP to control connection source IP 50.243.106.5
2021-10-07 11:09:51 14236 2 Trace: tls_layer_impl::client_handshake()
2021-10-07 11:09:51 14236 2 Trace: Trying to resume existing TLS session.
2021-10-07 11:09:51 14236 2 Command: STOR Checkout-Payment.php
2021-10-07 11:09:51 14236 2 Trace: tls_layer_impl::continue_handshake()
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::OnReceive()
2021-10-07 11:09:51 14236 2 Response: 150 Accepted data connection
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::ParseResponse() in state 4
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::SendNextCommand()
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::Send() in state 5
2021-10-07 11:09:51 14236 2 Trace: tls_layer_impl::continue_handshake()
2021-10-07 11:09:51 14236 2 Trace: tls_layer_impl::continue_handshake()
2021-10-07 11:09:51 14236 2 Trace: TLS Handshake successful
2021-10-07 11:09:51 14236 2 Trace: TLS Session resumed
2021-10-07 11:09:51 14236 2 Trace: Protocol: TLS1.3, Key exchange: unknown, Cipher: AES-256-GCM, MAC: AEAD
2021-10-07 11:09:51 14236 2 Trace: tls_layer_impl::verify_certificate()
2021-10-07 11:09:51 14236 2 Trace: CTransferSocket::OnConnect
2021-10-07 11:09:51 14236 2 Trace: tls_layer_impl::shutdown()
2021-10-07 11:09:51 14236 2 Trace: tls_layer_impl::continue_shutdown()
2021-10-07 11:09:51 14236 2 Trace: CTransferSocket::TransferEnd(1)
2021-10-07 11:09:51 14236 2 Trace: tls_layer_impl::shutdown()
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::TransferEnd()
2021-10-07 11:09:51 14236 2 Trace: gnutls_record_recv returned spurious EAGAIN
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::OnReceive()
2021-10-07 11:09:51 14236 2 Response: 226-File successfully transferred
2021-10-07 11:09:51 14236 2 Response: 226 0.036 seconds (measured here), 0.93 Mbytes per second
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::ParseResponse() in state 7
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::ResetOperation(0)
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::ResetOperation(0)
2021-10-07 11:09:51 14236 2 Trace: CFtpRawTransferOpData::Reset(0) in state 7
2021-10-07 11:09:51 14236 2 Trace: CFtpFileTransferOpData::SubcommandResult(0) in state 7
2021-10-07 11:09:51 14236 2 Trace: CFtpControlSocket::ResetOperation(0)
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::ResetOperation(0)
2021-10-07 11:09:51 14236 2 Trace: CFtpFileTransferOpData::Reset(0) in state 7
2021-10-07 11:09:51 14236 2 Status: File transfer successful, transferred 34,938 bytes in 1 second
2021-10-07 11:09:51 14236 2 Trace: CControlSocket::SendNextCommand()
2021-10-07 11:09:51 14236 2 Trace: CFtpListOpData::Send() in state 0
- martin
Re: WinSCP Suddenly No Longer Uploads...
Please attach complete verbose logs from both WinSCP and FileZilla showing an upload of the same file with the same settings.
- Zolaerla
WinSCP Suddenly No Longer Uploads...
Using the GUI of WinSCP v5.19.2 (Build 11614) in Windows 10, WinSCP can no longer upload files to my local server. It gets two different kinds of errors randomly. This happened out of nowhere, in the middle of uploading a large number of files. Now nothing uploads with WinSCP, but uploads have no issues through other FTP software. I have been using WinSCP for at least 2 months now with no problems until this suddenly happened. Note that downloads work without a problem.
Now, trying to upload files has one of the following happen:
1) The file acts like it was successful, but has a 0 size. The log file says it skipped uploading due to a future date on the server. This may happen whether the file existed first or not.
2) The file doesn't even try to upload. A popup appears saying,
Restarting WinSCP does not fix the problem. Restarting pure-ftpd on the server does not fix the problem. Diagnostics on the server return nothing wrong. Using another FTP program, such as FileZilla, works as expected.
Oddly enough, I do not have problems uploading via WinSCP to other servers.
It was working as expected in WinSCP until randomly it decided to no longer work.
Log for #1 happening:
Log for type 2 happening:
Now, trying to upload files has one of the following happen:
1) The file acts like it was successful, but has a 0 size. The log file says it skipped uploading due to a future date on the server. This may happen whether the file existed first or not.
2) The file doesn't even try to upload. A popup appears saying,
Copying files to remote side failed.
Error during read from data connection
Transfer aborted.
Restarting WinSCP does not fix the problem. Restarting pure-ftpd on the server does not fix the problem. Diagnostics on the server return nothing wrong. Using another FTP program, such as FileZilla, works as expected.
Oddly enough, I do not have problems uploading via WinSCP to other servers.
It was working as expected in WinSCP until randomly it decided to no longer work.
Log for #1 happening:
. 2021-10-06 12:44:22.194 [Background 1] Size of 1 local files/folders calculated as 32729
. 2021-10-06 12:44:22.194 [Background 1] Copying 1 files/directories to remote directory "/GolfRack/Plugin/Commerce/" - in parallel, with 1 total files - total size: 32,729
. 2021-10-06 12:44:22.197 [Background 1] PrTime: No; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: Yes; Mask: *.*
. 2021-10-06 12:44:22.197 [Background 1] TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: Yes; EncryptNewFiles: Yes; ExcludeHiddenFiles: No; ExcludeEmptyDirectories: No; InclM: ; ResumeL: 0
. 2021-10-06 12:44:22.197 [Background 1] AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2021-10-06 12:44:22.197 [Background 1] File: 'E:\Internet\MeMSO\!Generic\!PHP v4.0\Plugin\Commerce\Checkout-Payment.php' [2021-10-06T19:22:32.003Z] [32729]
. 2021-10-06 12:44:22.197 [Background 1] Copying "E:\Internet\MeMSO\!Generic\!PHP v4.0\Plugin\Commerce\Checkout-Payment.php" to remote directory started.
. 2021-10-06 12:44:22.197 [Background 1] Binary transfer mode selected.
. 2021-10-06 12:44:22.197 [Background 1] Starting upload of E:\Internet\MeMSO\!Generic\!PHP v4.0\Plugin\Commerce\Checkout-Payment.php
. 2021-10-06 12:44:22.197 [Background 1] Source file timestamp is [2021-10-06T19:22:32.000Z], destination timestamp is [2021-10-06T19:38:18.000Z], will not overwrite
. 2021-10-06 12:44:22.197 [Background 1] Upload successful
. 2021-10-06 12:44:22.197 [Background 1] Got reply 1 to the command 4
* 2021-10-06 12:44:22.197 [Background 1] (ESkipFile)
. 2021-10-06 12:44:22.197 [Background 1] Copying finished: Transferred: 0, Elapsed: 0:00:00, CPS: 0/s
Log for type 2 happening:
. 2021-10-06 12:51:16.645 [Background 1] Size of 1 local files/folders calculated as 32729
. 2021-10-06 12:51:16.645 [Background 1] Copying 1 files/directories to remote directory "/GolfRack/Plugin/Commerce/" - in parallel, with 1 total files - total size: 32,729
. 2021-10-06 12:51:16.645 [Background 1] PrTime: No; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: Yes; Mask: *.*
. 2021-10-06 12:51:16.645 [Background 1] TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: Yes; EncryptNewFiles: Yes; ExcludeHiddenFiles: No; ExcludeEmptyDirectories: No; InclM: ; ResumeL: 0
. 2021-10-06 12:51:16.645 [Background 1] AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2021-10-06 12:51:16.645 [Background 1] File: 'E:\Internet\MeMSO\!Generic\!PHP v4.0\Plugin\Commerce\Checkout-Payment.php' [2021-10-06T19:22:32.003Z] [32729]
. 2021-10-06 12:51:16.645 [Background 1] Copying "E:\Internet\MeMSO\!Generic\!PHP v4.0\Plugin\Commerce\Checkout-Payment.php" to remote directory started.
. 2021-10-06 12:51:16.645 [Background 1] Binary transfer mode selected.
. 2021-10-06 12:51:16.645 [Background 1] Starting upload of E:\Internet\MeMSO\!Generic\!PHP v4.0\Plugin\Commerce\Checkout-Payment.php
> 2021-10-06 12:51:16.645 [Background 1] TYPE I
< 2021-10-06 12:51:16.646 [Background 1] 200 TYPE is now 8-bit binary
> 2021-10-06 12:51:16.646 [Background 1] PASV
< 2021-10-06 12:51:16.646 [Background 1] 227 Entering Passive Mode (50,243,106,2,118,13)
> 2021-10-06 12:51:16.646 [Background 1] STOR Checkout-Payment.php
< 2021-10-06 12:51:16.647 [Background 1] 150 Accepted data connection
< 2021-10-06 12:51:16.676 [Background 1] 451-Error during read from data connection
< 2021-10-06 12:51:16.676 [Background 1] 451 Transfer aborted
. 2021-10-06 12:51:16.676 [Background 1] Copying files to remote side failed.
. 2021-10-06 12:51:16.676 [Background 1] Got reply 4 to the command 4
* 2021-10-06 12:51:16.676 [Background 1] (ExtException) **Copying files to remote side failed.**
* 2021-10-06 12:51:16.676 [Background 1] Error during read from data connection
* 2021-10-06 12:51:16.676 [Background 1] Transfer aborted
. 2021-10-06 12:51:16.676 [Background 1] Asking user:
. 2021-10-06 12:51:16.676 [Background 1] Error transferring file 'E:\Internet\MeMSO\!Generic\!PHP v4.0\Plugin\Commerce\Checkout-Payment.php'. ("Copying files to remote side failed.","Error during read from data connection","Transfer aborted")