debug.c

This is the library for all storage drivers. It simplifies writing a storage driver by implementing

                    switch (adSenseCodeQual){
                        MAKE_CASE(SCSI_SENSEQ_INCOMPATIBLE_MEDIA_INSTALLED)
                        MAKE_CASE(SCSI_SENSEQ_UNKNOWN_FORMAT)
                        MAKE_CASE(SCSI_SENSEQ_INCOMPATIBLE_FORMAT)
                        MAKE_CASE(SCSI_SENSEQ_CLEANING_CARTRIDGE_INSTALLED)
                    }
                    break;
                case SCSI_ADSENSE_OPERATOR_REQUEST:
                    switch (adSenseCodeQual){
                        MAKE_CASE(SCSI_SENSEQ_STATE_CHANGE_INPUT)
                        MAKE_CASE(SCSI_SENSEQ_MEDIUM_REMOVAL)
                        MAKE_CASE(SCSI_SENSEQ_WRITE_PROTECT_ENABLE)
                        MAKE_CASE(SCSI_SENSEQ_WRITE_PROTECT_DISABLE)
                    }
                    break;
                case SCSI_ADSENSE_COPY_PROTECTION_FAILURE:
                    switch (adSenseCodeQual){
                        MAKE_CASE(SCSI_SENSEQ_AUTHENTICATION_FAILURE)
                        MAKE_CASE(SCSI_SENSEQ_KEY_NOT_PRESENT)
                        MAKE_CASE(SCSI_SENSEQ_KEY_NOT_ESTABLISHED)
                        MAKE_CASE(SCSI_SENSEQ_READ_OF_SCRAMBLED_SECTOR_WITHOUT_AUTHENTICATION)
                        MAKE_CASE(SCSI_SENSEQ_MEDIA_CODE_MISMATCHED_TO_LOGICAL_UNIT)
                        MAKE_CASE(SCSI_SENSEQ_LOGICAL_UNIT_RESET_COUNT_ERROR)
                    }
                    break;
            }
        }

        return adSenseCodeQualStr;
    }


    /*
     *  DbgCheckReturnedPkt
     *
     *      Check a completed TRANSFER_PACKET for all sorts of error conditions
     *      and warn/trap appropriately.
     */
    VOID DbgCheckReturnedPkt(TRANSFER_PACKET *Pkt)
    {
        PCDB pCdb = (PCDB)Pkt->Srb.Cdb;

        ASSERT(Pkt->Srb.OriginalRequest == Pkt->Irp);
        ASSERT(Pkt->Srb.DataBuffer == Pkt->BufPtrCopy);
        ASSERT(Pkt->Srb.DataTransferLength <= Pkt->BufLenCopy);
        ASSERT(!Pkt->Irp->CancelRoutine);

        if (SRB_STATUS(Pkt->Srb.SrbStatus) == SRB_STATUS_PENDING){
            DBGERR(("SRB completed with status PENDING in packet %ph: (op=%s srbstat=%s(%xh), irpstat=%xh)",
                        Pkt,
                        DBGGETSCSIOPSTR(&Pkt->Srb),
                        DBGGETSRBSTATUSSTR(&Pkt->Srb),
                        (ULONG)Pkt->Srb.SrbStatus,
                        Pkt->Irp->IoStatus.Status));
        }
        else if (SRB_STATUS(Pkt->Srb.SrbStatus) == SRB_STATUS_SUCCESS){
            /*
             *  Make sure SRB and IRP status match.
             */
            if (!NT_SUCCESS(Pkt->Irp->IoStatus.Status)){
                DBGWARN(("SRB and IRP status don't match in packet %ph: (op=%s srbstat=%s(%xh), irpstat=%xh)",
                            Pkt,
                            DBGGETSCSIOPSTR(&Pkt->Srb),
                            DBGGETSRBSTATUSSTR(&Pkt->Srb),
                            (ULONG)Pkt->Srb.SrbStatus,
                            Pkt->Irp->IoStatus.Status));
            }

            if (Pkt->Irp->IoStatus.Information != Pkt->Srb.DataTransferLength){
                DBGERR(("SRB and IRP result transfer lengths don't match in succeeded packet %ph: (op=%s, SrbStatus=%s, Srb.DataTransferLength=%xh, Irp->IoStatus.Information=%xh).",
                            Pkt,
                            DBGGETSCSIOPSTR(&Pkt->Srb),
                            DBGGETSRBSTATUSSTR(&Pkt->Srb),
                            Pkt->Srb.DataTransferLength,
                            Pkt->Irp->IoStatus.Information));
            }
        }
        else {
            if (NT_SUCCESS(Pkt->Irp->IoStatus.Status)){
                DBGWARN(("SRB and IRP status don't match in packet %ph: (op=%s srbstat=%s(%xh), irpstat=%xh)",
                            Pkt,
                            DBGGETSCSIOPSTR(&Pkt->Srb),
                            DBGGETSRBSTATUSSTR(&Pkt->Srb),
                            (ULONG)Pkt->Srb.SrbStatus,
                            Pkt->Irp->IoStatus.Status));
            }
            DBGTRACE(ClassDebugWarning, ("Packet %ph failed (op=%s srbstat=%s(%xh), irpstat=%xh, sense=%s/%s/%s)",
                            Pkt,
                            DBGGETSCSIOPSTR(&Pkt->Srb),
                            DBGGETSRBSTATUSSTR(&Pkt->Srb),
                            (ULONG)Pkt->Srb.SrbStatus,
                            Pkt->Irp->IoStatus.Status,
                            DBGGETSENSECODESTR(&Pkt->Srb),
                            DBGGETADSENSECODESTR(&Pkt->Srb),
                            DBGGETADSENSEQUALIFIERSTR(&Pkt->Srb)));

            /*
             *  If the SRB failed with underrun or overrun, then the actual
             *  transferred length should be returned in both SRB and IRP.
             *  (SRB's only have an error status for overrun, so it's overloaded).
             */
            if ((SRB_STATUS(Pkt->Srb.SrbStatus) == SRB_STATUS_DATA_OVERRUN) &&
               (Pkt->Irp->IoStatus.Information != Pkt->Srb.DataTransferLength)){
                DBGERR(("SRB and IRP result transfer lengths don't match in failed packet %ph: (op=%s, SrbStatus=%s, Srb.DataTransferLength=%xh, Irp->IoStatus.Information=%xh).",
                            Pkt,
                            DBGGETSCSIOPSTR(&Pkt->Srb),
                            DBGGETSRBSTATUSSTR(&Pkt->Srb),
                            Pkt->Srb.DataTransferLength,
                            Pkt->Irp->IoStatus.Information));
            }
        }

        /*
         *  If the port driver returned STATUS_INSUFFICIENT_RESOURCES,
         *  make sure this is also the InternalStatus in the SRB so that we process it correctly.
         */
        if (Pkt->Irp->IoStatus.Status == STATUS_INSUFFICIENT_RESOURCES){
            ASSERT(SRB_STATUS(Pkt->Srb.SrbStatus) == SRB_STATUS_INTERNAL_ERROR);
            ASSERT(Pkt->Srb.InternalStatus == STATUS_INSUFFICIENT_RESOURCES);
        }

        /*
         *  Some miniport drivers have been caught changing the SCSI operation
         *  code in the SRB.  This is absolutely disallowed as it breaks our error handling.
         */
        switch (pCdb->CDB10.OperationCode){
            case SCSIOP_MEDIUM_REMOVAL:
            case SCSIOP_MODE_SENSE:
            case SCSIOP_READ_CAPACITY:
            case SCSIOP_READ:
            case SCSIOP_WRITE:
            case SCSIOP_START_STOP_UNIT:
            case SCSIOP_READ_CAPACITY16:
            case SCSIOP_READ16:
            case SCSIOP_WRITE16:
                break;
            default:
                DBGERR(("Miniport illegally changed Srb.Cdb.OperationCode in packet %ph failed (op=%s srbstat=%s(%xh), irpstat=%xh, sense=%s/%s/%s)",
                                Pkt,
                                DBGGETSCSIOPSTR(&Pkt->Srb),
                                DBGGETSRBSTATUSSTR(&Pkt->Srb),
                                (ULONG)Pkt->Srb.SrbStatus,
                                Pkt->Irp->IoStatus.Status,
                                DBGGETSENSECODESTR(&Pkt->Srb),
                                DBGGETADSENSECODESTR(&Pkt->Srb),
                                DBGGETADSENSEQUALIFIERSTR(&Pkt->Srb)));
                break;
        }

    }


    VOID DbgLogSendPacket(TRANSFER_PACKET *Pkt)
    {
        PFUNCTIONAL_DEVICE_EXTENSION fdoExt = Pkt->Fdo->DeviceExtension;
        PCLASS_PRIVATE_FDO_DATA fdoData = fdoExt->PrivateFdoData;
        KIRQL oldIrql;

        if (Pkt->OriginalIrp){
            Pkt->DbgOriginalIrpCopy = *Pkt->OriginalIrp;
            if (Pkt->OriginalIrp->MdlAddress){
                Pkt->DbgMdlCopy = *Pkt->OriginalIrp->MdlAddress;
            }
        }

        KeQueryTickCount(&Pkt->DbgTimeSent);
        Pkt->DbgTimeReturned.QuadPart = 0L;

        KeAcquireSpinLock(&fdoData->SpinLock, &oldIrql);
        fdoData->DbgPacketLogs[fdoData->DbgPacketLogNextIndex] = *Pkt;
        fdoData->DbgPacketLogNextIndex++;
        fdoData->DbgPacketLogNextIndex %= DBG_NUM_PACKET_LOG_ENTRIES;
        KeReleaseSpinLock(&fdoData->SpinLock, oldIrql);
    }

    VOID DbgLogReturnPacket(TRANSFER_PACKET *Pkt)
    {
        PFUNCTIONAL_DEVICE_EXTENSION fdoExt = Pkt->Fdo->DeviceExtension;
        PCLASS_PRIVATE_FDO_DATA fdoData = fdoExt->PrivateFdoData;
        KIRQL oldIrql;

        KeQueryTickCount(&Pkt->DbgTimeReturned);

        #if 0
            // ISSUE: there are some problems with this check (e.g. multiproc), so don't include it yet
            if (Pkt->OriginalIrp){
                /*
                 *  No one should have touched the original irp while the packet was outstanding,
                 *  except for a couple fields that we ourselves update during the transfer
                 *  or that are allowed to change;
                 *  make those couple fields the same and then to a bytewise compare
                 */
                ULONG lenSame;

                Pkt->DbgOriginalIrpCopy.IoStatus.Status = Pkt->OriginalIrp->IoStatus.Status;
                Pkt->DbgOriginalIrpCopy.IoStatus.Information = Pkt->OriginalIrp->IoStatus.Information;
                Pkt->DbgOriginalIrpCopy.Tail.Overlay.DriverContext[0] = Pkt->OriginalIrp->Tail.Overlay.DriverContext[0];
                Pkt->DbgOriginalIrpCopy.ThreadListEntry = Pkt->OriginalIrp->ThreadListEntry;
                Pkt->DbgOriginalIrpCopy.Cancel = Pkt->OriginalIrp->Cancel;

                lenSame = (ULONG)RtlCompareMemory(Pkt->OriginalIrp, &Pkt->DbgOriginalIrpCopy, sizeof(IRP));
                ASSERT(lenSame == sizeof(IRP));
            }
        #endif

        KeAcquireSpinLock(&fdoData->SpinLock, &oldIrql);
        fdoData->DbgPacketLogs[fdoData->DbgPacketLogNextIndex] = *Pkt;
        fdoData->DbgPacketLogNextIndex++;
        fdoData->DbgPacketLogNextIndex %= DBG_NUM_PACKET_LOG_ENTRIES;
        KeReleaseSpinLock(&fdoData->SpinLock, oldIrql);
    }


    VOID DbgLogFlushInfo(PCLASS_PRIVATE_FDO_DATA FdoData, BOOLEAN IsIO, BOOLEAN IsFUA, BOOLEAN IsFlush)
    {

        /*
         *  Reset all FUA/Flush logging fields.
         */
        if (FdoData->DbgInitFlushLogging){
            FdoData->DbgNumIORequests = 0;
            FdoData->DbgNumFUAs = 0;
            FdoData->DbgNumFlushes = 0;
            FdoData->DbgIOsSinceFUA = 0;
            FdoData->DbgIOsSinceFlush = 0;
            FdoData->DbgAveIOsToFUA = 0;
            FdoData->DbgAveIOsToFlush = 0;
            FdoData->DbgMaxIOsToFUA = 0;
            FdoData->DbgMaxIOsToFlush = 0;
            FdoData->DbgMinIOsToFUA = 0xffffffff;
            FdoData->DbgMinIOsToFlush = 0xffffffff;
            FdoData->DbgInitFlushLogging = FALSE;
        }

        if (IsIO){
            FdoData->DbgNumIORequests++;
            FdoData->DbgIOsSinceFlush++;
            if (IsFUA){
                if (FdoData->DbgNumFUAs > 0){
                    FdoData->DbgMinIOsToFUA = min(FdoData->DbgMinIOsToFUA, FdoData->DbgIOsSinceFUA);
                }
                FdoData->DbgNumFUAs++;
                FdoData->DbgAveIOsToFUA =  FdoData->DbgNumIORequests/FdoData->DbgNumFUAs;
                FdoData->DbgIOsSinceFUA = 0;
            }
            else {
                FdoData->DbgIOsSinceFUA++;
                FdoData->DbgMaxIOsToFUA = max(FdoData->DbgMaxIOsToFUA, FdoData->DbgIOsSinceFUA);
            }
            FdoData->DbgMaxIOsToFlush = max(FdoData->DbgMaxIOsToFlush, FdoData->DbgIOsSinceFlush);
        }
        else if (IsFlush){
            if (FdoData->DbgNumFlushes > 0){
                FdoData->DbgMinIOsToFlush = min(FdoData->DbgMinIOsToFlush, FdoData->DbgIOsSinceFlush);
            }
            FdoData->DbgNumFlushes++;
            FdoData->DbgAveIOsToFlush =  FdoData->DbgNumIORequests/FdoData->DbgNumFlushes;
            FdoData->DbgIOsSinceFlush = 0;
        }

    }

#else

    // We have to keep this in the retail build for legacy.
    VOID ClassDebugPrint(CLASS_DEBUG_LEVEL DebugPrintLevel, PCCHAR DebugMessage, ...)
    {
    }

#endif