SCSIControllerDriverKit: Process gets stuck on UserCreateTargetForID

Question

Context:

We are working on migration of the driver, which is currently represented as a kernel extension, to the DriverKit framework.

The driver works with Thunderbolt RAID storage devices.

When connected through the Thunderbolt interface to the host, the device itself presents in the OS as a PCI device. The main function of our driver (.kext) is to create a "virtual" SCSI device in the OS for each virtual RAID array. So that the OS can work with these SCSI drives as usual disk storage.

We use https://developer.apple.com/documentation/scsicontrollerdriverkit to migrate this functionality in the dext version of the driver.

Current issue:

When a device is connected - the dext driver cannot create a SCSI drive in the OS.

Technically our dext tries to create a SCSI drive using the UserCreateTargetForID() method. On this step the OS sends the first SCSI command "Test Unit Ready" to the device to check if it is a SCSI device.

We process this command in an additional thread separated from the main process of the dext (as it is recommended in the DriverKit documentation). We can see in the logs that the device receives this command and responses but when our dext sends this response to the OS the process is stuck in the waiting mode. How can we understand why it happens and fix it?

More details:

1. We are migrating functionality of an already existing “.kext” driver. We checked logs of the kext driver of this step:

    15:06:17.902539+0700        Target device try to create for idx:0
    15:06:17.902704+0700        Send command 0 for target 0 len 0
    15:06:18.161777+0700        Complete command: 0 for target: 0 Len: 0 status: 0 flags: 0
    15:06:18.161884+0700        Send command 18 for target 0 len 6
    15:06:18.161956+0700        Complete command: 18 for target: 0 Len: 6 status: 0 flags: 0
    15:06:18.162010+0700        Send command 18 for target 0 len 44
    15:06:18.172972+0700        Complete command: 18 for target: 0 Len: 44 status: 0 flags: 0
    15:06:18.275501+0700        Send command 18 for target 0 len 36
    15:06:18.275584+0700        Complete command: 18 for target: 0 Len: 36 status: 0 flags: 0
    15:06:18.276257+0700        Target device created for idx:0

We can see a successful message “Target device created for idx:0”

2. In the the dext logs of the same step: We do not see the “Send command 18 for target 0 len 6” as we have in the kext logs no log of the successful result “Target device created for idx:0”

I'll add a thread name to each line of the dext log (CustomThread,DefaultQueue,SendCommandCustomThread,InterruptQueue):

15:54:10.903466+0700        Try to create target for 0 UUID 432421434863538456 - CustomThread
15:54:10.903633+0700        UserDoesHBAPerformAutoSense - DefaultQueue
15:54:10.903763+0700        UserInitializeTargetForID - DefaultQueue
15:54:10.903876+0700        UserDoesHBASupportMultiPathing DefaultQueue
15:54:10.904200+0700        UserProcessParallelTask start - DefaultQueue
15:54:10.904298+0700        Sent command : 0 len 0 for target 0 - SendCommandCustomThread
15:54:11.163003+0700        Disable interrupts - InterruptQueue
15:54:11.163077+0700        Complete cmd : 0 for target: 0 len: 0  status: 0 flags: 0 - InterruptQueue
15:54:11.163085+0700        Enable interrupts - InterruptQueue

Code for complete task

 SCSIUserParallelResponse osRsp = {0};
 osRsp.fControllerTaskIdentifier = osTask->taskId;
 osRsp.fTargetID = osTask->targetId;
 osRsp.fServiceResponse = kSCSIServiceResponse_TASK_COMPLETE;
 osRsp.fCompletionStatus = (SCSITaskStatus) response->status;
 // Transfer length computation.
 osRsp.fBytesTransferred = transferLength; // === 0 for this case.
 ParallelTaskCompletion(osTask->action, osRsp);
 osTask->action->release();

Will appreciate any help

Answer 1

This is effectively a deadlock, which you seem to have already worked out. It's not 100% clear from your your question, but as I initially had the same problem, I assume you're calling UserCreateTargetForID from the driver's default queue. This won't work, you must call it from a non-default queue because SCSIControllerDriverKit assumes that your default queue is idle and ready to handle requests from the kernel while you are calling this function. The header docs are very ambiguous on this, though they do mention it:

The dext class should call this method to create a new target for the targetID. The framework ensures that the new target is created before the call returns. Note that this call to the framework runs on the Auxiliary queue.

SCSIControllerDriverKit expects your driver to use 3 different dispatch queues (default, auxiliary, and interrupt), although I think it can be done with 2 as well. I recommend you (re-)watch the relevant part of the WWDC2020 session video about how Apple wants you to use the 3 dispatch queues, exactly. The framework does not seem to be very flexible on this point.

Good luck with the rest of the driver port, I found this DriverKit framework even more fussy than the other ones.

Answer 2

Thanks to pmdj for direction of think. For my case answer is just add initialization for version field for response.

osRsp.version = kScsiUserParallelTaskResponseCurrentVersion1;

It looks obvious. But there are no any information in docs or WWDC2020 video about initialization version field.

Answer 3

My project is hardware raid 'user space driver' . My driver has now completed the io stress test. Your problem should be in the SCSI command with data transfer. And you want to send data to the system by your software driver to complete the SCSI ' inquiry ' command. I think you also used 'UserGetDataBuffer'. It seems to be some distance from iokit's function.

kern_return_t IMPL ( XXXXUserSpaceDriver, UserProcessParallelTask ) {

/* 
**********************************************************************
**                      UserGetDataBuffer
**********************************************************************
*/
if(parallelTask.fCommandDescriptorBlock[0] == SCSI_CMD_INQUIRY)
{
    IOBufferMemoryDescriptor *data_buffer_memory_descriptor = nullptr;

    /*
    ******************************************************************************************************************************************
    ** virtual kern_return_t UserGetDataBuffer(SCSIDeviceIdentifier fTargetID, uint64_t fControllerTaskIdentifier, IOBufferMemoryDescriptor **buffer);
    ******************************************************************************************************************************************
    */
    if((UserGetDataBuffer(parallelTask.fTargetID, parallelTask.fControllerTaskIdentifier, &data_buffer_memory_descriptor) == kIOReturnSuccess) && (data_buffer_memory_descriptor != NULL))
    {
        IOAddressSegment data_buffer_virtual_address_segment = {0};         

        if(data_buffer_memory_descriptor->GetAddressRange(&data_buffer_virtual_address_segment) == kIOReturnSuccess)
        {
            IOAddressSegment data_buffer_physical_address_segment = {0};
            IODMACommandSpecification dmaSpecification;
            IODMACommand *data_buffer_iodmacommand = {0};

            bzero(&dmaSpecification, sizeof(dmaSpecification));
            dmaSpecification.options        = kIODMACommandSpecificationNoOptions;
            dmaSpecification.maxAddressBits = 64;
            if(IODMACommand::Create(ivars->pciDevice, kIODMACommandCreateNoOptions, &dmaSpecification, &data_buffer_iodmacommand) == kIOReturnSuccess)
            {
                uint64_t dmaFlags = kIOMemoryDirectionInOut;
                uint32_t dmaSegmentCount = 1;

                pCCB->data_buffer_iodmacommand = data_buffer_iodmacommand;
                if(data_buffer_iodmacommand->PrepareForDMA(kIODMACommandPrepareForDMANoOptions, data_buffer_memory_descriptor, 0/*offset*/, parallelTask.fRequestedTransferCount/*length*/, &dmaFlags, &dmaSegmentCount, &data_buffer_physical_address_segment) == kIOReturnSuccess)
                {
                    parallelTask.fBufferIOVMAddr = (uint64_t)data_buffer_physical_address_segment.address;           /* data_buffer_physical_address: overwrite original fBufferIOVMAddr */
                    pCCB->OSDataBuffer  = reinterpret_cast <uint8_t *> (data_buffer_virtual_address_segment.address);/* data_buffer_virtual_address                                      */
                }
            }
        }
    }
}

}

Answer 4

response.fBytesTransferred          = dataxferlen;
response.version                    = kScsiUserParallelTaskResponseCurrentVersion1;
response.fTargetID                  = TARGETLUN2SCSITARGET(TargetID, 0);
response.fControllerTaskIdentifier  = pCCB->fControllerTaskIdentifier;
response.fCompletionStatus          = taskStatus;
response.fServiceResponse           = serviceResponse;
response.fSenseLength               = taskStatus;
IOUserSCSIParallelInterfaceController::ParallelTaskCompletion(pCCB->completion, response);
pCCB->completion->release();
pCCB->completion = NULL;
pCCB->ccb_flags.start = 0;/*reset startdone for outstanding ccb check*/
if(pCCB->data_buffer_iodmacommand != NULL)
{
    pCCB->data_buffer_iodmacommand->CompleteDMA(kIODMACommandCompleteDMANoOptions);
    OSSafeReleaseNULL(pCCB->data_buffer_iodmacommand);    // pCCB->data_buffer_iodmacommand->free(); pCCB->data_buffer_iodmacommand = NULL;
    pCCB->OSDataBuffer = NULL;
}