Ask a Question

System.InvalidOperationException: Not enough data

0 votes
by (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
by (73.5k 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/
by (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
by (73.5k 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-ServerSoftware_X.Y'.
by (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'.
by (73.5k points)
Thank you for the server info.
by (1.2k points)
In my case, where the error also occurred (and was also resolved by setting the `DisableSftp4` to `true`), the server string is: "Server is 'SSH-2.0-sFTP Server ready.'".
by (148k points)
Old versions of ProFTPd's mod_sftp used to suffer from a bug like this (and there was also a related bug in Rebex SFTP, which we fixed in 2017 - see https://www.rebex.net/sftp.net/history.aspx#2017R6.1). Could you please let us know which SFTP/SSH server is actually running at the server, and which version? Also, which version of Rebex SFTP do you use?
by (1.2k points)
This was from a Regex version that we included in a software of us last year. So it is not the most recent version, I cannot figure out which version exactly. Regarding the actual server, I also cannot figure out which exact server this is, I only know that the hoster is hoststar.ch.
by (148k points)
Would it be possible to create a log of this at LogLevel.Verbose (see https://www.rebex.net/kb/logging/) and mail us a) The version number from the beginning of the log; and b) The contents of the SSH packet received before the error occurred? That should make it possible to tell what is going on in this case.
by (1.2k points)
2021-12-16 15:59:33,518 [11] INFO  - [O] Connecting to lx17.hoststar.hosting:5544 using Sftp.
2021-12-16 15:59:33,530 [11] INFO  - [O] Assembly: Rebex.Sftp R5.6 for .NET 4.6-4.8
2021-12-16 15:59:33,536 [11] INFO  - [O] Platform: Windows 10.0.19043 64-bit; CLR: 4.0.30319.42000
2021-12-16 15:59:33,632 [11] INFO  - [I] Negotiation started.
2021-12-16 15:59:33,952 [11] INFO  - [I] Negotiation finished.
2021-12-16 15:59:33,956 [11] INFO  - [O] Server: SSH-2.0-sFTP Server ready.
2021-12-16 15:59:33,959 [11] INFO  - [O] Fingerprint (MD5): 7a:fc:fd:60:57:aa:51:d6:e9:bd:26:b9:5a:2f:ee:2a
2021-12-16 15:59:33,962 [11] INFO  - [O] Fingerprint (SHA-256): XhDOEzjIijdFS+8XTCZeei7MPzTAHQCCVy+oBkhyYMk
2021-12-16 15:59:33,966 [11] INFO  - [O] Cipher info: SSH 2.0, ecdh-sha2-nistp256, ssh-rsa, aes256-ctr/aes256-ctr, hmac-sha2-256/hmac-sha2-256
2021-12-16 15:59:36,693 [11] INFO  - [S] SSH_FXP_INIT (4)
2021-12-16 15:59:36,712 [11] INFO  - [R] SSH_FXP_VERSION (4, 7 extensions)
2021-12-16 15:59:36,717 [11] INFO  - [O] Using SFTP v4 on a Unix-like platform.
2021-12-16 15:59:36,725 [11] INFO  - [S] SSH_FXP_REALPATH (1, '.')
2021-12-16 15:59:36,744 [11] INFO  - [R] SSH_FXP_NAME (1, '/')
2021-12-16 15:59:36,748 [11] INFO  - [O] Home directory is '/'.
2021-12-16 15:59:36,767 [11] INFO  - [S] SSH_FXP_STAT (2, '/name-obfuscated-by-me.ch')
2021-12-16 15:59:36,850 [11] INFO  - [O] System.InvalidOperationException: Not enough data.
by (148k points)
Well, we actually need a log at LogLevel.Verbose instead of LogLevel.Debug to see the contents of the response packet that triggered the exception. It would be sufficient to set "sftp.LogWriter.Level=LogLevel.Verbose" prior to calling the method that fails.
by (1.2k points)
Sorry, I can't provide anything beside the above. This is a already shipped application that I cannot modify anymore for now, unfortunately :-(.
by (148k points)
We will add an option to the next version that will make it possible enable the existing mod_sftp workaround. This is just a guess, but perhaps it would help.
by (148k points)
edited by
Please try enabling this with the latest R6.1 release and let us know whether it helps:
    Rebex.Security.Cryptography.CryptoHelper.SetOption(sftp.Settings, "EnableRedundantCreateTimeWorkaround", true); // 'sftp' is your instance of Sftp object
by (148k points)
Starting with Rebex SFTP R6.3, the workaround can be enabled using Sftp.Settings.EnableMissingCreateTimeWorkaround property.
by (1.2k points)
Thank you very much. Just downloaded and changed my code to use the new property
...