System.InvalidOperationException: Not enough data

0 votes
asked Feb 28 by Fazul (120 points)

Getting the following exception while uploading the files.

System.InvalidOperationException: Not enough data.
at Rebex.Net.CCD.T()
at Rebex.Net.CCD.I()
at Rebex.Net.SftpAttributes..ctor(CCD W, Int32 O)
at Rebex.Net.QVD..ctor(Byte[] W, Int32 O, Int32 C, Encoding N, Int32 V)
at Rebex.Net.ZND.JC(VCD& W)
at Rebex.Net.ZND.JC(UInt32 W, Boolean O)
at Rebex.Net.ZND.MC(VCD W, UInt32 O, JCD C)
at Rebex.Net.ZND.GO(String W, Boolean O, Boolean C, Boolean N, MND V, IND& D, JCD A)
at Rebex.Net.Sftp.HEO(String W, Boolean O, Boolean

Applies to: Rebex SFTP
commented Feb 28 by Lukas Matyska (52,730 points)
Can you please create communication log in Debug level and post it here or send it to support@rebex.net for analysis? It can be done as described at https://www.rebex.net/kb/logging/
commented Apr 3 by Fazul (120 points)
2019-04-02 15:16:24.380 VERBOSE Sftp(1)[1] SSH: Sending packet SSH_MSG_USERAUTH_REQUEST (43 bytes).
 0000 |32-00-00-00-0C-69-74-61 6C-67-61-73-77-61-74-65| 2....italgaswate
 0010 |72-00-00-00-0E-73-73-68 2D-63-6F-6E-6E-65-63-74| r....ssh-connect
 0020 |69-6F-6E-00-00-00-04-6E 6F-6E-65               | ion....none
2019-04-02 15:16:24.396 VERBOSE Sftp(1)[7] SSH: Received packet SSH_MSG_USERAUTH_FAILURE (14 bytes).
 0000 |33-00-00-00-08-70-61-73 73-77-6F-72-64-00      | 3....password.
2019-04-02 15:16:24.396 DEBUG Sftp(1)[1] SSH: Allowed authentication methods for 'italgaswater': password.
2019-04-02 15:16:24.411 DEBUG Sftp(1)[1] SSH: Trying password authentication for 'italgaswater'.
2019-04-02 15:16:24.411 VERBOSE Sftp(1)[1] SSH: Sending packet SSH_MSG_USERAUTH_REQUEST (58 bytes).
 0000 |32-00-00-00-0C-69-74-61 6C-67-61-73-77-61-74-65| 2....italgaswate
 0010 |72-00-00-00-0E-73-73-68 2D-63-6F-6E-6E-65-63-74| r....ssh-connect
 0020 |69-6F-6E-00-00-00-08-70 61-73-73-77-6F-72-64-00| ion....password.
 0030 |00-00-00-06-**-**-**-** **-**                  | ....******
2019-04-02 15:16:24.442 VERBOSE Sftp(1)[7] SSH: Received packet SSH_MSG_USERAUTH_SUCCESS (1 bytes).
 0000 |34                                             | 4
2019-04-02 15:16:24.442 DEBUG Sftp(1)[1] SSH: Authentication successful.
2019-04-02 15:16:24.458 VERBOSE Sftp(1)[1] SSH: Sending packet SSH_MSG_CHANNEL_OPEN (24 bytes).
 0000 |5A-00-00-00-07-73-65-73 73-69-6F-6E-00-00-00-00| Z....session....
 0010 |00-02-00-00-00-01-F8-00                        | ........
2019-04-02 15:16:24.489 VERBOSE Sftp(1)[7] SSH: Received packet SSH_MSG_CHANNEL_OPEN_CONFIRMATION (17 bytes).
 0000 |5B-00-00-00-00-00-00-00 00-FF-FF-FF-FF-00-00-80| [...............
 0010 |00                                             | .
2019-04-02 15:16:24.489 DEBUG Sftp(1)[1] SSH: Requesting subsystem 'sftp'.
2019-04-02 15:16:24.489 VERBOSE Sftp(1)[1] SSH: Sending packet SSH_MSG_CHANNEL_REQUEST (27 bytes).
 0000 |62-00-00-00-00-00-00-00 09-73-75-62-73-79-73-74| b........subsyst
 0010 |65-6D-01-00-00-00-04-73 66-74-70               | em.....sftp
2019-04-02 15:16:24.521 VERBOSE Sftp(1)[7] SSH: Received packet SSH_MSG_CHANNEL_SUCCESS (5 bytes).
 0000 |63-00-00-00-00                                 | c....
2019-04-02 15:16:24.536 VERBOSE Sftp(1)[1] SSH: Sending packet SSH_MSG_CHANNEL_DATA (18 bytes).
 0000 |5E-00-00-00-00-00-00-00 09-00-00-00-05-01-00-00| ^...............
 0010 |00-04                                          | ..
2019-04-02 15:16:24.536 INFO Sftp(1)[1] Command: SSH_FXP_INIT (4)
2019-04-02 15:16:24.552 VERBOSE Sftp(1)[7] SSH: Received packet SSH_MSG_CHANNEL_DATA (204 bytes).
 0000 |5E-00-00-00-00-00-00-00 C3-00-00-00-BF-02-00-00| ^...............
 0010 |00-04-00-00-00-08-76-65 72-73-69-6F-6E-73-00-00| ......versions..
 0020 |00-09-32-2C-33-2C-34-2C 35-2C-36-00-00-00-07-6E| ..2,3,4,5,6....n
 0030 |65-77-6C-69-6E-65-00-00 00-01-0A-00-00-00-11-66| ewline.........f
 0040 |73-79-6E-63-40-6F-70-65 6E-73-73-68-2E-63-6F-6D| sync@openssh.com
 0050 |00-00-00-01-31-00-00-00 18-70-6F-73-69-78-2D-72| ....1....posix-r
 0060 |65-6E-61-6D-65-40-6F-70 65-6E-73-73-68-2E-63-6F| ename@openssh.co
 0070 |6D-00-00-00-01-31-00-00 00-13-73-74-61-74-76-66| m....1....statvf
 0080 |73-40-6F-70-65-6E-73-73 68-2E-63-6F-6D-00-00-00| s@openssh.com...
 0090 |01-32-00-00-00-14-66-73 74-61-74-76-66-73-40-6F| .2....fstatvfs@o
 00A0 |70-65-6E-73-73-68-2E-63 6F-6D-00-00-00-01-32-00| penssh.com....2.
 00B0 |00-00-14-68-61-72-64-6C 69-6E-6B-40-6F-70-65-6E| ...hardlink@open
 00C0 |73-73-68-2E-63-6F-6D-00 00-00-01-31            | ssh.com....1
2019-04-02 15:16:24.567 INFO Sftp(1)[1] Response: SSH_FXP_VERSION (4, 7 extensions)
2019-04-02 15:16:24.567 INFO Sftp(1)[1] Info: Using SFTP v4 on a Unix-like platform.
2019-04-02 15:16:24.567 VERBOSE Sftp(1)[1] SSH: Sending packet SSH_MSG_CHANNEL_DATA (23 bytes).
 0000 |5E-00-00-00-00-00-00-00 0E-00-00-00-0A-10-00-00| ^...............
 0010 |00-01-00-00-00-01-2E                           | .......
2019-04-02 15:16:24.567 INFO Sftp(1)[1] Command: SSH_FXP_REALPATH (1, '.')
2019-04-02 15:16:24.599 VERBOSE Sftp(1)[7] SSH: Received packet SSH_MSG_CHANNEL_DATA (32 bytes).
 0000 |5E-00-00-00-00-00-00-00 17-00-00-00-13-68-00-00| ^............h..
 0010 |00-01-00-00-00-01-00-00 00-01-2F-00-00-00-00-02| ........../.....
2019-04-02 15:16:24.599 INFO Sftp(1)[1] Response: SSH_FXP_NAME (1, 1 item)
2019-04-02 15:16:24.599 INFO Sftp(1)[1] Info: Current directory is '/'.
2019-04-02 15:16:24.614 VERBOSE Sftp(1)[1] SSH: Sending packet SSH_MSG_CHANNEL_DATA (31 bytes).
 0000 |5E-00-00-00-00-00-00-00 16-00-00-00-12-11-00-00| ^...............
 0010 |00-02-00-00-00-05-2F-54 65-73-74-00-00-00-B5   | ....../Test....
2019-04-02 15:16:24.614 INFO Sftp(1)[1] Command: SSH_FXP_STAT (2, '/Test')
2019-04-02 15:16:24.646 VERBOSE Sftp(1)[7] SSH: Received packet SSH_MSG_CHANNEL_DATA (75 bytes).
 0000 |5E-00-00-00-00-00-00-00 42-00-00-00-3E-69-00-00| ^.......B...>i..
 0010 |00-02-00-00-00-B5-02-00 00-00-00-00-00-10-00-00| ................
 0020 |00-00-0C-69-74-61-6C-67 61-73-77-61-74-65-72-00| ...italgaswater.
 0030 |00-00-0C-69-74-61-6C-67 61-73-77-61-74-65-72-00| ...italgaswater.
 0040 |00-01-F8-00-00-00-00-5C 76-6C-31               | .......\vl1
2019-04-02 15:16:24.646 ERROR Sftp(1)[1] Info: System.InvalidOperationException: Not enough data.
   at Rebex.Net.CCD.T()
   at Rebex.Net.CCD.I()
   at Rebex.Net.SftpAttributes..ctor(CCD W, Int32 O)
   at Rebex.Net.QVD..ctor(Byte[] W, Int32 O, Int32 C, Encoding N, Int32 V)
   at Rebex.Net.ZND.JC(VCD& W)
   at Rebex.Net.ZND.JC(UInt32 W, Boolean O)
   at Rebex.Net.ZND.MC(VCD W, UInt32 O, JCD C)
   at Rebex.Net.ZND.GO(String W, Boolean O, Boolean C, Boolean N, MND V, IND& D, JCD A)
   at Rebex.Net.Sftp.HEO(String W, Boolean O, Boolean C, Boolean N, JCD V)

1 Answer

0 votes
answered Apr 3 by Lukas Matyska (52,730 points)

Thank you for the log. It showed that the server sent malformed packet according to SFTP v4 specification (see section 5).

The received SSH_FXP_STAT packet contains SFTP flags: 0xB5

Which corresponds to fields:

SSH_FILEXFER_ATTR_SIZE              0x00000001
SSH_FILEXFER_ATTR_PERMISSIONS       0x00000004
SSH_FILEXFER_ATTR_CREATETIME        0x00000010
SSH_FILEXFER_ATTR_MODIFYTIME        0x00000020
SSH_FILEXFER_ATTR_OWNERGROUP        0x00000080

The fields and its corresponding values are:

int64    size          0x01000
string   owner         italgaswater
string   group         italgaswater
uint32   permissions   0x01F8
uint64   createtime    0x5C766C31
uint64   mtime         !!! not enough data

The solution is to report this issue to the server vendor, so the issue is fixed on the server.

As a workaround, please disable SFTP v4 by setting the Sftp.Settings.DisableSftp4 property to true.

Can you please post here what SFTP server you are using and which version?
It can be read from log (assign logger before calling Connect method). Locate line like this:

DEBUG Sftp(1)[9] SSH: Server is 'SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u3'.
commented Apr 4 by Fazul (120 points)
I think this is the one you are looking for :

2019-04-02 15:16:26.271 DEBUG Sftp(3)[1] SSH: Server is 'SSH-2.0-mod_sftp'.
commented Apr 4 by Lukas Matyska (52,730 points)
Thank you for the server info.
...