I've noticed with one of our users is having issues deleting files from our server. We tracked things down to their winscp batch script not waiting for
SSH_FXP_STATUS
after sending
SSH_FXP_CLOSE
. The script quickly moves onto
SSH_FXP_REMOVE
. Is this a known issue with the
get
command with the
-delete
flag in WinSCP? Sorry if there's a better source for this information, I was unable to find it. I don't have the client's exact software information, but I can get it.
Here's an example log from our server which demonstrates WinSCP's behavior:
2020-04-27 11:55:32,027 DEBUG SFTPSubsystemServer [Session.2188476:Default Site:testuser:123.456.789.10] Received message (SSH_FXP_CLOSE)
2020-04-27 11:55:32,027 DEBUG SFTPSubsystemServer [Session.2188476:Default Site:testuser:123.456.789.10] OnClose()
2020-04-27 11:55:32,027 DEBUG SFTPSubsystemServer [Session.2188476:Default Site:testuser:123.456.789.10] Queued FXP_CLOSE for file handle 939632750
2020-04-27 11:55:32,027 DEBUG SFTPConnection [Session.2188476:Default Site:testuser:123.456.789.10] PreProcessPacket pt=SSH_MSG_CHANNEL_DATA,len=76
2020-04-27 11:55:32,027 DEBUG SFTPConnection [Session.2188476:Default Site:testuser:123.456.789.10] SSH_MSG_CHANNEL_DATA for channel 0
2020-04-27 11:55:32,027 DEBUG SSHServerChannel [Session.2188476:Default Site:testuser:123.456.789.10] Channel 0: ProcessPacket pt=SSH_MSG_CHANNEL_DATA
2020-04-27 11:55:32,027 DEBUG SFTPServerMessageFactory [Session.2188476:Default Site:testuser:123.456.789.10] Received message (type=13,len=76)
2020-04-27 11:55:32,027 DEBUG SFTPSubsystemServer [Session.2188476:Default Site:testuser:123.456.789.10] Received message (SSH_FXP_REMOVE)
2020-04-27 11:55:32,027 DEBUG SFTPSubsystemServer [Session.2188476:Default Site:testuser:123.456.789.10] OnFileRemove(/outgoing/test.txt)
2020-04-27 11:55:32,027 DEBUG WindowsAdapter [Session.2188476:Default Site:testuser:123.456.789.10] Exception thrown while service_account was accessing test.txt - System.IO.IOException:The process cannot access the file 'test.txt' because it is being used by another process.
2020-04-27 11:55:32,027 DEBUG FileDetails [Session.2188476:Default Site:testuser:123.456.789.10] Closing file handle 939632750
2020-04-27 11:55:32,042 INFO FileDetails [Session.2188476:Default Site:testuser:123.456.789.10] Closed file /Root/partner/outgoing/test.txt after reading 4 bytes
2020-04-27 11:55:32,042 DEBUG FileDetails [Session.2188476:Default Site:testuser:123.456.789.10] Notifying stream closed 939632750
2020-04-27 11:55:32,042 DEBUG FileDetails [Session.2188476:Default Site:testuser:123.456.789.10] Notified stream closed 939632750
2020-04-27 11:55:32,042 DEBUG FileDetails [Session.2188476:Default Site:testuser:123.456.789.10] File /Root/partner/outgoing/test.txt: 0 messages to process
2020-04-27 11:55:32,042 DEBUG FileDetails [Session.2188476:Default Site:testuser:123.456.789.10] Removed file handle 939632750
2020-04-27 11:55:32,042 DEBUG SFTPSubsystemServer [Session.2188476:Default Site:testuser:123.456.789.10] Sending SSH_FXP_STATUS [requestid=47108,code=0]