Possible issue with test case: SmbdDataTransfer_VariableLengthSegment

[vinitagnihotri]

We are testing SMBD test suite for our SMBD capable server running in centos environment.
While running this test case, test case sends out write request and waits for write response,
our server sends out valid response yet test suite seems not to go further resulting into timeout and thus marks it as failed.

Error message:

Test method Microsoft.Protocol.TestSuites.Smbd.TestSuite.SmbdDataTransfer.SmbdDataTransfer_VariableLengthSegment threw exception: 

System.TimeoutException: Timeout for waiting an object.

We have captured packets using netmon and analysed in message analyser, to find we do receive correct request and client does receives valid response.

We are attaching image for dump for reference. Our server is 192.168.2.1 and client is 192.168.2.2 (Windows 2012 R2) We are using MSFT file sharing test suite for MS-SMBD 3.18.6.0

msg number: 50 indicates SMB write request with 65424 bytes of data (FF90h) (msg_50.png)
msg number: 1920 indicated response from our server with count as 65424 (FF90h) *msg_1920.png)

Black underline indicates command id and length, purple underline indicates request and response flags (08-09) respctively.

[vinitagnihotri]

Similar behaviour is observed with following test cases as well:
BVT_SmbdDataTransfer_Basic_SendModerateBytesData
SmbdDataTransfer_SmallLengthSegment

Similar test case BVT_SmbdDataTransfer_Basic_SendSmallBytesOfData does pass without any issue.

[huiren-jiang]

Hi vinitagnihotri,

Thanks for reporting this issue!

Observing from your captures, your server should have replied a normal SMB2 WRITE response while test suites missed it so the test case failed due to time out.

Could you please set the RdmaLayerLoggingEnabled to true in 'Configure Test Cases' tab of PTM and run those failed test cases again? This step will enable the RDMA layer log output so we could have a chance to figure out whether test cases received the response or not. There should be some log lines similar to below near the end,

2019-10-12 02:00:48.136 [Debug] Receive 20 bytes from entry 0xB

2019-10-12 02:00:48.136 [Debug] 1 operation Receive has been finished with result STATUS_SUCCESS and result Id: 72ECD30; Bytes of data transferred is 20; Segment Index is 11; Count of work items is 57

2019-10-12 02:00:48.138 [Debug] Receive SMBD Data Transfer Credit Request: 255 Credit Granted: 17 Flags: NONE Reserved: 0 RemainingDataLength: 0 DataOffset: 0 Buffer Length: 0

2019-10-12 02:00:48.143 [Debug] Receive 104 bytes from entry 0xC

2019-10-12 02:00:48.145 [Debug] Receive SMBD Data Transfer Credit Request: 255 Credit Granted: 0 Flags: NONE Reserved: 0 RemainingDataLength: 0 DataOffset: 24 Buffer Length: 80

2019-10-12 02:00:48.142 [Debug] 1 operation Receive has been finished with result STATUS_SUCCESS and result Id: 72ECC10; Bytes of data transferred is 104; Segment Index is 12; Count of work items is 56

2019-10-12 02:00:48.151 [CheckSucceeded] Assert.AreEqual succeeded. Status of SMB2 Read File is STATUS_SUCCESS

If receiving a request of buffer length 80 then it should be an SMB2 WRITE response.

Attaching the full log will be helpful for us to diagnose.

Best Regards,

Windows Protocol Test Suites Development Team

[vinitagnihotri]

SmbdDataTransfer_VariableLengthSegment.txt

Please find requested log file attached.
I did went through logs, but I couldn't find write response as such, all I could see is empty messages that we send out on receipt of fragmented frame. May be test suite is not expecting these empty messages before any write response.

Thanks.

[ms-hujia]

Hi vinitagnihotri,

Thanks for attaching the log.

Actually test suites code could handle data transfer message which only grants credits without data. I guess the issue might be test suites failed when receiving the SMB2 write response. The status is not checked so that response is not received and timed out.

In ValidateWriteResponse() of SmbdDataTransfer.cs,

            // receive write response
            SmbdDataTransferMessage transferPackage;
            NtStatus status;
            status = (NtStatus)smbdAdapter.SmbdReceivDataTransferMessage(
                smbdAdapter.TestConfig.Smb2ConnectionTimeout,
                out transferPackage
                );

            while (transferPackage.DataLength == 0)
            {
                // Discard data transfer package that only grants credits to client without data
                status = (NtStatus)smbdAdapter.SmbdReceivDataTransferMessage(
                    smbdAdapter.TestConfig.Smb2ConnectionTimeout,
                    out transferPackage);
            }

Could you try to modify the previous code as below, build and run those case again?

            do
            {
                // Discard data transfer package that only grants credits to client without data
                status = (NtStatus)smbdAdapter.SmbdReceivDataTransferMessage(
                    smbdAdapter.TestConfig.Smb2ConnectionTimeout,
                    out transferPackage);

                BaseTestSite.Assert.AreEqual(NtStatus.STATUS_SUCCESS, status, "Data transfer message should be received with status STATUS_SUCCESS.");

            } while (transferPackage.DataLength == 0);

If the receiving failed, test cases will output the NTSTATUS value in log.

Best Regards,

Windows Protocol Test Suites Development Team

[huiren-jiang]

Hi vinitagnihotri,

The fix is available on staging by commit adfd89a.

Here I attach a signed build with fix MS-SMBD-TestSuite-ServerEP.zip. Could you please try this build and re-run these cases? If these tests fail at bottom layer (NetDirect driver), NTSTATUS value will give us more information to figure out this issue.

Best Regards,

Windows Protocol Test Suites Development Team

[lumengyanhelen]

Hi vinitagnihotri,

Since this thread has been inactive for a long time, we close it for now. Feel free to reopen it if the problem remains.

Windows Protocol Test Suites Development Team

[vinitagnihotri]

Is this fixed in 3.19.9.0? As we still could not see this case passing at our end.