Rename succeeds but throws exception

Question

Hi,

when calling Rename the method throws the following exception:

Rebex.Net.SftpException: Failure; Unable to rename file or folder.
at nnuz.vwje(xdaf are, Type arf)
at Rebex.Net.Sftp.xhfq(String sh, String si, nnui sj)

But even though there is an exception the remote file is properly renamed, so I guess the parameters are good.

My problem is to distinguish this false negative (rename succeeded and exception thrown) from a real negative (rename failed and exception is thrown).

Any ideas?

Thanks,
Sascha

Answer 1

Hi,

as requested I logged everything at debug level. What's strange is that the file permissions shown in the log are not the permissions I can see when using e.g. winSCP. In winSCP the file permissions are rw-rw-rw, while in the log only the owner has rw. I can't validate it, but I doubt that my sftp-user is the owner of the files. Anyways, despite the exception shown in the log the file was properly renamed.

Here comes the log (some line removed due to max 8000 char limitation of the forum):

2019-01-07 06:15:00.729 Opening log file.
2019-01-07 06:15:00.729 INFO FileLogWriter(1)[5] Info: Assembly: Rebex.Common 2018 R4 for .NET 4.0-4.7
2019-01-07 06:15:00.744 INFO FileLogWriter(1)[5] Info: Platform: Windows 6.2.9200 64-bit; CLR: 4.0.30319.42000
2019-01-07 06:15:00.744 DEBUG FileLogWriter(1)[5] Info: Culture: de; Windows-1252
2019-01-07 06:15:00.760 INFO Sftp(1)[5] Info: Connecting to 217.243.172.107:22 using Sftp.
2019-01-07 06:15:00.760 INFO Sftp(1)[5] Info: Assembly: Rebex.Sftp 2018 R4 for .NET 4.0-4.7
2019-01-07 06:15:00.760 INFO Sftp(1)[5] Info: Platform: Windows 6.2.9200 64-bit; CLR: 4.0.30319.42000
2019-01-07 06:15:00.760 DEBUG Sftp(1)[5] Info: Culture: de; Windows-1252
2019-01-07 06:15:00.760 INFO Sftp(1)[5] Info: Using proxy SOCKS5 XXXXXXXXX.
2019-01-07 06:15:00.776 DEBUG Sftp(1)[5] Proxy: Resolving 'xxxxxxxxxxx'.
2019-01-07 06:15:00.791 DEBUG Sftp(1)[5] Proxy: Connecting to SOCKS5 proxy at xxxxxxxxxx
2019-01-07 06:15:00.791 DEBUG Sftp(1)[5] Proxy: Connecting to xxxxxxxxxxx through a proxy.
2019-01-07 06:15:00.807 DEBUG Sftp(1)[5] Proxy: Connection esatblished successfully.
2019-01-07 06:15:00.838 DEBUG Sftp(1)[5] SSH: Server is 'SSH-2.0-CerberusFTPServer9.0'.
2019-01-07 06:15:00.838 INFO Sftp(1)[5] SSH: Negotiation started.
2019-01-07 06:15:01.041 DEBUG Sftp(1)[5] SSH: Group exchange.
2019-01-07 06:15:01.119 DEBUG Sftp(1)[5] SSH: Negotiating key.
2019-01-07 06:15:01.166 DEBUG Sftp(1)[5] SSH: Received 2048-bit Diffie-Hellman prime (minimum allowed size is 1024 bits).
2019-01-07 06:15:01.276 DEBUG Sftp(1)[5] SSH: Validating signature.
2019-01-07 06:15:01.369 DEBUG Sftp(1)[5] SSH: Received 2048-bit RSA server key (minimum allowed size is 1023 bits).
2019-01-07 06:15:01.385 INFO Sftp(1)[5] SSH: Negotiation finished.
2019-01-07 06:15:01.385 INFO Sftp(1)[5] Info: Server: SSH-2.0-CerberusFTPServer9.0
2019-01-07 06:15:01.385 INFO Sftp(1)[5] Info: Fingerprint (MD5): f9:fe:2a:f7:9f:91:4f:39:60:2e:6b:c0:0b:c6:ea:19
2019-01-07 06:15:01.385 INFO Sftp(1)[5] Info: Fingerprint (SHA-256): nVryhc0l6KvO8zB15Jjx9GN2hTjTkIHcH0ib1LX66ag
2019-01-07 06:15:01.385 INFO Sftp(1)[5] Info: Cipher info: SSH 2.0, diffie-hellman-group-exchange-sha256, ssh-rsa, aes256-ctr/aes256-ctr, hmac-sha2-256/hmac-sha2-256
2019-01-07 06:15:01.479 DEBUG Sftp(1)[5] SSH: Allowed authentication methods for 'xxxxxxxxxx': password, publickey.
2019-01-07 06:15:01.479 DEBUG Sftp(1)[5] SSH: Trying password authentication for 'xxxxxxxxxxxx'.
2019-01-07 06:15:01.494 DEBUG Sftp(1)[5] SSH: Authentication successful.
2019-01-07 06:15:01.510 DEBUG Sftp(1)[5] SSH: Opening channel 'session' (initial window size: 131072, max packet size: 129024).
2019-01-07 06:15:01.526 DEBUG Sftp(1)[5] SSH: Requesting subsystem 'sftp'.
2019-01-07 06:15:01.557 INFO Sftp(1)[5] Command: SSHFXPINIT (4)
2019-01-07 06:15:01.573 INFO Sftp(1)[5] Response: SSHFXPVERSION (4, 2 extensions)
2019-01-07 06:15:01.573 INFO Sftp(1)[5] Info: Using SFTP v4 on a Windows-like platform.
2019-01-07 06:15:01.573 INFO Sftp(1)[5] Command: SSHFXPREALPATH (1, '.')
2019-01-07 06:15:01.588 INFO Sftp(1)[5] Response: SSHFXPNAME (1, 1 item)
2019-01-07 06:15:01.588 INFO Sftp(1)[5] Info: Home directory is '/'.
2019-01-07 06:15:01.604 INFO Sftp(1)[5] Command: SSHFXPOPENDIR (2, '/PROD-OUT')
2019-01-07 06:15:01.619 INFO Sftp(1)[5] Response: SSHFXPHANDLE (2, 0x7B45443645433137412D393544312D344437462D423234312D3841384630344241424135337D)
2019-01-07 06:15:01.619 INFO Sftp(1)[5] Command: SSHFXPREADDIR (3, 0x7B45443645433137412D393544312D344437462D423234312D3841384630344241424135337D)
2019-01-07 06:15:01.635 INFO Sftp(1)[5] Response: SSHFXPNAME (3, 40 items)
[...]
2019-01-07 06:15:01.869 DEBUG Sftp(1)[5] Info: Requests arrived.
2019-01-07 06:15:01.869 INFO Sftp(1)[5] Command: SSHFXPCLOSE (23, 0x7B33463233374441412D353138372D343937422D383732462D4146324136333938324346457D)
2019-01-07 06:15:01.885 INFO Sftp(1)[5] Response: SSHFXPSTATUS (23, 0, '')
2019-01-07 06:15:01.901 INFO Sftp(1)[5] Command: SSHFXPRENAME (24, '/PROD-OUT/LOGPDS20181023103306.xlsx', '/PROD-OUT/LOG_PDS20181023103306.xlsx.done')
2019-01-07 06:15:01.901 INFO Sftp(1)[5] Response: SSHFXPSTATUS (24, 0, 'File successfully renamed')
2019-01-07 06:15:01.901 INFO Sftp(1)[5] Command: SSHFXPRENAME (25, '/PROD-OUT/LOGPDS20181023103306.xlsx', '/PROD-OUT/LOG_PDS20181023103306.xlsx.done')
2019-01-07 06:15:01.916 INFO Sftp(1)[5] Response: SSH_FXP_STATUS (25, 4, 'Unable to rename file or folder')
2019-01-07 06:15:01.932 ERROR Sftp(1)[5] Info: Rebex.Net.SftpException: Failure; Unable to rename file or folder.
at kuwh.vidj(snro are, Type arf)
at Rebex.Net.Sftp.nqzc(String sh, String si, kuvq sj)

Comments

Thank you for the log. It showed, that you are calling the Rename() method two times.
The first call succeeded. Second call failed, because there was no such file yet.

Please ensure that you are calling the Rename() method for given parameters only once.

---

Arrggh!! Yes, you are right. I missed the second rename in my own code. Thanks for helping me out and for your quick response.

Sascha

Answer 2

Can you please create communication log in Debug level and post it here or send it to support@rebex.net for analysis. Using it, we should be able to tell what is going on and how to prevent false negative.

The log can be created like this:

var client = new Ftp();
client.LogWriter = new Rebex.FileLogWriter("c:/data/ftp.log", Rebex.LogLevel.Debug);