Ask a Question

Sftp.PutFile() doesn't fail, but server doesn't get the file, what could be the possible reason?

0 votes
by (220 points)

How do we know that PutFile() has failed? what are the exceptions it throws, if any?

The problem, we are facing is that on calling PutFile() it returns the number of bytes equal to the size of the file which is to be uploaded, but when we checked on server, the file is missing from there. What could be the possible causes?

code snippet:
long result = sftpClient.PutFile(filePath, string.Format("/{0}/{1}", pathToPlaceFile, fileNameToBeTransferred));

Applies to: Rebex SFTP
by (73.5k points)
Can you please create communication log and send it to support@rebex.net or post it here?
If the client sends the whole file, but the file is missing at server, it is probably some issue on the server. The log should give light where the problem is.

The log can be created like:
sftpClient.LogWriter = new Rebex.FileLogWriter(@"c:\data\sftp.log", Rebex.LogLevel.Debug);
by (220 points)
I got the following log, please have a look.
2019-06-17 11:44:49.271 Opening log file.
2019-06-17 11:44:49.271 INFO FileLogWriter(4)[74] Info: Assembly: Rebex.Common 2019 R2 for .NET 4.0-4.7
2019-06-17 11:44:49.271 INFO FileLogWriter(4)[74] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2019-06-17 11:44:49.294 DEBUG FileLogWriter(4)[74] Info: Culture: en; Windows-1252
2019-06-17 11:44:49.313 DEBUG Sftp(7)[74] SSH: Allowed authentication methods for 'u_db-transfer-mngmt': publickey, keyboard-interactive.
2019-06-17 11:44:49.313 DEBUG Sftp(7)[74] SSH: Trying public key authentication for 'u_db-transfer-mngmt'.
2019-06-17 11:44:51.222 DEBUG Sftp(7)[74] SSH: Authentication successful.
2019-06-17 11:44:51.222 DEBUG Sftp(7)[74] SSH: Opening channel 'session' (initial window size: 131072, max packet size: 129024).
2019-06-17 11:44:51.234 DEBUG Sftp(7)[84] SSH: Received debug message: /var/sftp/u_db-transfer-mngmt/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
2019-06-17 11:44:51.274 DEBUG Sftp(7)[74] SSH: Requesting subsystem 'sftp'.
2019-06-17 11:44:51.277 DEBUG Sftp(7)[84] SSH: Adjusted remote window size: 0 -> 2097152.
2019-06-17 11:44:51.277 INFO Sftp(7)[74] Command: SSH_FXP_INIT (4)
2019-06-17 11:44:51.283 INFO Sftp(7)[74] Response: SSH_FXP_VERSION (3, 5 extensions)
2019-06-17 11:44:51.283 INFO Sftp(7)[74] Info: Using SFTP v3 on a Unix-like platform.
2019-06-17 11:44:51.283 INFO Sftp(7)[74] Command: SSH_FXP_REALPATH (1, '.')
2019-06-17 11:44:51.285 INFO Sftp(7)[74] Response: SSH_FXP_NAME (1, 1 item)
2019-06-17 11:44:51.285 INFO Sftp(7)[74] Info: Home directory is '/'.
2019-06-17 11:44:51.286 INFO Sftp(7)[74] Command: SSH_FXP_OPEN (2, '/db/db.sqlite', 26)
2019-06-17 11:44:51.287 INFO Sftp(7)[74] Response: SSH_FXP_HANDLE (2, 0x0)
2019-06-17 11:44:51.289 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (3, 0x0, 0, 28672 bytes)
2019-06-17 11:44:51.289 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (4, 0x0, 28672, 28672 bytes)
2019-06-17 11:44:51.289 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (5, 0x0, 57344, 28672 bytes)
2019-06-17 11:44:51.292 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (6, 0x0, 86016, 28672 bytes)
2019-06-17 11:44:51.292 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (7, 0x0, 114688, 28672 bytes)
2019-06-17 11:44:51.292 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (8, 0x0, 143360, 28672 bytes)
2019-06-17 11:44:51.294 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (9, 0x0, 172032, 28672 bytes)
2019-06-17 11:44:51.320 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (10, 0x0, 200704, 28672 bytes)
2019-06-17 11:44:51.320 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (11, 0x0, 229376, 28672 bytes)
2019-06-17 11:44:51.347 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (3, 0, 'Success')
2019-06-17 11:44:51.347 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (12, 0x0, 258048, 28672 bytes)
2019-06-17 11:44:51.374 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (4, 0, 'Success')
2019-06-17 11:44:51.374 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (13, 0x0, 286720, 28672 bytes)
2019-06-17 11:44:51.398 DEBUG Sftp(7)[84] SSH: Adjusted remote window size: 1781370 -> 1896245.
2019-06-17 11:44:51.398 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (5, 0, 'Success')
2019-06-17 11:44:51.401 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (14, 0x0, 315392, 28672 bytes)
2019-06-17 11:44:51.421 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (6, 0, 'Success')
2019-06-17 11:44:51.422 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (15, 0x0, 344064, 28672 bytes)
2019-06-17 11:44:51.445 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (7, 0, 'Success')
2019-06-17 11:44:51.446 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (16, 0x0, 372736, 28672 bytes)
2019-06-17 11:44:51.469 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (8, 0, 'Success')
2019-06-17 11:44:51.469 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (17, 0x0, 401408, 28672 bytes)
2019-06-17 11:44:51.493 DEBUG Sftp(7)[84] SSH: Adjusted remote window size: 1781441 -> 1896245.
2019-06-17 11:44:51.494 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (9, 0, 'Success')
2019-06-17 11:44:51.874 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (34, 0x0, 888832, 28672 bytes)
2019-06-17 11:44:51.898 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (26, 0, 'Success')
2019-06-17 11:44:51.898 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (35, 0x0, 917504, 28672 bytes)
2019-06-17 11:44:51.923 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (27, 0, 'Success')
2019-06-17 11:44:51.924 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (36, 0x0, 946176, 28672 bytes)
2019-06-17 11:44:51.947 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (28, 0, 'Success')
2019-06-17 11:44:51.947 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (37, 0x0, 974848, 28672 bytes)
2019-06-17 11:44:51.970 DEBUG Sftp(7)[84] SSH: Adjusted remote window size: 1781441 -> 1896245.
2019-06-17 11:44:51.970 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (29, 0, 'Success')
2019-06-17 11:44:51.970 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (38, 0x0, 1003520, 28672 bytes)
2019-06-17 11:44:51.994 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (30, 0, 'Success')
2019-06-17 11:44:51.995 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (39, 0x0, 1032192, 28672 bytes)
2019-06-17 11:44:52.019 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (31, 0, 'Success')
2019-06-17 11:44:52.019 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (40, 0x0, 1060864, 28672 bytes)
2019-06-17 11:44:52.043 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (32, 0, 'Success')
2019-06-17 11:44:52.043 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (41, 0x0, 1089536, 28672 bytes)
2019-06-17 11:44:52.066 DEBUG Sftp(7)[84] SSH: Adjusted remote window size: 1781441 -> 1896245.
2019-06-17 11:44:52.067 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (33, 0, 'Success')
2019-06-17 11:44:52.067 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (42, 0x0, 1118208, 28672 bytes)
2019-06-17 11:44:52.091 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (34, 0, 'Success')
2019-06-17 11:44:52.091 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (43, 0x0, 1146880, 28672 bytes)
2019-06-17 11:44:52.114 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (35, 0, 'Success')
2019-06-17 11:44:52.115 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (44, 0x0, 1175552, 28672 bytes)
2019-06-17 11:44:52.146 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (36, 0, 'Success')
2019-06-17 11:44:52.147 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (45, 0x0, 1204224, 28672 bytes)
2019-06-17 11:44:52.162 DEBUG Sftp(7)[84] SSH: Adjusted remote window size: 1781441 -> 1896245.
2019-06-17 11:44:52.162 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (37, 0, 'Success')
2019-06-17 11:44:52.163 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (46, 0x0, 1232896, 28672 bytes)
2019-06-17 11:44:52.192 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (38, 0, 'Success')
2019-06-17 11:44:52.193 DEBUG Sftp(7)[74] Command: SSH_FXP_WRITE (47, 0x0, 1261568, 20480 bytes)
2019-06-17 11:44:52.209 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (39, 0, 'Success')
2019-06-17 11:44:52.232 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (40, 0, 'Success')
2019-06-17 11:44:52.254 DEBUG Sftp(7)[84] SSH: Adjusted remote window size: 1847035 -> 1961839.
2019-06-17 11:44:52.255 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (41, 0, 'Success')
2019-06-17 11:44:52.277 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (42, 0, 'Success')
2019-06-17 11:44:52.299 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (43, 0, 'Success')
2019-06-17 11:44:52.321 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (44, 0, 'Success')
2019-06-17 11:44:52.344 DEBUG Sftp(7)[84] SSH: Adjusted remote window size: 1961839 -> 2076643.
2019-06-17 11:44:52.344 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (45, 0, 'Success')
2019-06-17 11:44:52.361 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (46, 0, 'Success')
2019-06-17 11:44:52.361 DEBUG Sftp(7)[74] Response: SSH_FXP_STATUS (47, 0, 'Success')
2019-06-17 11:44:52.361 INFO Sftp(7)[74] Command: SSH_FXP_CLOSE (48, 0x0)
2019-06-17 11:44:52.363 INFO Sftp(7)[74] Response: SSH_FXP_STATUS (48, 0, 'Success')

1 Answer

0 votes
by (73.5k points)

Thank you for the log. It showed that the whole file was successfully uploaded to the server and the server replied with success acknowledgement:

Command: SSH_FXP_CLOSE (48, 0x0)
Response: SSH_FXP_STATUS (48, 0, 'Success')

From client side, everything went correctly.

Couple ideas:

  • Ensure that the file was not moved somewhere else, some servers do similar things.
  • Check the file existence immediately after the upload by calling sftp.FileExists("/db/db.sqlite") or sftp.GetInfo("/db/db.sqlite").
  • The upload was performed using transfer queue, some servers can have issues with it (but they should not report success on close). Try to disable transfer queue by setting sftp.Settings.DisableTransferQueue = true before you connect.
  • Does the upload works when using other SFTP client such as WinSCP or Filezilla?
...