VirtualBox

Changeset 38356 in vbox for trunk


Ignore:
Timestamp:
Aug 8, 2011 3:49:01 PM (13 years ago)
Author:
vboxsync
Message:

usb/win: more logging

Location:
trunk/src/VBox/HostDrivers/VBoxUSB/win
Files:
7 edited

Legend:

Unmodified
Added
Removed

  • trunk/src/VBox/HostDrivers/VBoxUSB/win/Makefile.kmk

    r38292 r38356  
    3838endif
    3939VBoxUSB_SDKS        = W2K3DDK WINPSDKINCS
    40 VBoxUSB_DEFS        = IN_RT_R0 IN_SUP_R0
     40VBoxUSB_DEFS        = IN_RT_R0 IN_SUP_R0 VBOX_DBG_LOG_NAME=\"USBDev\"
    4141VBoxUSB_LDFLAGS.x86 = -Entry:DriverEntry@8
    4242VBoxUSB_LDFLAGS.amd64 = -Entry:DriverEntry
    … …  
    6666VBoxUSBMon_DEFS        = IN_RT_R0 IN_SUP_R0 i386=1 STD_CALL CONDITION_HANDLING=1 NT_INST=0 \
    6767        WIN32=100 _NT1X_=100 WINNT=1 _WIN32_WINNT=0x0501 WINVER=0x0501 _WIN32_IE=0x0600 WIN32_LEAN_AND_MEAN=1 \
    68         VBOXUSBFILTERMGR_USB_SPINLOCK
     68        VBOXUSBFILTERMGR_USB_SPINLOCK VBOX_DBG_LOG_NAME=\"USBMon\"
    6969VBoxUSBMon_LDFLAGS.x86 = -Entry:DriverEntry@8
    7070VBoxUSBMon_LDFLAGS.amd64 = -Entry:DriverEntry
    … …  
    8686        $(PATH_STAGE_LIB)/RuntimeR0Drv$(VBOX_SUFF_LIB) \
    8787        $(usbd_1_TARGET)
    88 #VBoxUSBMon_DEFS      += LOG_ENABLED
     88if1of ($(KBUILD_TYPE), debug)
     89VBoxUSBMon_DEFS      += LOG_ENABLED VBOX_USB_WITH_VERBOSE_LOGGING
     90endif
    8991
    9092#

  • trunk/src/VBox/HostDrivers/VBoxUSB/win/cmn/VBoxDrvTool.cpp

    r37490 r38356  
    1919
    2020#include <iprt/assert.h>
     21#include <VBox/log.h>
     22
     23#include "../../../win/VBoxDbgLog.h"
    2124
    2225#define VBOXDRVTOOL_MEMTAG 'TDBV'
    … …  
    137140{
    138141    KEVENT Event;
     142    LOG(("post irp (0x%p) to DevObj(0x%p) with timeout (%u)", pIrp, pDevObj, dwTimeoutMs));
     143
    139144    KeInitializeEvent(&Event, NotificationEvent, FALSE);
    140145    NTSTATUS Status = VBoxDrvToolIoPostAsync(pDevObj, pIrp, &Event);
    … …  
    152157        if (Status == STATUS_TIMEOUT)
    153158        {
    154 #ifdef DEBUG_misha
    155             /* debugging only */
    156             AssertFailed();
    157 #endif
     159            WARN(("irp (0x%p) to DevObj(0x%p) was not completed within timeout (%u), cancelling", pIrp, pDevObj, dwTimeoutMs));
    158160            if (!IoCancelIrp(pIrp))
    159161            {
    160162                /* this may happen, but this is something the caller with timeout is not expecting */
    161                 AssertFailed();
     163                WARN(("IoCancelIrp failed"));
    162164            }
    163165
    … …  
    167169        else
    168170        {
    169             Assert(Status == STATUS_SUCCESS);
     171            ASSERT_WARN(Status == STATUS_SUCCESS, ("uunexpected Status (0x%x)", Status));
    170172        }
    171173
    172174        /* by this time the IRP is completed */
    173175        Status = pIrp->IoStatus.Status;
     176        LOG(("Pending IRP(0x%p) completed with status(0x%x)", pIrp, Status));
     177    }
     178    else
     179    {
     180        LOG(("IRP(0x%p) completed with status(0x%x)", pIrp, Status));
    174181    }
    175182    return Status;

  • trunk/src/VBox/HostDrivers/VBoxUSB/win/cmn/VBoxUsbTool.cpp

    r37065 r38356  
    2222#include <VBox/log.h>
    2323
     24#include "../../../win/VBoxDbgLog.h"
     25
    2426#define VBOXUSBTOOL_MEMTAG 'TUBV'
    2527
    … …  
    9799    USHORT cbUrb = sizeof (struct _URB_CONTROL_DESCRIPTOR_REQUEST);
    98100    PURB pUrb = VBoxUsbToolUrbAllocZ(URB_FUNCTION_GET_DESCRIPTOR_FROM_DEVICE, cbUrb);
    99     Assert(pUrb);
    100101    if(!pUrb)
    101102    {
     103        WARN(("allocating URB failed"));
    102104        return STATUS_INSUFFICIENT_RESOURCES;
    103105    }
    … …  
    116118
    117119    Status = VBoxUsbToolUrbPost(pDevObj, pUrb, dwTimeoutMs);
    118 #ifdef DEBUG_misha
    119     Assert(Status == STATUS_SUCCESS);
    120 #endif
     120    ASSERT_WARN(Status == STATUS_SUCCESS, ("VBoxUsbToolUrbPost failed Status (0x%x)", Status));
    121121
    122122    VBoxUsbToolUrbFree(pUrb);
    … …  
    349349    if (!pIrp)
    350350    {
     351        WARN(("VBoxUsbToolIoBuildAsyncInternalCtl failed"));
    351352        return STATUS_INSUFFICIENT_RESOURCES;
    352353    }
    … …  
    371372    if (!pIrp)
    372373    {
    373         AssertMsgFailed(("IoBuildDeviceIoControlRequest failed!!\n"));
     374        WARN(("IoBuildDeviceIoControlRequest failed!!\n"));
    374375        pIoStatus->Status = STATUS_INSUFFICIENT_RESOURCES;
    375376        pIoStatus->Information = 0;
    … …  
    395396    KeInitializeEvent(&Event, NotificationEvent, FALSE);
    396397
     398    LOG(("Sending sync Ctl pDevObj(0x%p), uCtl(0x%x), pvArg1(0x%p), pvArg2(0x%p)", pDevObj, uCtl, pvArg1, pvArg2));
     399
    397400    Status = VBoxUsbToolIoInternalCtlSendAsync(pDevObj, uCtl, pvArg1, pvArg2, &Event, &IoStatus);
    398401
    399402    if (Status == STATUS_PENDING)
    400403    {
     404        LOG(("VBoxUsbToolIoInternalCtlSendAsync returned pending for pDevObj(0x%x)", pDevObj));
    401405        KeWaitForSingleObject(&Event, Executive, KernelMode, FALSE, NULL);
    402406        Status = IoStatus.Status;
    403     }
    404 
    405     return Status;
    406 }
     407        LOG(("Pending VBoxUsbToolIoInternalCtlSendAsync completed with Status (0x%x) for pDevObj(0x%x)", Status, pDevObj));
     408    }
     409    else
     410    {
     411        LOG(("VBoxUsbToolIoInternalCtlSendAsync completed with Status (0x%x) for pDevObj(0x%x)", Status, pDevObj));
     412    }
     413
     414    return Status;
     415}

  • trunk/src/VBox/HostDrivers/VBoxUSB/win/mon/VBoxUsbFlt.cpp

    r38262 r38356  
    286286static PVBOXUSBFLT_DEVICE vboxUsbFltDevGetLocked(PDEVICE_OBJECT pPdo)
    287287{
    288 #ifdef DEBUG_misha
     288#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
    289289    for (PLIST_ENTRY pEntry = g_VBoxUsbFltGlobals.DeviceList.Flink;
    290290            pEntry != &g_VBoxUsbFltGlobals.DeviceList;
    … …  
    297297        {
    298298            PVBOXUSBFLT_DEVICE pDevice2 = PVBOXUSBFLT_DEVICE_FROM_LE(pEntry2);
    299             Assert(    pDevice->idVendor  != pDevice2->idVendor
     299            ASSERT_WARN(    pDevice->idVendor  != pDevice2->idVendor
    300300                    || pDevice->idProduct != pDevice2->idProduct
    301                     || pDevice->bcdDevice != pDevice2->bcdDevice);
     301                    || pDevice->bcdDevice != pDevice2->bcdDevice, ("duplicate devices in a list!!"));
    302302        }
    303303    }
    … …  
    308308    {
    309309        PVBOXUSBFLT_DEVICE pDevice = PVBOXUSBFLT_DEVICE_FROM_LE(pEntry);
    310         Assert(    pDevice->enmState == VBOXUSBFLT_DEVSTATE_REPLUGGING
     310        ASSERT_WARN(    pDevice->enmState == VBOXUSBFLT_DEVSTATE_REPLUGGING
    311311                || pDevice->enmState == VBOXUSBFLT_DEVSTATE_UNCAPTURED
    312312                || pDevice->enmState == VBOXUSBFLT_DEVSTATE_CAPTURING
    313313                || pDevice->enmState == VBOXUSBFLT_DEVSTATE_CAPTURED
    314                 || pDevice->enmState == VBOXUSBFLT_DEVSTATE_USED_BY_GUEST);
     314                || pDevice->enmState == VBOXUSBFLT_DEVSTATE_USED_BY_GUEST,
     315                ("Invalid device state(%d) for device(0x%p) PDO(0x%p)", pDevice->enmState, pDevice, pDevice->Pdo));
    315316        if (pDevice->Pdo == pPdo)
    316317            return pDevice;
    … …  
    328329    {
    329330        vboxUsbFltDevRetain(pDevice);
     331        LOG(("found device (0x%p), state(%d) for PDO(0x%p)", pDevice, pDevice->enmState, pPdo));
    330332    }
    331333    else
    332334    {
     335        LOG(("found replugging device (0x%p), state(%d) for PDO(0x%p)", pDevice, pDevice->enmState, pPdo));
    333336        pDevice = NULL;
    334337    }
    … …  
    340343static NTSTATUS vboxUsbFltPdoReplug(PDEVICE_OBJECT pDo)
    341344{
     345    LOG(("Replugging PDO(0x%p)", pDo));
    342346    NTSTATUS Status = VBoxUsbToolIoInternalCtlSendSync(pDo, IOCTL_INTERNAL_USB_CYCLE_PORT, NULL, NULL);
    343     Assert(Status == STATUS_SUCCESS);
     347    ASSERT_WARN(Status == STATUS_SUCCESS, ("replugging PDO(0x%p) failed Status(0x%x)", pDo, Status));
     348    LOG(("Replugging PDO(0x%p) done with Status(0x%x)", pDo, Status));
    344349    return Status;
    345350}
    … …  
    393398    pDevice->Pdo = pDo;
    394399
     400    LOG(("Populating Device(0x%p) for PDO(0x%p)", pDevice, pDo));
     401
    395402    pDevDr = (PUSB_DEVICE_DESCRIPTOR)VBoxUsbMonMemAllocZ(sizeof(*pDevDr));
    396403    if (pDevDr == NULL)
    397404    {
    398         AssertMsgFailed(("Failed to alloc mem for urb\n"));
     405        WARN(("Failed to alloc mem for urb\n"));
    399406        return STATUS_INSUFFICIENT_RESOURCES;
    400407    }
    … …  
    405412        if (!NT_SUCCESS(Status))
    406413        {
    407             LOGREL((__FUNCTION__": getting device descriptor failed\n"));
     414            WARN(("getting device descriptor failed, Status (0x%x)\n", Status));
    408415            break;
    409416        }
    … …  
    411418        if (vboxUsbFltBlDevMatchLocked(pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice))
    412419        {
    413             LOGREL((__FUNCTION__": found a known black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
    414 #ifdef DEBUG_misha
    415             AssertFailed();
    416 #endif
     420            WARN(("found a known black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
    417421            Status = STATUS_UNSUCCESSFUL;
    418422            break;
    … …  
    438442            if (!NT_SUCCESS(Status))
    439443            {
    440                 AssertMsgFailed((__FUNCTION__": reading language ID failed\n"));
     444                WARN(("reading language ID failed\n"));
    441445                if (Status == STATUS_CANCELLED)
    442446                {
    443                     AssertMsgFailed((__FUNCTION__": found a new black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
     447                    WARN(("found a new black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
    444448                    vboxUsbFltBlDevAddLocked(pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice);
    445449                    Status = STATUS_UNSUCCESSFUL;
    … …  
    453457                if (!NT_SUCCESS(Status))
    454458                {
    455                     AssertMsgFailed((__FUNCTION__": reading serial number failed\n"));
     459                    WARN(("reading serial number failed\n"));
    456460                    if (Status == STATUS_CANCELLED)
    457461                    {
    458                         AssertMsgFailed((__FUNCTION__": found a new black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
     462                        WARN(("found a new black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
    459463                        vboxUsbFltBlDevAddLocked(pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice);
    460464                        Status = STATUS_UNSUCCESSFUL;
    … …  
    469473                if (!NT_SUCCESS(Status))
    470474                {
    471                     AssertMsgFailed((__FUNCTION__": reading manufacturer name failed\n"));
     475                    WARN(("reading manufacturer name failed\n"));
    472476                    if (Status == STATUS_CANCELLED)
    473477                    {
    474                         AssertMsgFailed((__FUNCTION__": found a new black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
     478                        WARN(("found a new black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
    475479                        vboxUsbFltBlDevAddLocked(pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice);
    476480                        Status = STATUS_UNSUCCESSFUL;
    … …  
    485489                if (!NT_SUCCESS(Status))
    486490                {
    487                     AssertMsgFailed((__FUNCTION__": reading product name failed\n"));
     491                    WARN(("reading product name failed\n"));
    488492                    if (Status == STATUS_CANCELLED)
    489493                    {
    490                         AssertMsgFailed((__FUNCTION__": found a new black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
     494                        WARN(("found a new black list device, vid(0x%x), pid(0x%x), rev(0x%x)\n", pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice));
    491495                        vboxUsbFltBlDevAddLocked(pDevDr->idVendor, pDevDr->idProduct, pDevDr->bcdDevice);
    492496                        Status = STATUS_UNSUCCESSFUL;
    … …  
    535539            }
    536540#endif
    537             LOG((__FUNCTION__": strings: '%s':'%s':'%s' (lang ID %x)\n",
     541            LOG((": strings: '%s':'%s':'%s' (lang ID %x)\n",
    538542                        pDevice->szMfgName, pDevice->szProduct, pDevice->szSerial, langId));
    539543        }
    540544
     545        LOG(("Populating Device(0x%p) for PDO(0x%p) Succeeded", pDevice, pDo));
    541546        Status = STATUS_SUCCESS;
    542547    } while (0);
    543548
    544549    VBoxUsbMonMemFree(pDevDr);
     550    LOG(("Populating Device(0x%p) for PDO(0x%p) Done, Status (0x%x)", pDevice, pDo, Status));
    545551    return Status;
    546552}
    … …  
    566572static bool vboxUsbFltDevCheckReplugLocked(PVBOXUSBFLT_DEVICE pDevice, PVBOXUSBFLTCTX pContext)
    567573{
    568     Assert(pContext);
     574    ASSERT_WARN(pContext, ("context is NULL!"));
     575
     576    LOG(("Current context is (0x%p)", pContext));
     577    LOG(("Current Device owner is (0x%p)", pDevice->pOwner));
    569578
    570579    /* check if device is already replugging */
    571580    if (pDevice->enmState <= VBOXUSBFLT_DEVSTATE_ADDED)
    572581    {
     582        LOG(("Device (0x%p) is already replugging, return..", pDevice));
    573583        /* it is, do nothing */
    574         Assert(pDevice->enmState == VBOXUSBFLT_DEVSTATE_REPLUGGING);
     584        ASSERT_WARN(pDevice->enmState == VBOXUSBFLT_DEVSTATE_REPLUGGING,
     585                ("Device (0x%p) state is NOT REPLUGGING (%d)", pDevice, pDevice->enmState));
    575586        return false;
    576587    }
    … …  
    578589    if (pDevice->pOwner && pContext != pDevice->pOwner)
    579590    {
     591        LOG(("Device (0x%p) is owned by another context(0x%p), current is(0x%p)", pDevice, pDevice->pOwner, pContext));
    580592        /* this device is owned by another context, we're not allowed to do anything */
    581593        return false;
    … …  
    589601            false, /* do not remove a one-shot filter */
    590602            &fFilter, &fIsOneShot);
     603    LOG(("Matching Info: Filter (0x%p), NewOwner(0x%p), fFilter(%d), fIsOneShot(%d)", uId, pNewOwner, (int)fFilter, (int)fIsOneShot));
    591604    if (pDevice->pOwner && pNewOwner && pDevice->pOwner != pNewOwner)
    592605    {
     606        LOG(("Matching: Device (0x%p) is requested another owner(0x%p), current is(0x%p)", pDevice, pNewOwner, pDevice->pOwner));
    593607        /* the device is owned by another owner, we can not change the owner here */
    594608        return false;
    … …  
    597611    if (!fFilter)
    598612    {
     613        LOG(("Matching: Device (0x%p) should NOT be filtered", pDevice));
    599614        /* the device should NOT be filtered, check the current state  */
    600615        if (vboxUsbFltDevStateIsNotFiltered(pDevice))
    601616        {
     617            LOG(("Device (0x%p) is NOT filtered", pDevice));
    602618            /* no changes */
    603619            if (fIsOneShot)
    604620            {
    605                 Assert(pNewOwner);
     621                ASSERT_WARN(pNewOwner, ("no new owner"));
     622                LOG(("Matching: This is a one-shot filter (0x%p), removing..", uId));
    606623                /* remove a one-shot filter and keep the original filter data */
    607624                int tmpRc = VBoxUSBFilterRemove(pNewOwner, uId);
    608                 AssertRC(tmpRc);
     625                ASSERT_WARN(RT_SUCCESS(tmpRc), ("remove filter failed, rc (%d)", tmpRc));
    609626                if (!pDevice->pOwner)
    610627                {
     628                    LOG(("Matching: updating the one-shot owner to (0x%p), fltId(0x%p)", pNewOwner, uId));
    611629                    /* update owner for one-shot if the owner is changed (i.e. assigned) */
    612630                    vboxUsbFltDevOwnerUpdateLocked(pDevice, pNewOwner, uId, true);
     631                }
     632                else
     633                {
     634                    LOG(("Matching: device already has owner (0x%p) assigned", pDevice->pOwner));
    613635                }
    614636            }
    615637            else
    616638            {
     639                LOG(("Matching: This is NOT a one-shot filter (0x%p), newOwner(0x%p)", uId, pNewOwner));
    617640                if (pNewOwner)
    618641                {
    … …  
    623646        else
    624647        {
     648            LOG(("Device (0x%p) IS filtered", pDevice));
    625649            /* the device is currently filtered, we should release it only if
    626650             * 1. device does not have an owner
    … …  
    631655            if (!pDevice->pOwner || fIsOneShot || !pDevice->fIsFilterOneShot)
    632656            {
     657                LOG(("Matching: Need replug"));
    633658                bNeedReplug = true;
    634659            }
    … …  
    637662    else
    638663    {
     664        LOG(("Matching: Device (0x%p) SHOULD be filtered", pDevice));
    639665        /* the device should be filtered, check the current state  */
    640         Assert(uId);
    641         Assert(pNewOwner);
     666        ASSERT_WARN(uId, ("zero uid"));
     667        ASSERT_WARN(pNewOwner, ("zero pNewOwner"));
    642668        if (vboxUsbFltDevStateIsFiltered(pDevice))
    643669        {
     670            LOG(("Device (0x%p) IS filtered", pDevice));
    644671            /* the device is filtered */
    645672            if (pNewOwner == pDevice->pOwner)
    646673            {
     674                LOG(("Device owner match"));
    647675                /* no changes */
    648676                if (fIsOneShot)
    649677                {
     678                    LOG(("Matching: This is a one-shot filter (0x%p), removing..", uId));
    650679                    /* remove a one-shot filter and keep the original filter data */
    651680                    int tmpRc = VBoxUSBFilterRemove(pNewOwner, uId);
    652                     AssertRC(tmpRc);
     681                    ASSERT_WARN(RT_SUCCESS(tmpRc), ("remove filter failed, rc (%d)", tmpRc));
    653682                }
    654683                else
    655684                {
     685                    LOG(("Matching: This is NOT a one-shot filter (0x%p), Owner(0x%p)", uId, pDevice->pOwner));
    656686                    vboxUsbFltDevOwnerUpdateLocked(pDevice, pDevice->pOwner, uId, false);
    657687                }
    … …  
    659689            else
    660690            {
    661                 Assert(!pDevice->pOwner);
     691                ASSERT_WARN(!pDevice->pOwner, ("device should NOT have owner"));
     692                LOG(("Matching: Need replug"));
    662693                /* the device needs to be filtered, but the owner changes, replug needed */
    663694                bNeedReplug = true;
    … …  
    676707            {
    677708                bNeedReplug = true;
     709                LOG(("Matching: Need replug"));
    678710            }
    679711        }
    … …  
    682714    if (bNeedReplug)
    683715    {
     716        LOG(("Matching: Device needs replugging, marking as such"));
    684717        vboxUsbFltDevStateMarkReplugLocked(pDevice);
     718    }
     719    else
     720    {
     721        LOG(("Matching: Device does NOT need replugging"));
    685722    }
    686723
    … …  
    697734        pNext = pEntry->Flink;
    698735        PVBOXUSBFLT_DEVICE pDevice = PVBOXUSBFLT_DEVICE_FROM_REPLUGGINGLE(pEntry);
    699         Assert(pDevice->enmState == VBOXUSBFLT_DEVSTATE_REPLUGGING
    700                 || pDevice->enmState == VBOXUSBFLT_DEVSTATE_REMOVED);
     736        LOG(("replugging matched PDO(0x%p), pDevice(0x%p)", pDevice->Pdo, pDevice));
     737        ASSERT_WARN(pDevice->enmState == VBOXUSBFLT_DEVSTATE_REPLUGGING
     738                || pDevice->enmState == VBOXUSBFLT_DEVSTATE_REMOVED,
     739                ("invalid state(0x%x) for device(0x%p)", pDevice->enmState, pDevice));
    701740
    702741        vboxUsbFltPdoReplug(pDevice->Pdo);
    … …  
    713752    Assert(Irql == PASSIVE_LEVEL);
    714753
    715     LOG(("==" __FUNCTION__"\n"));
     754    LOG(("Running filters, Context (0x%p)..", pContext));
    716755
    717756    for (int i=0;i<RT_ELEMENTS(lpszStandardControllerName);i++)
    … …  
    758797                        PDEVICE_RELATIONS pDevRelations = NULL;
    759798
    760 #ifdef DEBUG
    761                         LOG(("Associated driver "));
    762                         vboxUsbDbgPrintUnicodeString(&pHubDevObj->DriverObject->DriverName);
    763                         LOG((" -> related dev obj=0x%p\n", IoGetRelatedDeviceObject(pHubFileObj)));
    764 #endif
     799                        LOG(("Flt Associated driver "));
     800                        LOG_USTR(&pHubDevObj->DriverObject->DriverName);
     801                        LOG((" -> related dev obj=0x%p", pHubDevObj));
    765802
    766803                        Status = VBoxUsbMonQueryBusRelations(pHubDevObj, pHubFileObj, &pDevRelations);
    … …  
    774811                                PDEVICE_OBJECT pDevObj = pDevRelations->Objects[k];
    775812
    776                                 LOG(("Found existing USB PDO 0x%p\n", pDevObj));
     813                                LOG(("Found existing USB PDO 0x%p", pDevObj));
    777814                                VBOXUSBFLT_LOCK_ACQUIRE();
    778815                                PVBOXUSBFLT_DEVICE pDevice = vboxUsbFltDevGetLocked(pDevObj);
    779816                                if (pDevice)
    780817                                {
     818                                    LOG(("Found existing device info (0x%p) for PDO 0x%p", pDevice, pDevObj));
    781819                                    bool bReplug = vboxUsbFltDevCheckReplugLocked(pDevice, pContext);
    782820                                    if (bReplug)
    783821                                    {
     822                                        LOG(("Replug needed for device (0x%p)", pDevice));
    784823                                        InsertHeadList(&ReplugDevList, &pDevice->RepluggingLe);
    785824                                        vboxUsbFltDevRetain(pDevice);
    … …  
    788827                                    else
    789828                                    {
     829                                        LOG(("Replug NOT needed for device (0x%p)", pDevice));
    790830                                        ObDereferenceObject(pDevObj);
    791831                                    }
    … …  
    795835                                    pDevRelations->Objects[k] = NULL;
    796836                                    --cReplugPdos;
    797                                     Assert((uint32_t)cReplugPdos < UINT32_MAX/2);
     837                                    ASSERT_WARN((uint32_t)cReplugPdos < UINT32_MAX/2, ("cReplugPdos(%d) state broken", cReplugPdos));
    798838                                    continue;
    799839                                }
    800840                                VBOXUSBFLT_LOCK_RELEASE();
    801841
     842                                LOG(("NO device info found for PDO 0x%p", pDevObj));
    802843                                VBOXUSBFLT_DEVICE Device;
    803844                                Status = vboxUsbFltDevPopulate(&Device, pDevObj /*, FALSE /* only need filter properties */);
    … …  
    812853                                            &fFilter, &fIsOneShot);
    813854                                    VBOXUSBFLT_LOCK_RELEASE();
     855                                    LOG(("Matching Info: Filter (0x%p), pCtx(0x%p), fFilter(%d), fIsOneShot(%d)", uId, pCtx, (int)fFilter, (int)fIsOneShot));
    814856                                    if (!fFilter)
    815857                                    {
     858                                        LOG(("Matching: This device should NOT be filtered"));
    816859                                        /* this device should not be filtered, and it's not */
    817860                                        ObDereferenceObject(pDevObj);
    … …  
    822865                                    }
    823866
     867                                    LOG(("Matching: This device SHOULD be filtered"));
    824868                                    /* this device needs to be filtered, but it's not,
    825869                                     * leave the PDO in array to issue a replug request for it
    … …  
    827871
    828872                                }
     873                                else
     874                                {
     875                                    WARN(("vboxUsbFltDevPopulate for PDO 0x%p failed with Status 0x%x", pDevObj, Status));
     876                                }
    829877                            }
     878
     879                            LOG(("(%d) non-matched PDOs to be replugged", cReplugPdos));
    830880
    831881                            if (cReplugPdos)
    … …  
    837887
    838888                                    Status = vboxUsbFltPdoReplug(pDevRelations->Objects[k]);
    839                                     Assert(Status == STATUS_SUCCESS);
     889                                    ASSERT_WARN(Status == STATUS_SUCCESS, ("vboxUsbFltPdoReplug ailed Status(0x%x)", Status));
    840890                                    ObDereferenceObject(pDevRelations->Objects[k]);
    841891                                    if (!--cReplugPdos)
    … …  
    843893                                }
    844894
    845                                 Assert(!cReplugPdos);
     895                                ASSERT_WARN(!cReplugPdos, ("cReplugPdosreached zero!"));
    846896                            }
    847897
    … …  
    849899
    850900                            ExFreePool(pDevRelations);
     901                        }
     902                        else
     903                        {
     904                            WARN(("VBoxUsbMonQueryBusRelations failed for DO(0x%p), Status(0x%x), pDevRelations(0x%p)",
     905                                    pHubDevObj, Status, pDevRelations));
    851906                        }
    852907                    }
    … …  
    856911        }
    857912    }
     913
     914    LOG(("DONE Running filters, Context (0x%p)", pContext));
    858915
    859916    return STATUS_SUCCESS;
    … …  
    936993        USBFilterGetString(pFilter, USBFILTERIDX_PRODUCT_STR)       ? USBFilterGetString(pFilter, USBFILTERIDX_PRODUCT_STR)       : "<null>",
    937994        USBFilterGetString(pFilter, USBFILTERIDX_SERIAL_NUMBER_STR) ? USBFilterGetString(pFilter, USBFILTERIDX_SERIAL_NUMBER_STR) : "<null>"));
    938 #ifdef DEBUG
    939     LOG(("VBoxUSBClient::addFilter: idVendor=%#x idProduct=%#x bcdDevice=%#x bDeviceClass=%#x bDeviceSubClass=%#x bDeviceProtocol=%#x bBus=%#x bPort=%#x\n",
     995#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
     996    LOG(("VBoxUSBClient::addFilter: idVendor=%#x idProduct=%#x bcdDevice=%#x bDeviceClass=%#x bDeviceSubClass=%#x bDeviceProtocol=%#x bBus=%#x bPort=%#x Type%#x\n",
    940997              USBFilterGetNum(pFilter, USBFILTERIDX_VENDOR_ID),
    941998              USBFilterGetNum(pFilter, USBFILTERIDX_PRODUCT_ID),
    … …  
    9451002              USBFilterGetNum(pFilter, USBFILTERIDX_DEVICE_PROTOCOL),
    9461003              USBFilterGetNum(pFilter, USBFILTERIDX_BUS),
    947               USBFilterGetNum(pFilter, USBFILTERIDX_PORT)));
     1004              USBFilterGetNum(pFilter, USBFILTERIDX_PORT),
     1005              USBFilterGetFilterType(pFilter)));
    9481006#endif
    9491007
    … …  
    9571015    int rc = VBoxUSBFilterAdd(pFilter, pContext, &uId);
    9581016    VBOXUSBFLT_LOCK_RELEASE();
    959     AssertRC(rc);
    9601017    if (RT_SUCCESS(rc))
    9611018    {
    962         Assert(uId);
     1019        LOG(("ADDED filer id 0x%p", uId));
     1020        ASSERT_WARN(uId, ("uid is NULL"));
    9631021#ifdef VBOX_USBMON_WITH_FILTER_AUTOAPPLY
    9641022        VBoxUsbFltFilterCheck();
    … …  
    9671025    else
    9681026    {
    969         Assert(!uId);
     1027        WARN(("VBoxUSBFilterAdd failed rc (%d)", rc));
     1028        ASSERT_WARN(!uId, ("uid is not NULL"));
    9701029    }
    9711030
    … …  
    9821041    if (!RT_SUCCESS(rc))
    9831042    {
    984         AssertFailed();
     1043        WARN(("VBoxUSBFilterRemove failed rc (%d)", rc));
    9851044        VBOXUSBFLT_LOCK_RELEASE();
    9861045        return rc;
    … …  
    9941053        if (pDevice->fIsFilterOneShot)
    9951054        {
    996             Assert(!pDevice->uFltId);
     1055            ASSERT_WARN(!pDevice->uFltId, ("oneshot filter on device(0x%p): unexpected uFltId(%d)", pDevice, pDevice->uFltId));
    9971056        }
    9981057
    … …  
    10001059            continue;
    10011060
    1002         Assert(pDevice->pOwner == pContext);
     1061        ASSERT_WARN(pDevice->pOwner == pContext, ("Device(0x%p) owner(0x%p) not match to (0x%p)", pDevice, pDevice->pOwner, pContext));
    10031062        if (pDevice->pOwner != pContext)
    10041063            continue;
    10051064
    1006         Assert(!pDevice->fIsFilterOneShot);
     1065        ASSERT_WARN(!pDevice->fIsFilterOneShot, ("device(0x%p) is filtered with a oneshot filter", pDevice));
    10071066        pDevice->uFltId = 0;
    10081067        /* clear the fIsFilterOneShot flag to ensure the device is replugged on the next VBoxUsbFltFilterCheck call */
    … …  
    10581117    if (pDevice->enmState == VBOXUSBFLT_DEVSTATE_REPLUGGING)
    10591118    {
    1060         Assert(!pDevice->pOwner);
    1061         Assert(!pDevice->uFltId);
    1062         AssertFailed();
     1119        ASSERT_WARN(!pDevice->pOwner, ("replugging device(0x%p) still has an owner(0x%p)", pDevice, pDevice->pOwner));
     1120        ASSERT_WARN(!pDevice->uFltId, ("replugging device(0x%p) still has filter(0x%p)", pDevice, pDevice->uFltId));
    10631121        /* no user state for this, we should not return it tu the user */
    10641122        return USBDEVICESTATE_USED_BY_HOST;
    … …  
    10661124
    10671125    /* the device is filtered, if owner differs from the context, return as USED_BY_HOST */
    1068     Assert(pDevice->pOwner);
     1126    ASSERT_WARN(pDevice->pOwner, ("device(0x%p) has noowner", pDevice));
    10691127    /* the id can be null if a filter is removed */
    10701128//    Assert(pDevice->uFltId);
    10711129
    10721130    if (pDevice->pOwner != pContext)
     1131    {
     1132        LOG(("Device owner differs from the current context, returning used by host"));
    10731133        return USBDEVICESTATE_USED_BY_HOST;
     1134    }
    10741135
    10751136    switch (pDevice->enmState)
    … …  
    10831144            return USBDEVICESTATE_USED_BY_GUEST;
    10841145        default:
    1085             AssertFailed();
     1146            WARN(("unexpected device state(%d) for device(0x%p)", pDevice->enmState, pDevice));
    10861147            return USBDEVICESTATE_UNSUPPORTED;
    10871148    }
    … …  
    11481209    if (pDevice)
    11491210    {
    1150         Assert(pDevice->enmState != VBOXUSBFLT_DEVSTATE_ADDED);
    1151         Assert(pDevice->enmState != VBOXUSBFLT_DEVSTATE_REMOVED);
     1211        LOG(("found device (0x%p), state(%d) for PDO(0x%p)", pDevice, pDevice->enmState, pPdo));
     1212        ASSERT_WARN(pDevice->enmState != VBOXUSBFLT_DEVSTATE_ADDED, ("VBOXUSBFLT_DEVSTATE_ADDED state for device(0x%p)", pDevice));
     1213        ASSERT_WARN(pDevice->enmState != VBOXUSBFLT_DEVSTATE_REMOVED, ("VBOXUSBFLT_DEVSTATE_REMOVED state for device(0x%p)", pDevice));
    11521214        *pbFiltered = pDevice->enmState >= VBOXUSBFLT_DEVSTATE_CAPTURING;
    11531215        VBOXUSBFLT_LOCK_RELEASE();
    … …  
    11581220    if (!pDevice)
    11591221    {
    1160         AssertFailed();
     1222        WARN(("VBoxUsbMonMemAllocZ failed"));
    11611223        return STATUS_NO_MEMORY;
    11621224    }
    … …  
    11671229    if (!NT_SUCCESS(Status))
    11681230    {
    1169         AssertFailed();
     1231        WARN(("vboxUsbFltDevPopulate failed, Status 0x%x", Status));
    11701232        VBoxUsbMonMemFree(pDevice);
    11711233        return Status;
    … …  
    11821244    if (pTmpDev)
    11831245    {
    1184         Assert(pTmpDev->enmState != VBOXUSBFLT_DEVSTATE_ADDED);
    1185         Assert(pTmpDev->enmState != VBOXUSBFLT_DEVSTATE_REMOVED);
     1246        LOG(("second try: found device (0x%p), state(%d) for PDO(0x%p)", pDevice, pDevice->enmState, pPdo));
     1247        ASSERT_WARN(pDevice->enmState != VBOXUSBFLT_DEVSTATE_ADDED, ("second try: VBOXUSBFLT_DEVSTATE_ADDED state for device(0x%p)", pDevice));
     1248        ASSERT_WARN(pDevice->enmState != VBOXUSBFLT_DEVSTATE_REMOVED, ("second try: VBOXUSBFLT_DEVSTATE_REMOVED state for device(0x%p)", pDevice));
    11861249        *pbFiltered = pTmpDev->enmState >= VBOXUSBFLT_DEVSTATE_CAPTURING;
    11871250        VBOXUSBFLT_LOCK_RELEASE();
    … …  
    11901253    }
    11911254
     1255    LOG(("Created Device 0x%p for PDO 0x%p", pDevice, pPdo));
     1256
    11921257    pCtx = vboxUsbFltDevMatchLocked(pDevice, &uId,
    11931258            true, /* remove a one-shot filter */
    11941259            &fFilter, &fIsOneShot);
     1260    LOG(("Matching Info: Filter (0x%p), pCtx(0x%p), fFilter(%d), fIsOneShot(%d)", uId, pCtx, (int)fFilter, (int)fIsOneShot));
    11951261    if (fFilter)
    11961262    {
    1197         Assert(pCtx);
    1198         Assert(uId);
     1263        LOG(("Created Device 0x%p should be filtered", pDevice));
     1264        ASSERT_WARN(pCtx, ("zero ctx"));
     1265        ASSERT_WARN(uId, ("zero uId"));
    11991266        pDevice->enmState = VBOXUSBFLT_DEVSTATE_CAPTURING;
    12001267    }
    12011268    else
    12021269    {
    1203         Assert(!uId == !pCtx); /* either both zero or both not */
     1270        LOG(("Created Device 0x%p should NOT be filtered", pDevice));
     1271        ASSERT_WARN(!uId == !pCtx, ("invalid uid(0x%p) - ctx(0x%p) pair", uId, pCtx)); /* either both zero or both not */
    12041272        pDevice->enmState = VBOXUSBFLT_DEVSTATE_UNCAPTURED;
    12051273    }
    … …  
    12801348    {
    12811349        pDevice->enmState = VBOXUSBFLT_DEVSTATE_CAPTURED;
     1350        LOG(("The proxy notified proxy start for the captured device 0x%x\n", pDevice));
    12821351        vboxUsbFltDevRetain(pDevice);
    12831352        vboxUsbFltSignalChangeLocked();
    … …  
    12851354    else
    12861355    {
    1287         AssertFailed();
     1356        WARN(("invalid state, %d", pDevice->enmState));
    12881357        pDevice = NULL;
    12891358    }
    … …  
    13001369    {
    13011370        /* this is due to devie was physically removed */
    1302         LOG(("The proxy notified progy stop for the captured device 0x%x\n", pDevice));
     1371        LOG(("The proxy notified proxy stop for the captured device 0x%x, current state %d\n", pDevice, pDevice->enmState));
    13031372        pDevice->enmState = VBOXUSBFLT_DEVSTATE_CAPTURING;
    13041373        vboxUsbFltSignalChangeLocked();
    … …  
    13061375    else
    13071376    {
    1308         Assert(pDevice->enmState == VBOXUSBFLT_DEVSTATE_REPLUGGING);
     1377        if(pDevice->enmState != VBOXUSBFLT_DEVSTATE_REPLUGGING)
     1378        {
     1379            WARN(("invalid state, %d", pDevice->enmState));
     1380        }
    13091381    }
    13101382    VBOXUSBFLT_LOCK_RELEASE();

  • trunk/src/VBox/HostDrivers/VBoxUSB/win/mon/VBoxUsbHook.cpp

    r38262 r38356  
    180180        if (pCur->pIrp != pIrp)
    181181            continue;
    182         AssertFailed();
     182        WARN(("found pending IRP(0x%p) when it should not be", pIrp));
    183183    }
    184184    KeReleaseSpinLock(&pHook->Lock, oldIrql);

  • trunk/src/VBox/HostDrivers/VBoxUSB/win/mon/VBoxUsbMon.cpp

    r38292 r38356  
    168168    if (!pIrp)
    169169    {
    170         AssertMsgFailed(("IoBuildDeviceIoControlRequest failed!!\n"));
     170        WARN(("IoBuildDeviceIoControlRequest failed!!\n"));
    171171        return STATUS_INSUFFICIENT_RESOURCES;
    172172    }
    … …  
    196196        }
    197197        else
    198             LOG(("Invalid pointer %p\n", pRel));
     198        {
     199            WARN(("Invalid pointer %p\n", pRel));
     200        }
     201    }
     202    else
     203    {
     204        WARN(("IRP_MN_QUERY_DEVICE_RELATIONS failed Status(0x%x)\n", Status));
    199205    }
    200206
    … …  
    302308static NTSTATUS vboxUsbMonHandlePnPIoctl(PDEVICE_OBJECT pDevObj, PIO_STACK_LOCATION pSl, PIO_STATUS_BLOCK pIoStatus)
    303309{
    304     LOG(("VBoxUSBMonHandlePnPIoctl IRQL = %d\n", KeGetCurrentIrql()));
     310    LOG(("IRQL = %d\n", KeGetCurrentIrql()));
    305311    switch(pSl->MinorFunction)
    306312    {
    … …  
    315321                    KIRQL Iqrl = KeGetCurrentIrql();
    316322                    /* IRQL should be always passive here */
    317                     Assert(Iqrl == PASSIVE_LEVEL);
     323                    ASSERT_WARN(Iqrl == PASSIVE_LEVEL, ("irql is not PASSIVE"));
    318324                    switch(pSl->Parameters.QueryDeviceText.DeviceTextType)
    319325                    {
    … …  
    328334                            if (VBoxUsbFltPdoIsFiltered(pDevObj))
    329335                            {
     336                                LOG(("PDO (0x%p) is filtered", pDevObj));
    330337                                WCHAR *pId = (WCHAR *)ExAllocatePool(PagedPool, sizeof(szDeviceTextDescription));
    331338                                if (!pId)
    … …  
    340347                                pIoStatus->Information = (ULONG_PTR)pId;
    341348                            }
     349                            else
     350                            {
     351                                LOG(("PDO (0x%p) is NOT filtered", pDevObj));
     352                            }
    342353                            break;
    343354                        default:
     355                            LOG(("DeviceText %d", pSl->Parameters.QueryDeviceText.DeviceTextType));
    344356                            break;
    345357                    }
    … …  
    357369            {
    358370                WCHAR *pId = (WCHAR *)pIoStatus->Information;
    359 #ifdef DEBUG
     371#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
    360372                WCHAR *pTmp;
    361373#endif
    … …  
    364376                    KIRQL Iqrl = KeGetCurrentIrql();
    365377                    /* IRQL should be always passive here */
    366                     Assert(Iqrl == PASSIVE_LEVEL);
     378                    ASSERT_WARN(Iqrl == PASSIVE_LEVEL, ("irql is not PASSIVE"));
    367379
    368380                    switch (pSl->Parameters.QueryDeviceRelations.Type)
    … …  
    375387                        case BusQueryDeviceID:
    376388                        {
     389                            LOG(("BusQueryDeviceID"));
    377390                            pId = (WCHAR *)ExAllocatePool(PagedPool, sizeof(szBusQueryDeviceId));
    378391                            if (!pId)
    379392                            {
    380                                 AssertFailed();
     393                                WARN(("ExAllocatePool failed"));
    381394                                break;
    382395                            }
    … …  
    386399                            if (Status != STATUS_SUCCESS || !bFiltered)
    387400                            {
    388                                 Assert(Status == STATUS_SUCCESS);
     401                                if(Status == STATUS_SUCCESS)
     402                                {
     403                                    LOG(("PDO (0x%p) is NOT filtered", pDevObj));
     404                                }
     405                                else
     406                                {
     407                                    WARN(("VBoxUsbFltPdoAdd for PDO (0x%p) failed Status 0x%x", pDevObj, Status));
     408                                }
    389409                                ExFreePool(pId);
    390410                                break;
    391411                            }
    392412
     413                            LOG(("PDO (0x%p) is filtered", pDevObj));
    393414                            ExFreePool((PVOID)pIoStatus->Information);
    394415                            memcpy(pId, szBusQueryDeviceId, sizeof(szBusQueryDeviceId));
    … …  
    398419                    case BusQueryHardwareIDs:
    399420                    {
    400 #ifdef DEBUG
     421                        LOG(("BusQueryHardwareIDs"));
     422#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
    401423                        while(*pId) //MULTI_SZ
    402424                        {
    403                             LOG(("BusQueryHardwareIDs"));
    404425                            LOG_STRW(pId);
    405426                            while(*pId) pId++;
    … …  
    410431                        if (!pId)
    411432                        {
    412                             AssertFailed();
     433                            WARN(("ExAllocatePool failed"));
    413434                            break;
    414435                        }
    … …  
    418439                        if (Status != STATUS_SUCCESS || !bFiltered)
    419440                        {
    420                             Assert(Status == STATUS_SUCCESS);
     441                            if(Status == STATUS_SUCCESS)
     442                            {
     443                                LOG(("PDO (0x%p) is NOT filtered", pDevObj));
     444                            }
     445                            else
     446                            {
     447                                WARN(("VBoxUsbFltPdoAdd for PDO (0x%p) failed Status 0x%x", pDevObj, Status));
     448                            }
    421449                            ExFreePool(pId);
    422450                            break;
    423451                        }
    424452
     453                        LOG(("PDO (0x%p) is filtered", pDevObj));
     454
    425455                        memcpy(pId, szBusQueryHardwareIDs, sizeof(szBusQueryHardwareIDs));
    426 #ifdef DEBUG
     456#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
     457                        LOG(("NEW BusQueryHardwareIDs"));
    427458                        pTmp = pId;
    428459                        while(*pTmp) //MULTI_SZ
    429460                        {
    430                             LOG(("NEW BusQueryHardwareIDs"));
     461
    431462                            LOG_STRW(pTmp);
    432463                            while(*pTmp) pTmp++;
    … …  
    439470                    }
    440471                    case BusQueryCompatibleIDs:
    441 #ifdef DEBUG
     472                        LOG(("BusQueryCompatibleIDs"));
     473#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
    442474                        while(*pId) //MULTI_SZ
    443475                        {
    444                             LOG(("BusQueryCompatibleIDs"));
    445476                            LOG_STRW(pId);
    446477                            while(*pId) pId++;
    … …  
    450481                        if (VBoxUsbFltPdoIsFiltered(pDevObj))
    451482                        {
     483                            LOG(("PDO (0x%p) is filtered", pDevObj));
    452484                            pId = (WCHAR *)ExAllocatePool(PagedPool, sizeof(szBusQueryCompatibleIDs));
    453485                            if (!pId)
    454486                            {
    455                                 AssertFailed();
     487                                WARN(("ExAllocatePool failed"));
    456488                                break;
    457489                            }
    458490                            memcpy(pId, szBusQueryCompatibleIDs, sizeof(szBusQueryCompatibleIDs));
    459 #ifdef DEBUG
     491#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
     492                            LOG(("NEW BusQueryCompatibleIDs"));
    460493                            pTmp = pId;
    461494                            while(*pTmp) //MULTI_SZ
    462495                            {
    463                                 LOG(("NEW BusQueryCompatibleIDs"));
    464496                                LOG_STRW(pTmp);
    465497                                while(*pTmp) pTmp++;
    … …  
    469501                            ExFreePool((PVOID)pIoStatus->Information);
    470502                            pIoStatus->Information = (ULONG_PTR)pId;
     503                        }
     504                        else
     505                        {
     506                            LOG(("PDO (0x%p) is NOT filtered", pDevObj));
    471507                        }
    472508                        break;
    … …  
    474510                }
    475511                else
     512                {
    476513                    LOG(("Invalid pointer %p\n", pId));
    477             }
    478             break;
    479         }
    480 
    481 #ifdef DEBUG
     514                }
     515            }
     516            break;
     517        }
     518
     519#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
    482520        case IRP_MN_QUERY_DEVICE_RELATIONS:
    483521        {
    … …  
    542580    } /*switch */
    543581
    544     LOG(("VBoxUSBMonHandlePnPIoctl returns %x (IRQL = %d)\n", pIoStatus->Status, KeGetCurrentIrql()));
     582    LOG(("Done returns %x (IRQL = %d)\n", pIoStatus->Status, KeGetCurrentIrql()));
    545583    return pIoStatus->Status;
    546584}
    … …  
    548586NTSTATUS _stdcall VBoxUsbPnPCompletion(DEVICE_OBJECT *pDevObj, IRP *pIrp, void *pvContext)
    549587{
    550     Assert(pvContext);
     588    LOG(("Completion PDO(0x%p), IRP(0x%p), Status(0x%x)\n", pDevObj, pIrp, pIrp->IoStatus.Status));
     589    ASSERT_WARN(pvContext, ("zero context"));
    551590
    552591    PVBOXUSBHOOK_REQUEST pRequest = (PVBOXUSBHOOK_REQUEST)pvContext;
    … …  
    562601     * */
    563602    PIO_STACK_LOCATION pSl = &pRequest->OldLocation;
    564     Assert(pIrp == pRequest->pIrp);
     603    ASSERT_WARN(pIrp == pRequest->pIrp, ("completed IRP(0x%x) not match request IRP(0x%x)", pIrp, pRequest->pIrp));
    565604    /* NOTE: we can not rely on pDevObj passed in IoCompletion since it may be zero
    566605     * in case IRP was created with extra stack locations and the caller did not initialize
    … …  
    574613        case IRP_MN_QUERY_DEVICE_TEXT:
    575614        case IRP_MN_QUERY_ID:
    576 #ifdef DEBUG
     615#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
    577616        case IRP_MN_QUERY_DEVICE_RELATIONS:
    578617        case IRP_MN_QUERY_CAPABILITIES:
    … …  
    584623            else
    585624            {
    586                 Assert(pIrp->IoStatus.Status == STATUS_NOT_SUPPORTED);
     625                ASSERT_WARN(pIrp->IoStatus.Status == STATUS_NOT_SUPPORTED, ("Irp failed with status(0x%x)", pIrp->IoStatus.Status));
    587626            }
    588627            break;
    … …  
    645684NTSTATUS _stdcall VBoxUsbMonPnPHook(IN PDEVICE_OBJECT pDevObj, IN PIRP pIrp)
    646685{
     686    LOG(("==>PnP: Mn(%s), PDO(0x%p), IRP(0x%p), Status(0x%x)\n", vboxUsbDbgStrPnPMn(IoGetCurrentIrpStackLocation(pIrp)->MinorFunction), pDevObj, pIrp, pIrp->IoStatus.Status));
     687
    647688    if(!VBoxUsbHookRetain(&g_VBoxUsbMonGlobals.UsbHubPnPHook.Hook))
    648689    {
     690        WARN(("VBoxUsbHookRetain failed"));
    649691        return VBoxUsbHookRequestPassDownHookSkip(&g_VBoxUsbMonGlobals.UsbHubPnPHook.Hook, pDevObj, pIrp);
    650692    }
    … …  
    653695    if (!pCompletion)
    654696    {
    655         AssertFailed();
     697        WARN(("VBoxUsbMonMemAlloc failed"));
    656698        VBoxUsbHookRelease(&g_VBoxUsbMonGlobals.UsbHubPnPHook.Hook);
    657699        pIrp->IoStatus.Status = STATUS_INSUFFICIENT_RESOURCES;
    … …  
    661703    }
    662704
    663     LOG(("==>PnP: Mn(%s), PDO(0x%p), IRP(0x%p), Status(0x%x)\n", vboxUsbDbgStrPnPMn(IoGetCurrentIrpStackLocation(pIrp)->MinorFunction), pDevObj, pIrp, pIrp->IoStatus.Status));
    664 
    665705    NTSTATUS Status = VBoxUsbHookRequestPassDownHookCompletion(&g_VBoxUsbMonGlobals.UsbHubPnPHook.Hook, pDevObj, pIrp, VBoxUsbPnPCompletion, &pCompletion->Rq);
    666 #ifdef DEBUG
     706#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
    667707    if (Status != STATUS_PENDING)
    668708    {
     709        LOG(("Request completed, Status(0x%x)", Status));
    669710        VBoxUsbHookVerifyCompletion(&g_VBoxUsbMonGlobals.UsbHubPnPHook.Hook, &pCompletion->Rq, pIrp);
     711    }
     712    else
     713    {
     714        LOG(("Request pending"));
    670715    }
    671716#endif
    … …  
    9921037            if (!pvBuffer || cbOutBuffer != sizeof(*pOut) || cbInBuffer != 0)
    9931038            {
    994                 AssertMsgFailed(("SUPUSBFLT_IOCTL_GET_VERSION: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
     1039                WARN(("SUPUSBFLT_IOCTL_GET_VERSION: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
    9951040                        cbInBuffer, 0, cbOutBuffer, sizeof (*pOut)));
    9961041                Status = STATUS_INVALID_PARAMETER;
    … …  
    10001045            pOut->u32Minor = USBMON_MINOR_VERSION;
    10011046            Info = sizeof (*pOut);
     1047            ASSERT_WARN(Status == STATUS_SUCCESS, ("unexpected status, 0x%x", Status));
    10021048            break;
    10031049        }
    … …  
    10111057            if (RT_UNLIKELY(!pvBuffer || cbInBuffer != sizeof (*pFilter) || cbOutBuffer != sizeof (*pOut)))
    10121058            {
    1013                 AssertMsgFailed(("SUPUSBFLT_IOCTL_ADD_FILTER: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
     1059                WARN(("SUPUSBFLT_IOCTL_ADD_FILTER: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
    10141060                        cbInBuffer, sizeof (*pFilter), cbOutBuffer, sizeof (*pOut)));
    10151061                Status = STATUS_INVALID_PARAMETER;
    … …  
    10211067            pOut->uId = uId;
    10221068            Info = sizeof (*pOut);
     1069            ASSERT_WARN(Status == STATUS_SUCCESS, ("unexpected status, 0x%x", Status));
    10231070            break;
    10241071        }
    … …  
    10311078            if (!pvBuffer || cbInBuffer != sizeof (*pIn) || (cbOutBuffer && cbOutBuffer != sizeof (*pRc)))
    10321079            {
    1033                 AssertMsgFailed(("SUPUSBFLT_IOCTL_REMOVE_FILTER: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
     1080                WARN(("SUPUSBFLT_IOCTL_REMOVE_FILTER: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
    10341081                        cbInBuffer, sizeof (*pIn), cbOutBuffer, 0));
    10351082                Status = STATUS_INVALID_PARAMETER;
    … …  
    10451092                Info = sizeof (*pRc);
    10461093            }
     1094            ASSERT_WARN(Status == STATUS_SUCCESS, ("unexpected status, 0x%x", Status));
    10471095            break;
    10481096        }
    … …  
    10521100            if (pvBuffer || cbInBuffer || cbOutBuffer)
    10531101            {
    1054                 AssertMsgFailed(("SUPUSBFLT_IOCTL_RUN_FILTERS: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
     1102                WARN(("SUPUSBFLT_IOCTL_RUN_FILTERS: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
    10551103                        cbInBuffer, 0, cbOutBuffer, 0));
    10561104                Status = STATUS_INVALID_PARAMETER;
    … …  
    10591107            LOG(("SUPUSBFLT_IOCTL_RUN_FILTERS \n"));
    10601108            Status = VBoxUsbMonRunFilters(pContext);
    1061             Assert(Status == STATUS_SUCCESS);
    1062             Assert(Status != STATUS_PENDING);
     1109            ASSERT_WARN(Status != STATUS_PENDING, ("status pending!"));
    10631110            break;
    10641111        }
    … …  
    10701117            if (!pvBuffer || cbInBuffer != sizeof (hDevice) || cbOutBuffer < sizeof (*pOut))
    10711118            {
    1072                 AssertMsgFailed(("SUPUSBFLT_IOCTL_GET_DEVICE: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected >= %d.\n",
     1119                WARN(("SUPUSBFLT_IOCTL_GET_DEVICE: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected >= %d.\n",
    10731120                        cbInBuffer, sizeof (hDevice), cbOutBuffer, sizeof (*pOut)));
    10741121                Status = STATUS_INVALID_PARAMETER;
    … …  
    10841131            else
    10851132            {
    1086                 AssertFailed();
     1133                WARN(("VBoxUsbMonGetDevice fail 0x%x", Status));
    10871134            }
    10881135            break;
    … …  
    10941141            if (!pvBuffer || cbInBuffer != sizeof (*pSne) || cbOutBuffer != sizeof (*pSne))
    10951142            {
    1096                 AssertMsgFailed(("SUPUSBFLT_IOCTL_SET_NOTIFY_EVENT: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
     1143                WARN(("SUPUSBFLT_IOCTL_SET_NOTIFY_EVENT: Invalid input/output sizes. cbIn=%d expected %d. cbOut=%d expected %d.\n",
    10971144                        cbInBuffer, sizeof (*pSne), cbOutBuffer, sizeof (*pSne)));
    10981145                Status = STATUS_INVALID_PARAMETER;
    … …  
    11021149            pSne->u.rc = VBoxUsbMonSetNotifyEvent(pContext, pSne->u.hEvent);
    11031150            Info = sizeof (*pSne);
     1151            ASSERT_WARN(Status == STATUS_SUCCESS, ("unexpected status, 0x%x", Status));
    11041152            break;
    11051153        }
    11061154
    11071155        default:
     1156            WARN(("Unknown code 0x%x", Ctl));
    11081157            Status = STATUS_INVALID_PARAMETER;
    11091158            break;
    11101159    }
    11111160
    1112     Assert(Status != STATUS_PENDING);
     1161    ASSERT_WARN(Status != STATUS_PENDING, ("Status pending!"));
    11131162
    11141163    *pInfo = Info;
    … …  
    11341183                    pSl->Parameters.DeviceIoControl.OutputBufferLength,
    11351184                    &Info);
    1136         Assert(Status != STATUS_PENDING);
     1185        ASSERT_WARN(Status != STATUS_PENDING, ("Status pending"));
    11371186
    11381187        IoReleaseRemoveLock(&g_VBoxUsbMonGlobals.RmLock, pDevObj);
     1188    }
     1189    else
     1190    {
     1191        WARN(("IoAcquireRemoveLock failed Status (0x%x)", Status));
    11391192    }
    11401193
    … …  
    11581211            if (!pvBuffer)
    11591212            {
    1160                 AssertMsgFailed(("VBOXUSBIDC_INTERNAL_IOCTL_GET_VERSION: Buffer is NULL\n"));
     1213                WARN(("VBOXUSBIDC_INTERNAL_IOCTL_GET_VERSION: Buffer is NULL\n"));
    11611214                Status = STATUS_INVALID_PARAMETER;
    11621215                break;
    … …  
    11641217            pOut->u32Major = VBOXUSBIDC_VERSION_MAJOR;
    11651218            pOut->u32Minor = VBOXUSBIDC_VERSION_MINOR;
     1219            ASSERT_WARN(Status == STATUS_SUCCESS, ("unexpected status, 0x%x", Status));
    11661220            break;
    11671221        }
    … …  
    11741228            if (!pvBuffer)
    11751229            {
    1176                 AssertMsgFailed(("VBOXUSBIDC_INTERNAL_IOCTL_GET_VERSION: Buffer is NULL\n"));
     1230                WARN(("VBOXUSBIDC_INTERNAL_IOCTL_PROXY_STARTUP: Buffer is NULL\n"));
    11771231                Status = STATUS_INVALID_PARAMETER;
    11781232                break;
    … …  
    11801234
    11811235            pOut->u.hDev = VBoxUsbFltProxyStarted(pOut->u.pPDO);
     1236            ASSERT_WARN(pOut->u.hDev, ("zero hDev"));
     1237            ASSERT_WARN(Status == STATUS_SUCCESS, ("unexpected status, 0x%x", Status));
    11821238            break;
    11831239        }
    … …  
    11901246            if (!pvBuffer)
    11911247            {
    1192                 AssertMsgFailed(("VBOXUSBIDC_INTERNAL_IOCTL_PROXY_TEARDOWN: Buffer is NULL\n"));
     1248                WARN(("VBOXUSBIDC_INTERNAL_IOCTL_PROXY_TEARDOWN: Buffer is NULL\n"));
    11931249                Status = STATUS_INVALID_PARAMETER;
    11941250                break;
    11951251            }
    11961252
     1253            ASSERT_WARN(pOut->hDev, ("zero hDev"));
    11971254            VBoxUsbFltProxyStopped(pOut->hDev);
     1255            ASSERT_WARN(Status == STATUS_SUCCESS, ("unexpected status, 0x%x", Status));
    11981256            break;
    11991257        }
    … …  
    12011259        default:
    12021260        {
    1203             AssertFailed();
     1261            WARN(("Unknown code 0x%x", Ctl));
    12041262            Status = STATUS_INVALID_PARAMETER;
    12051263            break;
    … …  
    12761334NTSTATUS _stdcall DriverEntry(PDRIVER_OBJECT pDrvObj, PUNICODE_STRING pRegPath)
    12771335{
    1278 #ifdef DEBUG_misha
     1336#ifdef VBOX_USB_WITH_VERBOSE_LOGGING
    12791337    RTLogGroupSettings(0, "+default.e.l.f.l2.l3");
    12801338    RTLogDestinations(0, "debugger");

  • trunk/src/VBox/HostDrivers/VBoxUSB/win/mon/VBoxUsbMon.h

    r38262 r38356  
    3131#endif
    3232
    33 #define VBOX_DBG_LOG_NAME "USBMon"
    3433#include "../../../win/VBoxDbgLog.h"
    3534#include "../cmn/VBoxDrvTool.h"
Note: See TracChangeset for help on using the changeset viewer.

© 2024 Oracle Support Privacy / Do Not Sell My Info Terms of Use Trademark Policy Automated Access Etiquette