Re: VMware USB Arbitration Service bug

Minaum · ‎11-25-2012

Hello!

VMware Workstation v8.0.x (all versions), VMware Workstation v9.0.0 and VMware Workstation v9.0.1 have the same bug in USB Arbitration Service.

I have a few error messages in debug log of USB Arbitration Service. This service try to do something with USB every second, and always fail. All these errors are stored to the debug log, it is writing, writing, writing and writing this errors to the log, again, again, and again. My logs have a very huge size - 231MB (vmware-usbarb-3384.log), 236MB (vmware-usbarb-3512.log), 479MB (vmware-usbarb-3036.log) and so on. Moreover, vmware-usbarbitrator.exe process (service) acquiring this virtual memory to store all log in the memory!!! I.e. it seems like a permanent memory leak, but really, it actively store new errors to the log. Please fix this bug with USB.

Here is a log in %TEMP%: vmware-usbarb-XXXX.log

===================================================================================

2012-11-25T14:59:46.736+04:00| usbArb| I120: Log for VMware USB Arbitration Service pid=15996 version=5.0.1 build=build-871296 option=Release
2012-11-25T14:59:46.736+04:00| usbArb| I120: The process is 32-bit.
2012-11-25T14:59:46.736+04:00| usbArb| I120: Host codepage=windows-1251 encoding=windows-1251
2012-11-25T14:59:46.736+04:00| usbArb| I120: Host is Windows Server 2003 Enterprise Edition Service Pack 2 (Build 3790)
2012-11-25T14:59:46.736+04:00| usbArb| I120: VTHREAD initialize main thread 2 "usbArb" host id 12712
2012-11-25T14:59:46.736+04:00| usbArb| I120: Msg_Reset:
2012-11-25T14:59:46.736+04:00| usbArb| I120: [msg.dictionary.load.openFailed] Cannot open file "C:\Documents and Settings\All Users\Application Data\VMware\VMware USB Arbitration Service\config.ini": The system cannot find the file specified.
2012-11-25T14:59:46.736+04:00| usbArb| I120: ----------------------------------------
2012-11-25T14:59:46.736+04:00| usbArb| I120: PREF Optional preferences file not found at C:\Documents and Settings\All Users\Application Data\VMware\VMware USB Arbitration Service\config.ini. Using default values.
2012-11-25T14:59:46.736+04:00| usbArb| I120: Msg_Reset:
2012-11-25T14:59:46.736+04:00| usbArb| I120: [msg.dictionary.load.openFailed] Cannot open file "C:\Documents and Settings\All Users\Application Data\VMware\VMware USB Arbitration Service\settings.ini": The system cannot find the file specified.
2012-11-25T14:59:46.736+04:00| usbArb| I120: ----------------------------------------
2012-11-25T14:59:46.736+04:00| usbArb| I120: PREF Optional preferences file not found at C:\Documents and Settings\All Users\Application Data\VMware\VMware USB Arbitration Service\settings.ini. Using default values.
2012-11-25T14:59:46.736+04:00| usbArb| I120: Msg_Reset:
2012-11-25T14:59:46.736+04:00| usbArb| I120: [msg.dictionary.load.openFailed] Cannot open file "C:\Documents and Settings\All Users\Application Data\VMware\VMware USB Arbitration Service\config.ini": The system cannot find the file specified.
2012-11-25T14:59:46.736+04:00| usbArb| I120: ----------------------------------------
2012-11-25T14:59:46.736+04:00| usbArb| I120: PREF Optional preferences file not found at C:\Documents and Settings\All Users\Application Data\VMware\VMware USB Arbitration Service\config.ini. Using default values.
2012-11-25T14:59:46.736+04:00| usbArb| I120: Msg_Reset:
2012-11-25T14:59:46.736+04:00| usbArb| I120: [msg.dictionary.load.openFailed] Cannot open file "C:\Documents and Settings\Default User\Application Data\VMware\config.ini": The system cannot find the file specified.
2012-11-25T14:59:46.736+04:00| usbArb| I120: ----------------------------------------
2012-11-25T14:59:46.736+04:00| usbArb| I120: PREF Optional preferences file not found at C:\Documents and Settings\Default User\Application Data\VMware\config.ini. Using default values.
2012-11-25T14:59:46.736+04:00| usbArb| I120: PREF Disabling user preferences because disableUserPreferences is set.
2012-11-25T14:59:46.736+04:00| usbArb| I120: PREF Failed to load user preferences.
2012-11-25T14:59:46.736+04:00| usbArb| I120: POLL Using the select API Implementation for PollDefault
2012-11-25T14:59:46.736+04:00| usbArb| I120: Hostinfo_OpenProcessBits: OpenProcess access bits are 400.
2012-11-25T14:59:46.783+04:00| usbArb| I120: DICT --- USER PREFERENCES
2012-11-25T14:59:46.783+04:00| usbArb| I120: DICT --- USER DEFAULTS C:\Documents and Settings\Default User\Application Data\VMware\config.ini
2012-11-25T14:59:46.783+04:00| usbArb| I120: DICT --- HOST DEFAULTS C:\Documents and Settings\All Users\Application Data\VMware\VMware USB Arbitration Service\config.ini
2012-11-25T14:59:46.783+04:00| usbArb| I120: DICT --- SITE DEFAULTS C:\Documents and Settings\All Users\Application Data\VMware\VMware USB Arbitration Service\config.ini
2012-11-25T14:59:46.783+04:00| usbArb| I120: VMware USB Arbitration Service Version 10.1.23
2012-11-25T14:59:46.783+04:00| vthread-3| I120: VTHREAD initialize thread 3 "vthread-3" host id 16000
2012-11-25T14:59:46.783+04:00| vthread-3| I120: USBArb: Starting VMUSBArbService args:'VMUSBArbService'
2012-11-25T14:59:46.783+04:00| vthread-3| I120: USBGW: Host controller #0 = "\\?\HCD0"
2012-11-25T14:59:46.783+04:00| vthread-3| I120: USBGW: Host controller #1 = "\\?\HCD1"
2012-11-25T14:59:46.783+04:00| vthread-3| I120: USBGW: Host controller #2 = "\\?\pci#ven_1b21&dev_1042&subsys_84881043&rev_00#4&39d38640&0&00e2#{3abf6f2d-71c4-462a-8a92-1e6861e6af27}"
2012-11-25T14:59:46.783+04:00| vthread-3| I120: USBGW: Host controller #3 = "\\?\pci#ven_1b21&dev_1042&subsys_84881043&rev_00#4&2a3c25e0&0&00e3#{3abf6f2d-71c4-462a-8a92-1e6861e6af27}"
2012-11-25T14:59:46.783+04:00| vthread-3| I120: USBArb: Connected to HCMON version 3.16
2012-11-25T14:59:46.783+04:00| vthread-3| W110: USBArb: Failed to send HC NamC:\??\pci#ven_1b21&dev_1042&subsys_84881043&rev_00#4&39d38640&0&00e2#{3abf6f2d-71c4-462a-8a92-1e6861e6af27} to HCMON: A device attached to the system is not functioning (31)
2012-11-25T14:59:46.783+04:00| vthread-3| W110: USBArb: Failed to send HC NamC:\??\pci#ven_1b21&dev_1042&subsys_84881043&rev_00#4&2a3c25e0&0&00e3#{3abf6f2d-71c4-462a-8a92-1e6861e6af27} to HCMON: A device attached to the system is not functioning (31)
2012-11-25T14:59:46.892+04:00| vthread-4| I120: VTHREAD initialize thread 4 "vthread-4" host id 15304
2012-11-25T14:59:46.892+04:00| vthread-4| I120: HOSTINFO 1090789854562 @ 3579545Hz -> 0 @ 1000000000Hz
2012-11-25T14:59:46.892+04:00| vthread-4| I120: HOSTINFO ((x * 2343484437) >> 23) + -304728632951204
2012-11-25T14:59:46.908+04:00| vthread-4| I120: USBArb: VMUSBArbService Started.
2012-11-25T14:59:48.908+04:00| vthread-4| I120: USBGW: Error retrieving child name: The request is not supported (50)
2012-11-25T14:59:48.908+04:00| vthread-4| W110: USBGW-ENUM: Failed to get hub name for port:2
2012-11-25T14:59:48.923+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:1. Leaving out of enum
2012-11-25T14:59:48.923+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:2. Leaving out of enum
2012-11-25T14:59:48.923+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:3. Leaving out of enum
2012-11-25T14:59:48.923+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:4. Leaving out of enum
2012-11-25T14:59:48.923+04:00| vthread-4| I120: USBGW: Error retrieving child name: The request is not supported (50)
2012-11-25T14:59:48.923+04:00| vthread-4| W110: USBGW-ENUM: Failed to get hub name for port:2
2012-11-25T14:59:49.923+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:1. Leaving out of enum
2012-11-25T14:59:49.923+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:2. Leaving out of enum
2012-11-25T14:59:49.923+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:3. Leaving out of enum
2012-11-25T14:59:49.923+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:4. Leaving out of enum
2012-11-25T14:59:49.923+04:00| vthread-4| I120: USBGW: Error retrieving child name: The request is not supported (50)
2012-11-25T14:59:49.923+04:00| vthread-4| W110: USBGW-ENUM: Failed to get hub name for port:2

[... skipped about 5 mb of the same content ...]

2012-11-25T17:16:47.653+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:1. Leaving out of enum
2012-11-25T17:16:47.653+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:2. Leaving out of enum
2012-11-25T17:16:47.653+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:3. Leaving out of enum
2012-11-25T17:16:47.653+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:4. Leaving out of enum
2012-11-25T17:16:47.653+04:00| vthread-4| I120: USBGW: Error retrieving child name: The request is not supported (50)
2012-11-25T17:16:47.653+04:00| vthread-4| W110: USBGW-ENUM: Failed to get hub name for port:2
2012-11-25T17:16:48.654+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:1. Leaving out of enum
2012-11-25T17:16:48.654+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:2. Leaving out of enum
2012-11-25T17:16:48.654+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:3. Leaving out of enum
2012-11-25T17:16:48.654+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:4. Leaving out of enum
2012-11-25T17:16:48.654+04:00| vthread-4| I120: USBGW: Error retrieving child name: The request is not supported (50)
2012-11-25T17:16:48.654+04:00| vthread-4| W110: USBGW-ENUM: Failed to get hub name for port:2
2012-11-25T17:16:49.654+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:1. Leaving out of enum
2012-11-25T17:16:49.654+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:2. Leaving out of enum
2012-11-25T17:16:49.654+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:3. Leaving out of enum
2012-11-25T17:16:49.654+04:00| vthread-4| I120: USBGW_ENUM: Couldn't get instanceId from topology:0x3000000 port:4. Leaving out of enum
2012-11-25T17:16:49.654+04:00| vthread-4| I120: USBGW: Error retrieving child name: The request is not supported (50)
2012-11-25T17:16:49.654+04:00| vthread-4| W110: USBGW-ENUM: Failed to get hub name for port:2

===================================================================================

continuum · ‎11-25-2012

do you have USB 3 hardware on your host ? - USB3 support is work in progress and only works with a few drivers at the moment

________________________________________________
Do you need support with a VMFS recovery problem ? - send a message via skype "sanbarrow"
I do not support Workstation 16 at this time ...

Minaum · ‎11-25-2012

No, I have not.

There are few devices, that are connected through USB: simple Microsoft Keyboard, simple A4Tech mouse, an old Transcend USB Flash and an old D-Link ADSL USB Modem. All these devices are USB 1.0/1.1/2.0, not a 3.0 for 100%. Also, they are plugged to USB 2.0 connectors, not USB 3.0.

Minaum · ‎11-25-2012

Could someone forward this to developers? Because it is a real bug:

* permanently growing a log with the same error messages (the best thing it is to fix the issue, to have no that error messages or find workaround for them)

* and permanently growing used Virtual Memory for USB Arbitrator Service process = this behaviour is similar to memory leak, but there is is known why it occurs -- growing log with errors.

BrianTokyo · ‎01-27-2013

Same issue here, after a few days the service is already using over 1GB of ram.

zacwolfdotcom · ‎04-15-2013

I am seeing this issue as well, and it pretty much equates to a memory leak because within a short-time of firing up an appliance, the "VMWARE USB Arbitration" services consumes over a gig of memory...

I do have an additional USB3 pci-e card [is there any information regarding currently supported drivers?].

Is there any workaround to disable logging for the service until support is implemented?

My log file is filled with:

2013-04-10T17:45:40.403-04:00| vthread-4| I120: USBGW_ENUM: Got invalid dd for topology:0x3000000 port:4. Leaving out of enum

zacwolfdotcom · ‎04-15-2013

OK, after researching this further, it looks like the root cause was I had a faulty USB device driver ("for topology:0x3000000 port:4") on my system OS (not the guest OS). I am running Windows 8-64bit and WMware Workstation 9 with all latest patches.

I deleted the device from the Device Manager, re-installed with a good driver, and the error messages stopped.

BUT, this does still point to a very serious flaw in the "VMware USB Abritration Service" code, in that it would seem that the log output is being retained in memory as well as output to the log file? This quickly creates what equates to a memory leak issue, when log entries are being created over and over and over again.

This service needs to be fixed to not "cache" the log output in memory, and/or to ignore errors after X-number of repeats.

THANKS!

-Zac Morris

jolocktest · ‎07-13-2013

dose any one no how to fix this because it is bull**** and i hate it because i boght it

jolocktest · ‎07-13-2013

Select the ‘Start’ button, in the ‘search programs and files’ box, type ‘regedit.exe’
-Navigate the registry to this entry:
HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Class\{36FC9E60-C465-11CF-8056-444553540000}.
In the right hand side, if the value “UpperFilters” exists, delete it.

5. Reboot the system so that VMWare can access USB devices.

IT WORKS TRUST ME IT THE ONLY WAY IF YOU WANT TO THANK ME SUBSCRIB TO MY YOU TUBE CHEANLE jake Bradford - YouTube PLZ DO IT IT TOOK ME HOURS FINDING OUT THIS HOPE IT HELPS