Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

threads_windows.c: Memory access violation #412

Closed
jite opened this issue Mar 27, 2018 · 19 comments
Closed

threads_windows.c: Memory access violation #412

jite opened this issue Mar 27, 2018 · 19 comments
Labels

Comments

@jite
Copy link

jite commented Mar 27, 2018

Commit 4be3202 refactored the Windows locking handling. However when running pyusb (using libusb1 backend) on win10 (64bit/64bit Python) we ran into a problem while trying to find USB devices: it always gave an OSError exception: "access violation writing 0x0000000000000024". Worth noting is that it works fine to detect devices, however the object finalize/del stage fails.

Unsure if it's a problem in libusb or pyusb, but did some digging and found out that prior to the commit mentioned, it works fine. Anyway, what I suspect is causing the issue is that something references mutex after usbi_mutex_destroy() has been called (which runs DeleteCriticalSection(mutex)). Quick test of adding a InitializeCriticalSection(mutex)after the deletion eliminates the problem (while of course not a proper solution).

@dickens
Copy link
Member

dickens commented Mar 27, 2018

Please provide a debug log of libusb.

@mcuee mcuee added the windows label Apr 7, 2018
@JoshMayberry
Copy link

I also get this error when running the following code:

import wx
import usb

class MyForm(wx.Frame):
	def __init__(self):
		wx.Frame.__init__(self, None, wx.ID_ANY, "Example")
		panel = wx.Panel(self, wx.ID_ANY)
		sizer = wx.BoxSizer(wx.VERTICAL)

		button = wx.Button(panel, label="Run test()")
		button.Bind(wx.EVT_BUTTON, self.test)
		
		sizer.Add(button, 0, wx.ALL|wx.CENTER, 5)
		panel.SetSizer(sizer)

	def test(self, event):
		valueList = []
		devices = usb.core.find(find_all=True)
		for config in devices:
			valueList.append((config.idVendor, config.idProduct))
		print(valueList)

		event.Skip()

if __name__ == "__main__":
	app = wx.App(False)
	frame = MyForm()
	frame.Show()
	app.MainLoop()

To produce the error, press the button "Run test()" in the frame that appears after running the code.

Here is the error that I get:

Exception ignored in: <bound method _AutoFinalizedObjectBase.__del__ of <usb.backend.libusb1._Device object at 0x04307210>>
Traceback (most recent call last):
  File "C:\Users\guest\AppData\Local\Programs\Python\Python36-32\lib\site-packages\usb\_objfinalizer.py", line 84, in __del__
    self.finalize()
  File "C:\Users\guest\AppData\Local\Programs\Python\Python36-32\lib\site-packages\usb\_objfinalizer.py", line 144, in finalize
    self._finalizer()
  File "C:\Users\guest\AppData\Local\Programs\Python\Python36-32\lib\weakref.py", line 548, in __call__
    return info.func(*info.args, **(info.kwargs or {}))
  File "C:\Users\guest\AppData\Local\Programs\Python\Python36-32\lib\site-packages\usb\_objfinalizer.py", line 104, in _do_finalize_object_ref
    obj._do_finalize_object()
  File "C:\Users\guest\AppData\Local\Programs\Python\Python36-32\lib\site-packages\usb\_objfinalizer.py", line 71, in _do_finalize_object
    self._finalize_object()
  File "C:\Users\guest\AppData\Local\Programs\Python\Python36-32\lib\site-packages\usb\backend\libusb1.py", line 604, in _finalize_object
    _lib.libusb_unref_device(self.devid)
OSError: exception: access violation writing 0x00000014
^C

@mcuee
Copy link
Member

mcuee commented Jun 13, 2018 via email

@JoshMayberry
Copy link

How do I set those variables? Also, where will the logs be generated to?

@mcuee
Copy link
Member

mcuee commented Jun 14, 2018

Something like this under Windows command (I tested using a virtual env).

(myenv) C:\work\pyusb>set PYUSB_ERROR=debug
(myenv) C:\work\pyusb>set LIBUSB_DEBUG=4
(myenv) C:\work\pyusb>cd test
(myenv) C:\work\pyusb\test>python simpleusb.py > test.log 2>&1

@mcuee
Copy link
Member

mcuee commented Jun 14, 2018

Then post the log file.

It will be something like this.

[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.000000] [000022dc] libusb: debug [libusb_init] created default context
[ 0.000000] [000022dc] libusb: debug [libusb_init] libusb v1.0.22.11312
[ 0.000000] [000022dc] libusb: debug [windows_init_dlls] Will use CancelIoEx for I/O cancellation
[ 0.000000] [000022dc] libusb: debug [get_windows_version] Windows 11 or later 64-bit
[ 0.000000] [000022dc] libusb: debug [windows_init_clock] hires timer available (Frequency: 2734376 Hz)
[ 0.000000] [000022dc] libusb: debug [windows_init_clock] timer thread will run on core #0
[ 0.000000] [000022dc] libusb: debug [htab_create] using 1021 entries hash table
[ 0.000000] [000022dc] libusb: debug [winusbx_init] using libusbK DLL for universal access
[ 0.000000] [000022dc] libusb: debug [winusbx_init] libusbK version: 3.0.7.0
[ 0.000000] [000022dc] libusb: debug [winusbx_init] initalized sub API libusbK
[ 0.000000] [000022dc] libusb: debug [winusbx_init] initalized sub API libusb0
[ 0.000000] [000022dc] libusb: debug [winusbx_init] initalized sub API WinUSB
[ 0.000000] [000022dc] libusb: debug [windows_init] UsbDk backend is available
[ 0.000000] [000022dc] libusb: debug [usbi_add_pollfd] add fd 0 events 1
[ 0.000000] [000022dc] libusb: debug [libusb_get_device_list] 
...

@mcuee
Copy link
Member

mcuee commented Jun 14, 2018

Okay, I can reproduce this issue myself by running your program.

(myenv) C:\work\pyusb\test>python wxusb.py
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.000000] [000007ac] libusb: debug [libusb_init] created default context
[ 0.000000] [000007ac] libusb: debug [libusb_init] libusb v1.0.22.11312
[ 0.000000] [000007ac] libusb: debug [windows_init_dlls] Will use CancelIoEx for I/O cancellation
[ 0.000000] [000007ac] libusb: debug [get_windows_version] Windows 11 or later 64-bit
[ 0.000000] [000007ac] libusb: debug [windows_init_clock] hires timer available (Frequency: 2734376 Hz)
[ 0.000000] [000007ac] libusb: debug [windows_init_clock] timer thread will run on core #0
[ 0.000000] [000007ac] libusb: debug [htab_create] using 1021 entries hash table
[ 0.000000] [000007ac] libusb: debug [winusbx_init] using libusbK DLL for universal access
[ 0.000000] [000007ac] libusb: debug [winusbx_init] libusbK version: 3.0.7.0
[ 0.000000] [000007ac] libusb: debug [winusbx_init] initalized sub API libusbK
[ 0.000000] [000007ac] libusb: debug [winusbx_init] initalized sub API libusb0
[ 0.000000] [000007ac] libusb: debug [winusbx_init] initalized sub API WinUSB
[ 0.000000] [000007ac] libusb: debug [windows_init] UsbDk backend is available
[ 0.000000] [000007ac] libusb: debug [usbi_add_pollfd] add fd 0 events 1
[ 0.000000] [000007ac] libusb: debug [libusb_get_device_list]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [56]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [57]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [58]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [59]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [5A]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [5B]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [5C]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [5D]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [5E]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [5F]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [60]
[ 0.015625] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [61]
[ 0.031249] [000007ac] libusb: debug [get_api_type] driver(s): BTHUSB
[ 0.031249] [000007ac] libusb: debug [get_api_type] lower filter driver(s): bcbtums;btwampfl
[ 0.031249] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [1]
[ 0.031249] [000007ac] libusb: debug [get_api_type] driver(s): libusb0
[ 0.031249] [000007ac] libusb: debug [get_api_type] matched driver name against libusb0
[ 0.031249] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [B]
[ 0.031249] [000007ac] libusb: debug [get_api_type] driver(s): RtlWlanu
[ 0.031249] [000007ac] libusb: debug [get_api_type] upper filter driver(s): vwifibus
[ 0.031249] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [1B]
[ 0.031249] [000007ac] libusb: debug [get_api_type] driver(s): CH341SER_A64
[ 0.031249] [000007ac] libusb: debug [get_api_type] upper filter driver(s): serenum
[ 0.031249] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [26]
[ 0.031249] [000007ac] libusb: debug [get_api_type] driver(s): WinUSB
[ 0.031249] [000007ac] libusb: debug [get_api_type] matched driver name against WinUSB
[ 0.031249] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [3F]
[ 0.031249] [000007ac] libusb: debug [get_api_type] driver(s): usbccgp
[ 0.031249] [000007ac] libusb: debug [get_api_type] matched driver name against Composite API
[ 0.031249] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [43]
[ 0.031249] [000007ac] libusb: debug [get_api_type] driver(s): USBSTOR
[ 0.031249] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [44]
[ 0.031249] [000007ac] libusb: debug [get_api_type] driver(s): HidUsb
[ 0.031249] [000007ac] libusb: debug [get_api_type] matched driver name against HID API
[ 0.031249] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [45]
[ 0.046875] [000007ac] libusb: debug [get_api_type] driver(s): USBSTOR
[ 0.046875] [000007ac] libusb: debug [winusb_get_device_list] allocating new device for session [46]
[ 0.046875] [000007ac] libusb: debug [enumerate_hcd_root_hub] assigning HCD 'PCI\VEN_8086&DEV_27CB&SUBSYS_2A8C103C&REV_01\3&11583659&0&EB' bus number 1
[ 0.046875] [000007ac] libusb: debug [enumerate_hcd_root_hub] assigning HCD 'PCI\VEN_8086&DEV_27C8&SUBSYS_2A8C103C&REV_01\3&11583659&0&E8' bus number 2
[ 0.046875] [000007ac] libusb: debug [enumerate_hcd_root_hub] assigning HCD 'PCI\VEN_8086&DEV_27C9&SUBSYS_2A8C103C&REV_01\3&11583659&0&E9' bus number 3
[ 0.046875] [000007ac] libusb: debug [enumerate_hcd_root_hub] assigning HCD 'PCI\VEN_1033&DEV_0194&SUBSYS_00000000&REV_03\FFFFFFFFFFFFFFFF00' bus number 4
[ 0.046875] [000007ac] libusb: debug [enumerate_hcd_root_hub] assigning HCD 'PCI\VEN_8086&DEV_27CA&SUBSYS_2A8C103C&REV_01\3&11583659&0&EA' bus number 5
[ 0.046875] [000007ac] libusb: debug [enumerate_hcd_root_hub] assigning HCD 'PCI\VEN_8086&DEV_27CC&SUBSYS_2A8C103C&REV_01\3&11583659&0&EF' bus number 6
[ 0.046875] [000007ac] libusb: debug [init_device] (bus: 1, addr: 0, depth: 0, port: 0): 'USB\ROOT_HUB\4&1D76050&0'
[ 0.046875] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [5D]
[ 0.046875] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.046875] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 41 bytes)
[ 0.046875] [000007ac] libusb: debug [init_device] (bus: 4, addr: 5, depth: 2, port: 1): 'USB\VID_0BDA&PID_5411\7&8604D34&0&1'
[ 0.046875] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [5B]
[ 0.046875] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.046875] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 31 bytes)
[ 0.046875] [000007ac] libusb: debug [init_device] (bus: 4, addr: 3, depth: 2, port: 1): 'USB\VID_0BDA&PID_0411\7&48EBE67&0&1'
[ 0.046875] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [60]
[ 0.046875] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.062500] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 31 bytes)
[ 0.062500] [000007ac] libusb: debug [init_device] (bus: 4, addr: 1, depth: 1, port: 1): 'USB\VID_0BDA&PID_0411\6&38FE5F06&0&1'
[ 0.062500] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [58]
[ 0.062500] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.062500] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 41 bytes)
[ 0.062500] [000007ac] libusb: debug [init_device] (bus: 4, addr: 2, depth: 1, port: 3): 'USB\VID_0BDA&PID_5411\6&38FE5F06&0&3'
[ 0.062500] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [1]
[ 0.062500] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.062500] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 218 bytes)
[ 0.062500] [000007ac] libusb: debug [init_device] (bus: 6, addr: 6, depth: 2, port: 7): 'USB\VID_0A5C&PID_21E8\5CF3708A6D48'
[ 0.062500] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [59]
[ 0.062500] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.062500] [000007ac] libusb: info [cache_config_descriptors] could not access configuration descriptor 0 (dummy) for 'USB\VID_1A40&PID_0201\6&142A28FA&0&5': [31] A device attached to the system is not functioning.
[ 0.062500] [000007ac] libusb: debug [init_device] (bus: 6, addr: 5, depth: 2, port: 5): 'USB\VID_1A40&PID_0201\6&142A28FA&0&5'
[ 0.062500] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [45]
[ 0.147642] [000007ac] libusb: debug [init_device] found 2 configurations (active conf: 1)
[ 0.147642] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 41 bytes)
[ 0.147642] [000007ac] libusb: info [cache_config_descriptors] could not access configuration descriptor 1 (dummy) for 'USB\VID_04D8&PID_0033\PK2NEW': [31] A device attached to the system is not functioning.
[ 0.147642] [000007ac] libusb: debug [init_device] (bus: 6, addr: 7, depth: 3, port: 3): 'USB\VID_04D8&PID_0033\PK2NEW'
[ 0.147642] [000007ac] libusb: debug [init_device] (bus: 5, addr: 0, depth: 0, port: 0): 'USB\ROOT_HUB\4&1397E823&0'
[ 0.147642] [000007ac] libusb: debug [discovered_devs_append] need to increase capacity
[ 0.147642] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [26]
[ 0.147642] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.147642] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 39 bytes)
[ 0.147642] [000007ac] libusb: debug [init_device] (bus: 6, addr: 4, depth: 2, port: 3): 'USB\VID_1A86&PID_7523\6&142A28FA&0&3'
[ 0.147642] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [1B]
[ 0.147642] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.147642] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 83 bytes)
[ 0.147642] [000007ac] libusb: debug [init_device] (bus: 4, addr: 6, depth: 1, port: 2): 'USB\VID_2357&PID_0106\123456'
[ 0.147642] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [44]
[ 0.147642] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.147642] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 44 bytes)
[ 0.147642] [000007ac] libusb: debug [init_device] (bus: 4, addr: 4, depth: 3, port: 2): 'USB\VID_0781&PID_5581\4C531001401224105220'
[ 0.147642] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [B]
[ 0.147642] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.163274] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 32 bytes)
[ 0.163274] [000007ac] libusb: debug [init_device] (bus: 2, addr: 1, depth: 1, port: 1): 'USB\VID_0FCF&PID_1009\111'
[ 0.163274] [000007ac] libusb: debug [init_device] (bus: 6, addr: 0, depth: 0, port: 0): 'USB\ROOT_HUB20\4&1AB460DB&0'
[ 0.163274] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [46]
[ 0.163274] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.163274] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 32 bytes)
[ 0.163274] [000007ac] libusb: debug [init_device] (bus: 6, addr: 1, depth: 1, port: 7): 'USB\VID_058F&PID_6366\058F63666433'
[ 0.163274] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [61]
[ 0.163274] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.163274] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 41 bytes)
[ 0.163274] [000007ac] libusb: debug [init_device] (bus: 6, addr: 2, depth: 1, port: 4): 'USB\VID_1A40&PID_0201\5&2B206C2B&0&4'
[ 0.163274] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [43]
[ 0.163274] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.178900] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 84 bytes)
[ 0.178900] [000007ac] libusb: debug [init_device] (bus: 3, addr: 1, depth: 1, port: 1): 'USB\VID_046D&PID_C52B\5&1AB0C0B&0&1'
[ 0.178900] [000007ac] libusb: debug [discovered_devs_append] need to increase capacity
[ 0.178900] [000007ac] libusb: debug [init_device] (bus: 3, addr: 0, depth: 0, port: 0): 'USB\ROOT_HUB\4&287CBA06&0'
[ 0.178900] [000007ac] libusb: debug [init_device] (bus: 4, addr: 0, depth: 0, port: 0): 'USB\ROOT_HUB30\5&345C3975&0&0'
[ 0.178900] [000007ac] libusb: debug [winusb_get_device_list] extra GUID: {8D891245-36D8-4ECA-9A92-481F0A912DCF}
[ 0.178900] [000007ac] libusb: debug [winusb_get_device_list] found existing device for session [3F]
[ 0.178900] [000007ac] libusb: debug [init_device] found 1 configurations (active conf: 1)
[ 0.178900] [000007ac] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 32 bytes)
[ 0.178900] [000007ac] libusb: debug [init_device] (bus: 6, addr: 3, depth: 2, port: 2): 'USB\VID_0403&PID_6001\A8007UB5'
[ 0.178900] [000007ac] libusb: debug [init_device] (bus: 2, addr: 0, depth: 0, port: 0): 'USB\ROOT_HUB\4&288D5874&0'
[ 0.178900] [000007ac] libusb: debug [winusb_get_device_list] setting composite interface for [43]:
[ 0.178900] [000007ac] libusb: debug [set_composite_interface] interface[1] = \\.\HID#VID_046D&PID_C52B&MI_01&COL01#7&56C8C02&0&0000#{4D1E55B2-F16F-11CF-88CB-001111000030}
[ 0.178900] [000007ac] libusb: debug [winusb_get_device_list] setting composite interface for [43]:
[ 0.178900] [000007ac] libusb: debug [set_composite_interface] interface[1] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_01&COL03\7&56C8C02&0&0002
[ 0.194525] [000007ac] libusb: debug [winusb_get_device_list] setting composite interface for [43]:
[ 0.194525] [000007ac] libusb: debug [set_composite_interface] interface[1] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_01&COL04\7&56C8C02&0&0003
[ 0.194525] [000007ac] libusb: debug [winusb_get_device_list] setting HID interface for [45]:
[ 0.194525] [000007ac] libusb: debug [set_hid_interface] interface[0] = \\.\HID#VID_04D8&PID_0033#8&BD5B18B&0&0000#{4D1E55B2-F16F-11CF-88CB-001111000030}
[ 0.194525] [000007ac] libusb: debug [winusb_get_device_list] setting composite interface for [43]:
[ 0.194525] [000007ac] libusb: debug [set_composite_interface] interface[2] = \\.\HID#VID_046D&PID_C52B&MI_02&COL01#7&1E6AB1C0&0&0000#{4D1E55B2-F16F-11CF-88CB-001111000030}
[ 0.194525] [000007ac] libusb: debug [winusb_get_device_list] setting composite interface for [43]:
[ 0.194525] [000007ac] libusb: debug [set_composite_interface] interface[2] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_02&COL02\7&1E6AB1C0&0&0001
[ 0.194525] [000007ac] libusb: debug [winusb_get_device_list] setting composite interface for [43]:
[ 0.194525] [000007ac] libusb: debug [set_composite_interface] interface[2] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_02&COL03\7&1E6AB1C0&0&0002
[ 0.194525] [000007ac] libusb: debug [winusb_get_device_list] setting composite interface for [43]:
[ 0.194525] [000007ac] libusb: debug [set_composite_interface] interface[0] = \\.\HID#VID_046D&PID_C52B&MI_00#7&2943C9C4&0&0000#{4D1E55B2-F16F-11CF-88CB-001111000030}
[ 0.194525] [000007ac] libusb: debug [winusb_get_device_list] setting composite interface for [43]:
[ 0.210149] [000007ac] libusb: debug [set_composite_interface] interface[1] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_01&COL02\7&56C8C02&0&0001
[ 0.210149] [000007ac] libusb: debug [get_api_type] driver(s): WinUSB
[ 0.216036] [000007ac] libusb: debug [get_api_type] matched driver name against WinUSB
[ 0.217037] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.218037] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.218037] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.219036] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220036] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_get_device_descriptor]
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 1.0
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 4.5
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 4.2
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 6.6
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 6.7
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 6.5
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 5.0
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 6.4
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 4.6
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 4.4
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 4.3
[ 0.220463] [000007ac] libusb: debug [libusb_unref_device] destroy device 4.1
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 2.1
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 6.1
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 3.1
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 3.0
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 4.0
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 6.3
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 6.2
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 6.0
[(32902, 10187), (3034, 21521), (3034, 1041), (3034, 1041), (3034, 21521), (2652, 8680), (6720, 513), (1240, 51), (32902, 10186), (6790, 29987), (9047, 262), (1921, 21889), (4047, 4105), (32902, 10188), (1423, 25446), (6720, 513), (1133, 50475), (32902, 10185), (4147, 404), (1027, 24577), (32902, 10184)]
[ 0.236087] [000007ac] libusb: debug [libusb_exit]
[ 0.236087] [000007ac] libusb: debug [libusb_exit] destroying default context
[ 0.236087] [000007ac] libusb: warning [libusb_exit] some libusb_devices were leaked
[ 0.236087] [000007ac] libusb: debug [usbi_remove_pollfd] remove fd 0
[ 0.236087] [00001eb4] libusb: debug [windows_clock_gettime_threaded] timer thread quitting
[ 0.236087] [000007ac] libusb: debug [libusb_unref_device] destroy device 2.0
Exception ignored in: <bound method _AutoFinalizedObjectBase.__del__ of <usb.backend.libusb1._Device object at 0x000002502B662F98>>
Traceback (most recent call last):
  File "C:\work\pyenv64\myenv\lib\site-packages\usb\_objfinalizer.py", line 84, in __del__
    self.finalize()
  File "C:\work\pyenv64\myenv\lib\site-packages\usb\_objfinalizer.py", line 144, in finalize
    self._finalizer()
  File "C:\work\pyenv64\myenv\lib\weakref.py", line 548, in __call__
    return info.func(*info.args, **(info.kwargs or {}))
  File "C:\work\pyenv64\myenv\lib\site-packages\usb\_objfinalizer.py", line 104, in _do_finalize_object_ref
    obj._do_finalize_object()
  File "C:\work\pyenv64\myenv\lib\site-packages\usb\_objfinalizer.py", line 71, in _do_finalize_object
    self._finalize_object()
  File "C:\work\pyenv64\myenv\lib\site-packages\usb\backend\libusb1.py", line 604, in _finalize_object
    _lib.libusb_unref_device(self.devid)
OSError: exception: access violation writing 0x0000000000000024

@JoshMayberry
Copy link

Awesome. I'm glad you were able to reproduce it.

@jite
Copy link
Author

jite commented Jun 14, 2018

It would be interesting to know later on if the debug logs actually helped you solve this particular issue or not (since you’ve been inclined not to touch this issue without one). I’m a developer myself and I know how frustrating it can be with bad bug reports so don’t get me wrong.

I did provide you with the commit that introduced the issue and a likely cause for it. It looked like it wouldn’t take the author more than a couple of hours tops to figure out what went wrong. Priorities shifted at work right after this happened so couldn’t provide a log.

@mcuee
Copy link
Member

mcuee commented Jun 15, 2018

@jite I can understand what you come from. And thanks for reporting the issue and provide a possible cause which is great.

On the other hand, I have some issues with your comment. Firstly to ask for a debug log can usually help. Secondly you can see that "Priorities shifted at work right after this happened so couldn’t provide a log" and it only takes a few minutes to generate the debug log, not "a couple of hours". It can be difficult to find a couple of hours at your spare time working on open source projects like libusb. BTW, I do not know if it is really a couple of hours myself since I am not a programmer and I do not know much about the internal working mechanisms of libusb (mainly on technical support and testing side of the projects).

@welitonfreitas
Copy link

same issue, any solutions or workaround?

@JoshMayberry
Copy link

@mcuee @jite Have you found a way to patch this behavior?

@jite
Copy link
Author

jite commented Jul 3, 2018

@JoshMayberry I did an initial investigation of what caused it and found that the mutex variable is most likely referenced after it’s been destroyed. I don’t know the internals of libusb and I’m not that familiar with Windows threading/locks to find the exact culprit. I did a quick workaround by initializing the mutex right after it’s destroyed so that any action towards ’mutex’ would be valid (from memory perspective). It’s not a proper fix but it worked as a temporary workaround.

We’ve later seen other weird issues using libusb1 as backend (for a winusb device) to pyusb forcing us to move to libusb0-win32 backend instead. The big drawback doing so is that we need to install a device filter for our device pointing it to libusb0.

What kind of usb device do you have? Winusb?

@mcuee The circumstances were unfortunate. I didn’t see the request for the logs immediatly, and when I did we had scrapped the hardware for other reasons (and started with a new setup). I would have provided the logs if I easily could :) (Having that said though, I don’t think the logs would provide much help for this issue. I’ve narrowed down the commit and that’s usually enough to get a good grip of what might be wrong. Since the change involved rewriting locking on windows and it was a rather small commit, I found it rather likely that the author could find the issue pretty quickly with the information given.)

@JoshMayberry
Copy link

@jite The USB device in particular that I am using is a USB/COM barcode scanner. But, I get this issue regardless of it being plugged in or not. I hope that answered your question.
For now, I am using 'serial' to communicate with it.

@mcuee
Copy link
Member

mcuee commented Jul 10, 2018

@jite I see. Thanks for the clarifications. Hopefully this issue can be fixed (if it is confirmed to be an issue with libusb and not pyusb) once Chris or others have time to look into this.

@mcuee
Copy link
Member

mcuee commented Aug 1, 2018

Not so sure if this is related.
pyusb/pyusb#186

@mcuee
Copy link
Member

mcuee commented Aug 1, 2018

Same as issue here in pyusb.
pyusb/pyusb#203

@mcuee
Copy link
Member

mcuee commented Aug 1, 2018

Temporary workaround is to go back to libusb-1.0.21.

@dickens
Copy link
Member

dickens commented Aug 3, 2018

_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CBE0>)
[ 0.673023] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C759548670 [2] (3.1)
[ 0.675556] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CCC0>)
[ 0.682100] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C7594D0830 [4] (3.0)
[ 0.684642] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CBE0>)
[ 0.689348] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C759548670 [1] (3.1)
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CC50>)
[ 0.692994] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C7594709A0 [2] (3.3)
[ 0.695454] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CCC0>)
[ 0.700620] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C7594D0830 [3] (3.0)
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CDD8>)
[ 0.706609] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C7595492B0 [2] (2.2)
[ 0.708977] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CC50>)
[ 0.715358] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C7594709A0 [1] (3.3)
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CBE0>)
[ 0.720169] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C7594D0E50 [3] (2.0)
[ 0.722662] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CDD8>)
[ 0.728500] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C7595492B0 [1] (2.2)
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CCC0>)
[ 0.733579] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C75946C990 [3] (2.1)
[ 0.736316] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CBE0>)
[ 0.742019] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C7594D0E50 [2] (2.0)
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CC50>)
[ 0.746880] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C759548050 [3] (1.0)
[ 0.749325] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CCC0>)
[ 0.755046] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C75946C990 [2] (2.1)
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CDD8>)
[ 0.759850] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C7594D0210 [4] (3.2)
[ 0.762281] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CC50>)
[ 0.768653] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C759548050 [2] (1.0)
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CBE0>)
[ 0.773529] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C7595498D0 [2] (3.4)
[ 0.776019] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CDD8>)
[ 0.782545] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C7594D0210 [3] (3.2)
_Device initializer (<usb.backend.libusb1._Device object at 0x000001C75970CCC0>)
[ 0.787474] [00004e20] libusb: debug [libusb_ref_device] ref device 000001C759548C90 [2] (1.1)
[ 0.789987] [00004e20] libusb: debug [libusb_get_device_descriptor]
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CBE0>)
[ 0.795905] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C7595498D0 [1] (3.4)
_LibUSB finalizer (<usb.backend.libusb1._LibUSB object at 0x000001C75970CB70>)
[ 0.801349] [00004e20] libusb: debug [libusb_exit]
[ 0.803800] [00004e20] libusb: debug [libusb_exit] destroying default context
[ 0.806145] [00004e20] libusb: warning [libusb_exit] some libusb_devices were leaked
[ 0.809560] [00004e20] libusb: debug [usbi_remove_pollfd] remove fd 0
[ 0.813402] [000046c8] libusb: debug [windows_clock_gettime_threaded] timer thread quitting
_Device finalizer (<usb.backend.libusb1._Device object at 0x000001C75970CCC0>)
[ 0.817313] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C759548C90 [1] (1.1)
[ 0.819770] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C759548670 [0] (3.1)
[ 0.823254] [00004e20] libusb: debug [libusb_unref_device] destroy device 3.1 (parent 000001C7594D0830)
[ 0.825610] [00004e20] libusb: debug [libusb_unref_device] unref device 000001C7594D0830 [2] (3.0)
Exception ignored in: <bound method _AutoFinalizedObjectBase.__del__ of <usb.backend.libusb1._DevIterator object at 0x000001C75970CBA8>>
Traceback (most recent call last):
  File "C:\Users\dickensc\AppData\Local\Programs\Python\Python36\lib\site-packages\usb\_objfinalizer.py", line 84, in __del__
    self.finalize()
  File "C:\Users\dickensc\AppData\Local\Programs\Python\Python36\lib\site-packages\usb\_objfinalizer.py", line 144, in finalize
    self._finalizer()
  File "C:\Users\dickensc\AppData\Local\Programs\Python\Python36\lib\weakref.py", line 548, in __call__
    return info.func(*info.args, **(info.kwargs or {}))
  File "C:\Users\dickensc\AppData\Local\Programs\Python\Python36\lib\site-packages\usb\_objfinalizer.py", line 104, in _do_finalize_object_ref
    obj._do_finalize_object()
  File "C:\Users\dickensc\AppData\Local\Programs\Python\Python36\lib\site-packages\usb\_objfinalizer.py", line 71, in _do_finalize_object
    self._finalize_object()
  File "C:\Users\dickensc\AppData\Local\Programs\Python\Python36\lib\site-packages\usb\backend\libusb1.py", line 641, in _finalize_object
    _lib.libusb_free_device_list(self.dev_list, 1)
OSError: exception: access violation reading 0xFFFFFFFFFFFFFFFF
DEVICE ID 0424:5434 on Bus 003 Address 001, Hub
DEVICE ID 8086:8c31 on Bus 003 Address 000, Hub
DEVICE ID 0e53:2516 on Bus 003 Address 003, Specified at interface
DEVICE ID 8087:07da on Bus 002 Address 002, Wireless Controller
DEVICE ID 8086:8c2d on Bus 002 Address 000, Hub
DEVICE ID 8087:8008 on Bus 002 Address 001, Hub
DEVICE ID 8086:8c26 on Bus 001 Address 000, Hub
DEVICE ID 0424:5434 on Bus 003 Address 002, Hub
DEVICE ID 047f:ac11 on Bus 003 Address 004, Specified at interface
DEVICE ID 8087:8000 on Bus 001 Address 001, Hub

The refcounting mechanism in pyusb is broken. The above log shows debug messages added within the ref/unref functions of libusb and the init/_finalize_object methods of pyusb. You can see that the _LibUSB backend object was finalized before all of the _Device objects were finalized. The warning from libusb during libusb_exit() even says "some libusb_devices were leaked". Applications are not allowed to reference a device after its context has been destroyed.

Closing this since this is not a libusb issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

5 participants