Failed to rename because the file is currently in progress ?

Question

Hello Rebex SFTP Team

Could you please give me some help?

I'm currently programming an SSIS script task that involves renaming files in a remote SFTP directory. Sometimes I get this error message and the files do not get renamed:

"Failed to rename originalname to newname because the file is currently in progress."

There is a previous task that transfers the file being renamed. But it allways completes sucessfuly. It means there should not be a message like "currently in progress" since the file has been completely uploaded. Every task have its own connection code and do not execute paralelly or something of that kind.

Please let me know if you need more information.

Kind Regards

Comments

The "Failed to rename originalname to newname because the file is currently in progress." error message doesn't actually seem to come from Rebex SFTP. Would it be possible to create a log using Sftp object's LogWriter property (as described at http://www.rebex.net/kb/logging.aspx) and post it here or mail it to us? That should make it possible to tell what is going on.

---

Hello

This is the log file that gets created when running the SSIS package. As you can see this error does not for all the files. This log belong to an execution involving 5 files. The package transfer them to the SFTP server and rename them once they have been completely uploaded (just a change of extension from .tmp to .txt)

2014-05-12 10:52:17.837 Opening log file.
2014-05-12 10:52:17.897 INFO Sftp(1)[3] Info: Connecting to 74.120.45.139:22 using Sftp 3.0.4700.0.
2014-05-12 10:52:18.053 DEBUG Sftp(1)[3] SSH: Server is 'SSH-2.0-SSHD'.
2014-05-12 10:52:18.079 INFO Sftp(1)[3] SSH: Negotiation started.
2014-05-12 10:52:18.264 DEBUG Sftp(1)[3] SSH: Group exchange.
2014-05-12 10:52:18.336 DEBUG Sftp(1)[3] SSH: Negotiating key.
2014-05-12 10:52:18.520 DEBUG Sftp(1)[3] SSH: Validating signature.
2014-05-12 10:52:18.676 INFO Sftp(1)[3] SSH: Negotiation finished.
2014-05-12 10:52:18.677 INFO Sftp(1)[3] Info: Server: SSH-2.0-SSHD
2014-05-12 10:52:18.680 INFO Sftp(1)[3] Info: Fingerprint: ab:ec:c0:cb:c6:f2:7e:04:14:dc:45:42:76:31:59:f9
2014-05-12 10:52:18.685 INFO Sftp(1)[3] Info: Cipher info: SSH 2.0, DiffieHellmanGroupExchangeSHA256, RSA, aes256-ctr/aes256-ctr, hmac-sha1/hmac-sha1
2014-05-12 10:52:18.850 DEBUG Sftp(1)[3] SSH: Allowed authentication methods: password, keyboard-interactive.
2014-05-12 10:52:21.148 DEBUG Sftp(1)[3] SSH: Trying password authentication for 'abaftptest'.
2014-05-12 10:52:21.810 DEBUG Sftp(1)[3] SSH: Authentication successful.
2014-05-12 10:52:26.230 DEBUG Sftp(1)[3] SSH: Requesting subsystem 'sftp'.
2014-05-12 10:52:26.704 INFO Sftp(1)[3] Command: SSH_FXP_INIT (4)
2014-05-12 10:52:26.768 INFO Sftp(1)[3] Response: SSH_FXP_VERSION (3, 1 extension)
2014-05-12 10:52:26.787 INFO Sftp(1)[3] Info: Using SFTP v3.
2014-05-12 10:52:26.808 INFO Sftp(1)[3] Command: SSH_FXP_REALPATH (1, '.')
2014-05-12 10:52:26.900 INFO Sftp(1)[3] Response: SSH_FXP_NAME (1, 1 item)
2014-05-12 10:52:26.902 INFO Sftp(1)[3] Info: Current directory is '/'.
2014-05-12 10:52:27.039 INFO Sftp(1)[3] Command: SSH_FXP_STAT (2, '/IN/SINNestor')
2014-05-12 10:52:27.129 INFO Sftp(1)[3] Response: SSH_FXP_ATTRS (2)
2014-05-12 10:52:27.250 INFO Sftp(1)[3] Command: SSH_FXP_STAT (3, '/IN/SINNestor/ASAA13E097.tmp')
2014-05-12 10:52:27.323 INFO Sftp(1)[3] Response: SSH_FXP_STATUS (3, 2, '/IN/SINNestor/ASAA13E097.tmp is not a valid file path')
2014-05-12 10:52:27.394 INFO Sftp(1)[3] Command: SSH_FXP_OPEN (4, '/IN/SINNestor/ASAA13E097.tmp', 26)
2014-05-12 10:52:27.528 INFO Sftp(1)[3] Response: SSH_FXP_HANDLE (4, 0x30)
2014-05-12 10:52:27.676 DEBUG Sftp(1)[3] Command: SSH_FXP_WRITE (5, 0x30, 0, 28672 bytes)
2014-05-12 10:52:27.833 DEBUG Sftp(1)[3] Command: SSH_FXP_WRITE (6, 0x30, 28672, 28672 bytes)
2014-05-12 10:52:28.530 DEBUG Sftp(1)[3] Command: SSH_FXP_WRITE (7, 0x30, 57344, 28672 bytes)
2014-05-12 10:52:28.677 DEBUG Sftp(1)[3] Command: SSH_FXP_WRITE (8, 0x30, 86016, 2578 bytes)
2014-05-12 10:52:28.679 DEBUG Sftp(1)[3] Response: SSH_FXP_STATUS (5, 0, 'The write completed successfully')
2014-05-12 10:52:28.680 DEBUG Sftp(1)[3] Response: SSH_FXP_STATUS (6, 0, 'The write completed successfully')
2014-05-12 10:52:28.926 DEBUG Sftp(1)[3] Response: SSH_FXP_STATUS (7, 0, 'The write completed successfully')
2014-05-12 10:52:28.927 DEBUG Sftp(1)[3] Response: SSH_FXP_STATUS (8, 0, 'The write completed successfully')
2014-05-12 10:52:28.933 INFO Sftp(1)[3] Command: SSH_FXP_CLOSE (9, 0x30)
2014-05-12 10:52:29.067 INFO Sftp(1)[3] Response: SSH_FXP_STATUS (9, 0, 'The operation completed')
2014-05-12 10:52:29.403 INFO Sftp(3)[3] Info: Connecting to 74.120.45.139:22 using Sftp 3.0.4700.0.
2014-05-12 10:52:29.503 DEBUG Sftp(3)[3] SSH: Server is 'SSH-2.0-SSHD'.
2014-05-12 10:52:29.504 INFO Sftp(3)[3] SSH: Negotiation started.
2014-05-12 10:52:29.555 DEBUG Sftp(3)[3] SSH: Group exchange.
2014-05-12 10:52:29.624 DEBUG Sftp(3)[3] SSH: Negotiating key.
2014-05-12 10:52:29.737 DEBUG Sftp(3)[3] SSH: Validating signature.
2014-05-12 10:52:29.798 INFO Sftp(3)[3] SSH: Negotiation finished.
2014-05-12 10:52:29.799 INFO Sftp(3)[3] Info: Server: SSH-2.0-SSHD
2014-05-12 10:52:29.799 INFO Sftp(3)[3] Info: Fingerprint: ab:ec:c0:cb:c6:f2:7e:04:14:dc:45:42:76:31:59:f9
2014-05-12 10:52:29.800 INFO Sftp(3)[3] Info: Cipher info: SSH 2.0, DiffieHellmanGroupExchangeSHA256, RSA, aes256-ctr/aes256-ctr, hmac-sha1/hmac-sha1
2014-05-12 10:52:29.902 DEBUG Sftp(3)[3] SSH: Allowed authentication methods: password, keyboard-interactive.
2014-05-12 10:52:29.903 DEBUG Sftp(3)[3] SSH: Trying password authentication for 'abaftptest'.
2014-05-12 10:52:29.984 DEBUG Sftp(3)[3] SSH: Authentication successful.
2014-05-12 10:52:30.037 DEBUG Sftp(3)[3] SSH: Requesting subsystem 'sftp'.
2014-05-12 10:52:30.335 INFO Sftp(3)[3] Command: SSH_FXP_INIT (4)
2014-05-12 10:52:30.385 INFO Sftp(3)[3] Response: SSH_FXP_VERSION (3, 1 extension)
2014-05-12 10:52:30.386 INFO Sftp(3)[3] Info: Using SFTP v3.
2014-05-12 10:52:30.387 INFO Sftp(3)[3] Command: SSH_FXP_REALPATH (1, '.')
2014-05-12 10:52:30.463 INFO Sftp(3)[3] Response: SSH_FXP_NAME (1, 1 item)
2014-05-12 10:52:30.464 INFO Sftp(3)[3] Info: Current directory is '/'.
2014-05-12 10:52:30.475 INFO Sftp(3)[3] Command: SSH_FXP_RENAME (2, '/IN/SINNestor/ASAA13E097.tmp', '/IN/SINNestor/ASAA13E097.txt')
2014-05-12 10:52:30.637 INFO Sftp(3)[3] Response: SSH_FXP_STATUS (2, 0, 'The file was renamed')
2014-05-12 10:52:31.283 INFO Sftp(5)[3] Info: Connecting to 74.120.45.139:22 using Sftp 3.0.4700.0.
2014-05-12 10:52:31.383 DEBUG Sftp(5)[3] SSH: Server is 'SSH-2.0-SSHD'.
2014-05-12 10:52:31.383 INFO Sftp(5)[3] SSH: Negotiation started.
2014-05-12 10:52:31.434 DEBUG Sftp(5)[3] SSH: Group exchange.
2014-05-12 10:52:31.504 DEBUG Sftp(5)[3] SSH: Negotiating key.
2014-05-12 10:52:31.616 DEBUG Sftp(5)[3] SSH: Validating signature.
2014-05-12 10:52:31.671 INFO Sftp(5)[3] SSH: Negotiation finished.
2014-05-12 10:52:31.672 INFO Sftp(5)[3] Info: Server: SSH-2.0-SSHD
2014-05-12 10:52:31.672 INFO Sftp(5)[3] Info: Fingerprint: ab:ec:c0:cb:c6:f2:7e:04:14:dc:45:42:76:31:59:f9
2014-05-12 10:52:31.673 INFO Sftp(5)[3] Info: Cipher info: SSH 2.0, DiffieHellmanGroupExchangeSHA256, RSA, aes256-ctr/aes256-ctr, hmac-sha1/hmac-sha1
2014-05-12 10:52:31.773 DEBUG Sftp(5)[3] SSH: Allowed authentication methods: password, keyboard-interactive.
2014-05-12 10:52:31.773 DEBUG Sftp(5)[3] SSH: Trying password authentication for 'abaftptest'.
2014-05-12 10:52:31.852 DEBUG Sftp(5)[3] SSH: Authentication successful.
2014-05-12 10:52:31.902 DEBUG Sftp(5)[3] SSH: Requesting subsystem 'sftp'.
2014-05-12 10:52:32.194 INFO Sftp(5)[3] Command: SSH_FXP_INIT (4)
2014-05-12 10:52:32.243 INFO Sftp(5)[3] Response: SSH_FXP_VERSION (3, 1 extension)
2014-05-12 10:52:32.244 INFO Sftp(5)[3] Info: Using SFTP v3.
2014-05-12 10:52:32.244 INFO Sftp(5)[3] Command: SSH_FXP_REALPATH (1, '.')
2014-05-12 10:52:32.325 INFO Sftp(5)[3] Response: SSH_FXP_NAME (1, 1 item)
2014-05-12 10:52:32.325 INFO Sftp(5)[3] Info: Current directory is '/'.
2014-05-12 10:52:32.328 INFO Sftp(5)[3] Command: SSH_FXP_STAT (2, '/IN/SINNestor')
2014-05-12 10:52:32.417 INFO Sftp(5)[3] Response: SSH_FXP_ATTRS (2)
2014-05-12 10:52:32.418 INFO Sftp(5)[3] Command: SSH_FXP_STAT (3, '/IN/SINNestor/ASAA13E098.tmp')
2014-05-12 10:52:32.487 INFO Sftp(5)[3] Response: SSH_FXP_STATUS (3, 2, '/IN/SINNestor/ASAA13E098.tmp is not a valid file path')
2014-05-12 10:52:32.505 INFO Sftp(5)[3] Command: SSH_FXP_OPEN (4, '/IN/SINNestor/ASAA13E098.tmp', 26)
2014-05-12 10:52:32.636 INFO Sftp(5)[3] Response: SSH_FXP_HANDLE (4, 0x30)
2014-05-12 10:52:32.641 DEBUG Sftp(5)[3] Command: SSH_FXP_WRITE (5, 0x30, 0, 28672 bytes)
2014-05-12 10:52:32.795 DEBUG Sftp(5)[3] Command: SSH_FXP_WRITE (6, 0x30, 28672, 28672 bytes)
2014-05-12 10:52:32.898 DEBUG Sftp(5)[3] Command: SSH_FXP_WRITE (7, 0x30, 57344, 28672 bytes)
2014-05-12 10:52:33.034 DEBUG Sftp(5)[3] Command: SSH_FXP_WRITE (8, 0x30, 86016, 2578 bytes)
2014-05-12 10:52:33.035 DEBUG Sftp(5)[3] Response: SSH_FXP_STATUS (5, 0, 'The write completed s

Answer 1

Thanks for the log!

According to the log, the "Resource busy. Failed to rename /IN/SINNestor/ASAA13E100.tmp to /IN/SINNestor/ASAA13E100.txt because the file is currently in progress." messages actually comes from the SFTP server which failed to rename a file.

However, the log also proves that the file was completely uploaded and the handle obtained by a SSH_FXP_OPEN request was properly closed by a corresponding SSH_FXP_CLOSE request. When the SSH_FXP_RENAME request was received by the server, the SFTP client certainly was not accessing the file in any way.

Unfortunately, this means that there is not much the client can do - your code (and Rebex SFTP) doesn't do anything wrong, it's the server that is refusing the rename request for some reason... For example, it's possible that as soon as a file is completely uploaded, the server itself keeps it locked for a short time while updating its database or scanning it for malicious code. Without access to the server, we can't really tell, but it looks like some process is in fact going when the file has been uploaded.

At this point, I would recommend experimenting a bit with simple workarounds such as retrying the rename operation after a delay - to detect this kind of error, catch SftpException and check whether its Status property is SftpExceptionStatus.ProtocolError and whether its Code property is SftpErrorCode.Failure. Please let me know whether this has any effect.