SFTP Upload fails (Failure; Transfer failed. AuditID=AA1120011373.)

Question

I've been trying to figure out the issue with the SFTP transfer and don't seem to be able to find any possible solution. First of all - there are no problems during a connection established manually through Filezilla and such. I'm able to connect, navigate to the folder, upload. When I try to upload the file using rebex - I'm getting an exception when I call PutFile method on SFTP. You can find the example of my code below (nothing special there, and we have it running just fine for many other SFTP clients, with the exception of this particular one). I have also attached the logwriter to see if I can make any sense out of it. By looking at it (also included below) it seems that it fails during the close event, and that the file, in fact, did transfer successfully. Am I correct?

Any help would be appreciated. Thank you,

Here is just a small excerpt of my code:

        sftp.Connect(url, port)
        sftp.Login(login, pw)
        Try
            sftp.ChangeDirectory(path)
            sftp.PutFile(tempFile, "test.txt")
        Catch ex As Exception

        End Try

And the piece of the log that I captured.

2012-10-11 20:07:15.179 VERBOSE Sftp(1)[9] SSH: Sending packet SSH_MSG_CHANNEL_DATA (53 bytes).
 0000 |5E-00-00-00-00-00-00-00 2C-00-00-00-28-03-00-00| ^.......,...(...
 0010 |00-04-00-00-00-17-2F-68 6F-6D-65-2F-63-70-69-6D| ....../home/cpim
 0020 |6F-64-30-31-2F-74-65-73 74-2E-74-78-74-00-00-00| od01/test.txt...
 0030 |1A-00-00-00-00                                 | .....

2012-10-11 20:07:15.181 INFO Sftp(1)[9] Command: SSH_FXP_OPEN (4, '/home/cpimod01/test.txt', 26)

2012-10-11 20:07:16.025 VERBOSE Sftp(1)[9] SSH: Received packet SSH_MSG_CHANNEL_DATA (24 bytes).
 0000 |5E-00-00-00-00-00-00-00 0F-00-00-00-0B-66-00-00| ^............f..
 0010 |00-04-00-00-00-02-32-36                        | ......26

2012-10-11 20:07:16.027 INFO Sftp(1)[9] Response: SSH_FXP_HANDLE (4, 0x3236)

2012-10-11 20:07:16.033 VERBOSE Sftp(1)[9] SSH: Sending packet SSH_MSG_CHANNEL_DATA (74 bytes).
 0000 |5E-00-00-00-00-00-00-00 41-00-00-00-3D-06-00-00| ^.......A...=...
 0010 |00-05-00-00-00-02-32-36 00-00-00-00-00-00-00-00| ......26........
 0020 |00-00-00-26-54-68-69-73 20-69-73-20-61-20-74-65| ...&This is a te
 0030 |73-74-20-66-69-6C-65-2E 20-50-6C-65-61-73-65-20| st file. Please 
 0040 |64-69-73-72-65-67-61-72 64-21                  | disregard!

2012-10-11 20:07:16.034 DEBUG Sftp(1)[9] Command: SSH_FXP_WRITE (5, 0x3236, 0, 38 bytes)

2012-10-11 20:07:16.088 VERBOSE Sftp(1)[9] SSH: Received packet SSH_MSG_CHANNEL_DATA (62 bytes).
 0000 |5E-00-00-00-00-00-00-00 35-00-00-00-31-65-00-00| ^.......5...1e..
 0010 |00-05-00-00-00-00-00-00 00-20-54-68-65-20-77-72| ......... The wr
 0020 |69-74-65-20-63-6F-6D-70 6C-65-74-65-64-20-73-75| ite completed su
 0030 |63-63-65-73-73-66-75-6C 6C-79-00-00-00-00      | ccessfully....
2012-10-11 20:07:16.089 DEBUG Sftp(1)[9] Response: SSH_FXP_STATUS (5, 0, 'The write completed successfully')

2012-10-11 20:07:16.091 VERBOSE Sftp(1)[9] SSH: Sending packet SSH_MSG_CHANNEL_DATA (24 bytes).
 0000 |5E-00-00-00-00-00-00-00 0F-00-00-00-0B-04-00-00| ^...............
 0010 |00-06-00-00-00-02-32-36                        | ......26
2012-10-11 20:07:16.092 INFO Sftp(1)[9] Command: SSH_FXP_CLOSE (6, 0x3236)

2012-10-11 20:07:16.376 VERBOSE Sftp(1)[9] SSH: Received packet SSH_MSG_CHANNEL_DATA (67 bytes).
 0000 |5E-00-00-00-00-00-00-00 3A-00-00-00-36-65-00-00| ^.......:...6e..
 0010 |00-06-00-00-00-04-00-00 00-25-54-72-61-6E-73-66| .........%Transf
 0020 |65-72-20-66-61-69-6C-65 64-2E-20-41-75-64-69-74| er failed. Audit
 0030 |49-44-3D-41-41-31-31-32 30-30-31-31-36-33-32-00| ID=AA1120011632.
 0040 |00-00-00                                       | ...

2012-10-11 20:07:16.376 INFO Sftp(1)[9] Response: SSH_FXP_STATUS (6, 4, 'Transfer failed. AuditID=AA1120011632')

2012-10-11 20:07:16.407 ERROR Sftp(1)[9] Info: Rebex.Net.SftpException: Failure; Transfer failed. AuditID=AA1120011632.
   at gbMKS.PEQpz.eCVvJZ(1dRwomZ , Type )
   at gbMKS.PEQpz.1GGhpaZ(PTFpRZ , Boolean )
   at Rebex.Net.Sftp.1xTmHi(Qu2Ci , udycp , String , Stream , Int64 , Int64 , 27NpLhZ )

Answer 1

Yes, you are correct - first, the SSH_FXP_OPEN command succeeded and sent back the handle. Then, SSH_FXP_WRITE succeeded as well and 38 bytes were written. But when closing the handle, the server reported an error in response to SSH_FXP_CLOSE command. The error message of "Transfer failed. AuditID=AA1120011632" actually comes from the server. While trying to find something about it, I stumbled upon a similar issue, but with FTP protocol. According to the server manual, the audid ID is supposed to be a "record number associated with the file transfer request" and it can be "used in a URL to point to the audit record for the file that was transferred". Perhaps the server administrators might be able to tell what is going on based on this ID?

In any case, it is very strange the same operation seems to work in Filezilla. Once an SFTP session is established, an upload of a 38-byte file is a very simple operation and the actual commands being sent should be the same. Unfortunately, Filezilla is unable to create a log verbose enough to actually show the commands. Would it be possible to try using WinSCP instead? It can create verbose logs and if it works as well, this would make it possible to spot any difference and change Rebex SFTP's behavior accordingly.

Answer 2

Thank you for a quick response, Lukas. I just tried using the WinSCP and seeing a similar behavior when I just tried to upload a dummy file (see screenshot:

Below is a part of the log that I was able to obtain from the WinSCP

. 2012-10-12 07:52:43.389 Enter password for cpimod01, Password:)
. 2012-10-12 07:52:43.390 Using stored password.
. 2012-10-12 07:52:43.964 Access granted
. 2012-10-12 07:52:43.997 Opened channel for session
. 2012-10-12 07:52:44.226 Started a shell/command
. 2012-10-12 07:52:44.266 --------------------------------------------------------------------------
. 2012-10-12 07:52:44.266 Using SFTP protocol.
. 2012-10-12 07:52:44.267 Doing startup conversation with host.

> 2012-10-12 07:52:44.321 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2012-10-12 07:52:44.355 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2012-10-12 07:52:44.356 SFTP version 3 negotiated.
. 2012-10-12 07:52:44.356 We believe the server has signed timestamps bug
. 2012-10-12 07:52:44.356 We will use UTF-8 strings for status messages only
. 2012-10-12 07:52:44.375 Changing directory to "/home/cpimod01".
. 2012-10-12 07:52:44.375 Getting real path for '/home/cpimod01'
> 2012-10-12 07:52:44.375 Type: SSH_FXP_REALPATH, Size: 23, Number: 6416
< 2012-10-12 07:52:44.507 Type: SSH_FXP_NAME, Size: 69, Number: 6416
. 2012-10-12 07:52:44.507 Real path is '/home/cpimod01'
. 2012-10-12 07:52:44.507 Trying to open directory "/home/cpimod01".
> 2012-10-12 07:52:44.507 Type: SSH_FXP_LSTAT, Size: 23, Number: 6663
< 2012-10-12 07:52:44.567 Type: SSH_FXP_ATTRS, Size: 29, Number: 6663
. 2012-10-12 07:52:44.567 Getting current directory name.
. 2012-10-12 07:52:44.673 Listing directory "/home/cpimod01".
> 2012-10-12 07:52:44.673 Type: SSH_FXP_OPENDIR, Size: 23, Number: 6923
< 2012-10-12 07:52:44.746 Type: SSH_FXP_HANDLE, Size: 11, Number: 6923
> 2012-10-12 07:52:44.747 Type: SSH_FXP_READDIR, Size: 11, Number: 7180
< 2012-10-12 07:52:44.779 Type: SSH_FXP_STATUS, Size: 28, Number: 7180
< 2012-10-12 07:52:44.779 Status code: 1
. 2012-10-12 07:52:44.779 Listing file "/home/cpimod01/..".
> 2012-10-12 07:52:44.780 Type: SSH_FXP_LSTAT, Size: 26, Number: 7431
< 2012-10-12 07:52:44.812 Type: SSH_FXP_ATTRS, Size: 29, Number: 7431
> 2012-10-12 07:52:44.812 Type: SSH_FXP_CLOSE, Size: 11, Number: 7684
. 2012-10-12 07:52:44.872 Startup conversation with host finished.
. 2012-10-12 07:52:57.388 Copying 1 files/directories to remote directory "/home/cpimod01/"
. 2012-10-12 07:52:57.388   PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: Yes; Mask: *.*
. 2012-10-12 07:52:57.388   TM: B; ClAr: No; CPS: 0; InclM: 
. 2012-10-12 07:52:57.388   AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2012-10-12 07:52:57.388 File: "D:\Temp\FTPTest1.pgp"
. 2012-10-12 07:52:57.391 Copying "D:\Temp\FTPTest1.pgp" to remote directory started.
. 2012-10-12 07:52:57.391 Binary transfer mode selected.
. 2012-10-12 07:52:57.392 Opening remote file.
> 2012-10-12 07:52:57.392 Type: SSH_FXP_OPEN, Size: 52, Number: 7939
< 2012-10-12 07:52:57.392 Type: SSH_FXP_STATUS, Size: 40, Number: 7684
. 2012-10-12 07:52:57.392 Discarding reserved response
< 2012-10-12 07:52:58.478 Type: SSH_FXP_HANDLE, Size: 11, Number: 7939
> 2012-10-12 07:52:58.496 Type: SSH_FXP_WRITE, Size: 64, Number: 8454
> 2012-10-12 07:52:58.496 Type: SSH_FXP_CLOSE, Size: 11, Number: 8708
> 2012-10-12 07:52:58.496 Type: SSH_FXP_SETSTAT, Size: 48, Number: 8201
< 2012-10-12 07:52:58.528 Type: SSH_FXP_STATUS, Size: 49, Number: 8454
< 2012-10-12 07:52:58.742 Type: SSH_FXP_STATUS, Size: 54, Number: 8708
< 2012-10-12 07:52:58.743 Status code: 4, Message: 8708, Server: Transfer failed. AuditID=AA1220001411, Language:  
* 2012-10-12 07:52:58.743 (ETerminal) General failure (server should provide error description).
* 2012-10-12 07:52:58.743 Error code: 4
* 2012-10-12 07:52:58.743 Error message from server: Transfer failed. AuditID=AA1220001411
* 2012-10-12 07:52:58.743 Request code: 4
. 2012-10-12 07:52:58.844 Asking user:
. 2012-10-12 07:52:58.844 Cannot close remote file 'FTPTest1.pgp'. ("General failure (server should provide error description).
. 2012-10-12 07:52:58.844 Error code: 4
. 2012-10-12 07:52:58.844 Error message from server: Transfer failed. AuditID=AA1220001411
. 2012-10-12 07:52:58.844 Request code: 4")
* 2012-10-12 07:53:01.245 (EScpSkipFile) Cannot close remote file 'FTPTest1.pgp'.
* 2012-10-12 07:53:01.245 General failure (server should provide error description).
* 2012-10-12 07:53:01.245 Error code: 4
* 2012-10-12 07:53:01.245 Error message from server: Transfer failed. AuditID=AA1220001411
* 2012-10-12 07:53:01.245 Request code: 4
. 2012-10-12 07:53:01.246 Listing directory "/home/cpimod01".
> 2012-10-12 07:53:01.246 Type: SSH_FXP_OPENDIR, Size: 23, Number: 8971
< 2012-10-12 07:53:01.246 Type: SSH_FXP_STATUS, Size: 40, Number: 8201
. 2012-10-12 07:53:01.246 Discarding reserved response
< 2012-10-12 07:53:01.321 Type: SSH_FXP_HANDLE, Size: 11, Number: 8971
> 2012-10-12 07:53:01.322 Type: SSH_FXP_READDIR, Size: 11, Number: 9228
< 2012-10-12 07:53:01.359 Type: SSH_FXP_STATUS, Size: 28, Number: 9228
< 2012-10-12 07:53:01.360 Status code: 1
. 2012-10-12 07:53:01.360 Listing file "/home/cpimod01/..".
> 2012-10-12 07:53:01.360 Type: SSH_FXP_LSTAT, Size: 26, Number: 9479
< 2012-10-12 07:53:01.398 Type: SSH_FXP_ATTRS, Size: 29, Number: 9479
> 2012-10-12 07:53:01.398 Type: SSH_FXP_CLOSE, Size: 11, Number: 9732

I'm not a pro at SFTP and not really sure what exactly is going on here, but am I safe to assume that it is the issue on the client's end? Do you know if the file, in fact, did transfer and error message only caused by attempting to close a connection? And if so - is there any way to overcome this in code (so it doesn't throw an exception). Or did the failure occur during the transfer?

The other interesting part I noticed in the log is this :

. 2012-10-12 07:52:44.356 We believe the server has signed timestamps bug

Could this be the reason for a failure? Thank you once again for your help. N

Answer 3

Thanks for update!

Am I safe to assume that it is the issue on the client's end?

I would not assume the issue is on the client's end - two different SFTP clients (WinSCP and Rebex SFTP) encountered an identical issue, which strongly indicates this is actually a server-side problem.

I'm wondering why there was no error in FileZilla now. Have you checked its log? It's not very verbosem, but there still might be some information. It's even possible it encountered this error as well but ignored it.

Do you know if the file, in fact, did transfer and error message only caused by attempting to close a connection?

SFTP protocol is actually a remote file system protocol. It doesn't have a single "transfer a file" operation (in contrast to FTP), but instead defines the following commands (among others):

1. SSH_FXP_OPEN - Opens or creates a specified file in specified mode and returns its handle (to be used by subsequent operations).
2. SSH_FXP_WRITE - Writes a block of data to the specified offset in the file identified by the supplied handle.
3. SSH_FXP_CLOSE - Closes a file identified by the supplied handle.

An SFTP client actually opens the file first, then uploads the data, and finally it closes the file (this resembles .NET's System.IO.FileStream object). The issue encountered by Rebex SFTP and WinSCP is during the SSH_FXP_CLOSE command - the server reports an error when SFTP client tries closing the file, which is very strange. That's why WinSCP says "Cannot close remote file".

Is there any way to overcome this in code (so it doesn't throw an exception).

You might catch SftpException and check whether its Status property indicates SftpExceptionStatus.ProtocolError. If it does, it means that the server reported an error (such as the one above), but the Sftp object is still usable. Try calling an Sftp method such as GetFileLength to check the remote file length - if it is the same as the length of the file being uploaded, then the transfer most likely succeeded. The problem is that the file might be still open (depending on whether the SSH_FXP_CLOSE actually closed the file before failing), but it should be closed as soon as you disconnect from the server anyway.

Or did the failure occur during the transfer?

No, the SSH_FXP_STATUS response indicates the write operation was successful (the 'The write completed successfully' message actually comes from the server).

The other interesting part I noticed in the log is this: 2012-10-12 07:52:44.356 We believe the server has signed timestamps bug Could this be the reason for a failure?

This is not related to the issue. WinSCP reports this message for all servers using SFTP v3 by default, regardless whether there is a bug or not. The bug itself - if present - only means that "files on the server with timestamps before 1970 will be interpreted by WinSCP as times after 2038". See the end of this page for details.