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

CI: [TEST ONLY] Run macOS with debug level 3 to investigate stress_mt failure #1358

Draft
wants to merge 4 commits into
base: master
Choose a base branch
from

Conversation

tormodvolden
Copy link
Contributor

As a good heisenbug the stress_mt failure will likely not happen now...

@tormodvolden
Copy link
Contributor Author

I have been trying to reproduce the stress_mt failure locally on an Intel MBP but to no avail.

@tormodvolden
Copy link
Contributor Author

tormodvolden commented Dec 3, 2023

2023-12-03T11:40:08.9953880Z Running test 'stress_mt' ...
2023-12-03T11:40:10.8181050Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8189000Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8190040Z Running multithreaded init/exit test...
2023-12-03T11:40:10.8219540Z libusb: error [submit_control_transfer] control request failed: unknown error (0xe00002c7)
2023-12-03T11:40:10.8247180Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8247980Z Starting 8 threads
2023-12-03T11:40:10.8248930Z Running multithreaded init/exit test with enumeration...
2023-12-03T11:40:10.8275380Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8276560Z Starting 8 threads
2023-12-03T11:40:10.8279130Z libusb: error [submit_control_transfer] control request failed: unknown error (0xe00002c7)
2023-12-03T11:40:10.8280330Z All threads discovered 0 devices (0 not opened)
2023-12-03T11:40:10.8283000Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8284160Z All done, 8 errors
2023-12-03T11:40:10.8287220Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8293800Z libusb: error [submit_control_transfer] control request failed: unknown error (0xe00002c7)
2023-12-03T11:40:10.8304110Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8306380Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8408320Z libusb: error [submit_control_transfer] control request failed: unknown error (0xe00002c7)
2023-12-03T11:40:10.8508390Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8543420Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8646100Z libusb: error [submit_control_transfer] control request failed: unknown error (0xe00002c7)
2023-12-03T11:40:10.8729310Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8731040Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8732970Z libusb: error [submit_control_transfer] control request failed: unknown error (0xe00002c7)
2023-12-03T11:40:10.8736210Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8738170Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.8782600Z libusb: error [submit_control_transfer] control request failed: unknown error (0xe00002c7)
2023-12-03T11:40:10.8883840Z Thread 0 failed (iteration 1): LIBUSB_ERROR_OTHER
2023-12-03T11:40:10.8985050Z Thread 1 failed (iteration 1): LIBUSB_ERROR_OTHER
2023-12-03T11:40:10.9086100Z Thread 2 failed (iteration 1): LIBUSB_ERROR_OTHER
2023-12-03T11:40:10.9106850Z Thread 3 failed (iteration 1): LIBUSB_ERROR_OTHER
2023-12-03T11:40:10.9109600Z Thread 4 failed (iteration 1): LIBUSB_ERROR_OTHER
2023-12-03T11:40:10.9111810Z Thread 5 failed (iteration 1): LIBUSB_ERROR_OTHER
2023-12-03T11:40:10.9113130Z Thread 6 failed (iteration 1): LIBUSB_ERROR_OTHER
2023-12-03T11:40:10.9135820Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.9145440Z libusb: warning [darwin_open] USBDeviceOpen: another process has device opened for exclusive access
2023-12-03T11:40:10.9147370Z libusb: error [submit_control_transfer] control request failed: unknown error (0xe00002c7)
2023-12-03T11:40:10.9148950Z Thread 7 failed (iteration 1): LIBUSB_ERROR_OTHER
2023-12-03T11:40:10.9172960Z ##[error]Process completed with exit code 1.

@tormodvolden
Copy link
Contributor Author

@hjelmn Any idea why we see this intermittently on the macOS CI host?

As a good heisenbug the stress_mt failure will likely not happen now...
@RReverser
Copy link
Contributor

Hm so looking at those "another process has device opened for exclusive access", does that mean that on macOS it's not possible to libusb_open same device multiple times?

Is this a bug in the backend or a general limitation of the OS?

@RReverser
Copy link
Contributor

If it's the latter, one thing that could be done is to use reference counting in the backend's device wrapper.

But first would be good to understand where this limitation lies and why you can't reproduce it locally. Maybe different OS versions? Or simply different system load, e.g. worth trying to increase number of threads as well as iterations locally to see if it reproduces under heavier contention.

@RReverser
Copy link
Contributor

I'll probably leave further investigation to macOS backend maintainers. But this looks like exactly the kind of issues with concurrent transfers I was hoping the updated test would help reveal, as it did for me in the WebUSB backend as well.

@mcuee
Copy link
Member

mcuee commented Dec 3, 2023

The latest run's failure is a bit strange.
https://github.com/libusb/libusb/actions/runs/7076700249/job/19260244014

2023-12-03T12:08:59.4989370Z [ 2.528845] [0000bda6] libusb: debug [libusb_close]  
2023-12-03T12:08:59.4989600Z [ 2.528880] [0000bda6] libusb: debug [libusb_exit]  
2023-12-03T12:08:59.4990020Z [ 2.528884] [0000bda6] libusb: debug [libusb_unref_device] destroy device 7.5
2023-12-03T12:08:59.4990590Z [ 2.528887] [0000bda6] libusb: debug [libusb_unref_device] destroy device 7.4
2023-12-03T12:08:59.4991000Z [ 2.528889] [0000bda6] libusb: debug [libusb_unref_device] destroy device 7.3
2023-12-03T12:08:59.4991400Z [ 2.528891] [0000bda6] libusb: debug [libusb_unref_device] destroy device 7.2
2023-12-03T12:08:59.4991890Z [ 2.528894] [0000bda6] libusb: debug [libusb_unref_device] destroy device 7.1
2023-12-03T12:08:59.4992560Z [ 2.528926] [0000bda9] libusb: debug [darwin_event_thread_main] darwin event thread exiting
2023-12-03T12:08:59.4992950Z [ 2.529676] [0000bda6] libusb: debug [usbi_remove_event_source] remove fd 4
2023-12-03T12:08:59.4993150Z Running multithreaded init/exit test...
2023-12-03T12:08:59.4993280Z Starting 8 threads
2023-12-03T12:08:59.4993590Z Running multithreaded init/exit test with enumeration...
2023-12-03T12:08:59.4993730Z Starting 8 threads
2023-12-03T12:08:59.4994100Z Device count mismatch: Thread 1 discovered 5 devices instead of 0
2023-12-03T12:08:59.4994240Z All done, 2 errors
2023-12-03T12:08:59.5010620Z ##[error]Process completed with exit code 1.

@mcuee
Copy link
Member

mcuee commented Dec 3, 2023

No issues here with git HEAD on my Mac Mini M1 running macOS 14.1.

mcuee@mcuees-Mac-mini libusb % ./examples/testlibusb
Dev (bus 2, device 24): 1915 - 1025 speed: 12M
  Manufacturer:              ZY.Ltd
  Product:                   ZY Control Mic
Dev (bus 2, device 23): 046D - C52B speed: 12M
  Manufacturer:              Logitech
  Product:                   USB Receiver
Dev (bus 2, device 22): 1A40 - 0201 speed: 12M
  Product:                   USB 2.0 Hub [MTT]
Dev (bus 2, device 21): 1A40 - 0201 speed: 12M
  Product:                   USB 2.0 Hub [MTT]
Dev (bus 2, device 20): 0BDA - 5411 speed: 12M
  Manufacturer:              Generic
  Product:                   4-Port USB 2.0 Hub
Dev (bus 2, device 19): 0BDA - 5411 speed: 12M
  Manufacturer:              Generic
  Product:                   4-Port USB 2.0 Hub
Dev (bus 2, device 15): 05E3 - 0749 speed: 5G
  Manufacturer:              Generic
  Product:                   USB3.0 Card Reader
Dev (bus 2, device 12): 0BDA - 0411 speed: 5G
  Manufacturer:              Generic
  Product:                   4-Port USB 3.0 Hub
Dev (bus 2, device 11): 0BDA - 0411 speed: 5G
  Manufacturer:              Generic
  Product:                   4-Port USB 3.0 Hub

mcuee@mcuees-Mac-mini libusb % ./examples/listdevs  
1915:1025 (bus 2, device 24) path: 2.4.5.6
046d:c52b (bus 2, device 23) path: 2.4.6
1a40:0201 (bus 2, device 22) path: 2.4.5
1a40:0201 (bus 2, device 21) path: 2.4
0bda:5411 (bus 2, device 20) path: 2.1
0bda:5411 (bus 2, device 19) path: 2
05e3:0749 (bus 2, device 15) path: 6.1.1
0bda:0411 (bus 2, device 12) path: 6.1
0bda:0411 (bus 2, device 11) path: 6

mcuee@mcuees-Mac-mini libusb % ./tests/stress
Starting test run: init_and_exit...
Success (0)
Starting test run: get_device_list...
Success (0)
Starting test run: many_device_lists...
Success (0)
Starting test run: default_context_change...
Success (0)
---
Ran 4 tests
Passed 4 tests
Failed 0 tests
Error in 0 tests
Skipped 0 tests

mcuee@mcuees-Mac-mini libusb % ./tests/stress_mt  
Running multithreaded init/exit test...
Starting 8 threads
Running multithreaded init/exit test with enumeration...
Starting 8 threads
All threads discovered 9 devices (0 not opened)
All done, 0 errors

@tormodvolden
Copy link
Contributor Author

tormodvolden commented Dec 3, 2023

Yes, the last run (with debug level 4) is different. There are some failing opens, but also the thread "0" didn't find any devices.

Naturally the full debug log is enormous (15 MB), I copy in just the first lines of the stress_mt part here with the 5 devices detected.

Five devices detected
2023-12-03T12:08:49.3755770Z Running test 'stress_mt' ...
2023-12-03T12:08:49.4708380Z [timestamp] [threadID] facility level [function call] <message>
2023-12-03T12:08:49.4709430Z --------------------------------------------------------------------------------
2023-12-03T12:08:49.4710470Z [ 0.000204] [0000bc47] libusb: debug [libusb_init_context] libusb v1.0.26.11835
2023-12-03T12:08:49.4711520Z [ 0.000245] [0000bc47] libusb: debug [usbi_add_event_source] add fd 4 events 1
2023-12-03T12:08:49.4713200Z [ 0.000359] [0000bc4f] libusb: debug [darwin_event_thread_main] creating hotplug event source
2023-12-03T12:08:49.4714580Z [ 0.000844] [0000bc4f] libusb: debug [darwin_event_thread_main] darwin event thread ready to receive events
2023-12-03T12:08:49.4716470Z [ 0.001080] [0000bc47] libusb: debug [darwin_get_cached_device] could not get connected port number
2023-12-03T12:08:49.4717850Z [ 0.001096] [0000bc47] libusb: debug [darwin_get_cached_device] finding cached device for sessionID 0x0
2023-12-03T12:08:49.4719220Z [ 0.001118] [0000bc47] libusb: debug [darwin_get_cached_device] caching new device with sessionID 0x0
2023-12-03T12:08:49.4751000Z [ 0.004398] [0000bc47] libusb: debug [darwin_cache_device_descriptor] cached device descriptor:
2023-12-03T12:08:49.4752320Z [ 0.004417] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDescriptorType:    0x01
2023-12-03T12:08:49.4753610Z [ 0.004421] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdUSB:             0x0100
2023-12-03T12:08:49.4754890Z [ 0.004424] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceClass:       0x09
2023-12-03T12:08:49.4756160Z [ 0.004426] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceSubClass:    0xff
2023-12-03T12:08:49.4757440Z [ 0.004428] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceProtocol:    0x03
2023-12-03T12:08:49.4758710Z [ 0.004431] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bMaxPacketSize0:    0x08
2023-12-03T12:08:49.4759980Z [ 0.004433] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idVendor:           0x05ac
2023-12-03T12:08:49.4762040Z [ 0.004435] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idProduct:          0x8007
2023-12-03T12:08:49.4763330Z [ 0.004437] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdDevice:          0x0198
2023-12-03T12:08:49.4764610Z [ 0.004439] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iManufacturer:      0x00
2023-12-03T12:08:49.4765870Z [ 0.004441] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iProduct:           0x00
2023-12-03T12:08:49.4767130Z [ 0.004444] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iSerialNumber:      0x00
2023-12-03T12:08:49.4768400Z [ 0.004446] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bNumConfigurations: 0x01
2023-12-03T12:08:49.4769780Z [ 0.004556] [0000bc47] libusb: debug [darwin_get_cached_device] finding cached device for sessionID 0x506615a4
2023-12-03T12:08:49.4771800Z [ 0.004587] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x506615a4/0x7900000 against cached device with sessionID/locationID 0x0/0x7000000
2023-12-03T12:08:49.4773800Z [ 0.004590] [0000bc47] libusb: debug [darwin_get_cached_device] caching new device with sessionID 0x506615a4
2023-12-03T12:08:49.4775440Z [ 0.005999] [0000bc47] libusb: debug [darwin_cache_device_descriptor] cached device descriptor:
2023-12-03T12:08:49.4776970Z [ 0.006014] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDescriptorType:    0x01
2023-12-03T12:08:49.4778500Z [ 0.006019] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdUSB:             0x0200
2023-12-03T12:08:49.4780040Z [ 0.006021] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceClass:       0x00
2023-12-03T12:08:49.4781510Z [ 0.006023] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceSubClass:    0x00
2023-12-03T12:08:49.4783020Z [ 0.006025] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceProtocol:    0x00
2023-12-03T12:08:49.4784450Z [ 0.006027] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bMaxPacketSize0:    0x40
2023-12-03T12:08:49.4785880Z [ 0.006029] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idVendor:           0x1d9e
2023-12-03T12:08:49.4787850Z [ 0.006060] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idProduct:          0x0003
2023-12-03T12:08:49.4790060Z [ 0.006068] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdDevice:          0x0100
2023-12-03T12:08:49.4791570Z [ 0.006071] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iManufacturer:      0x01
2023-12-03T12:08:49.4793060Z [ 0.006074] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iProduct:           0x02
2023-12-03T12:08:49.4794500Z [ 0.006076] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iSerialNumber:      0x03
2023-12-03T12:08:49.4796120Z [ 0.006078] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bNumConfigurations: 0x01
2023-12-03T12:08:49.4797700Z [ 0.006103] [0000bc47] libusb: debug [darwin_check_configuration] active config: 1, first config: 1
2023-12-03T12:08:49.4799420Z [ 0.006107] [0000bc47] libusb: debug [process_new_device] allocating new device in context 0x617000000080 for with session 0x506615a4
2023-12-03T12:08:49.4801350Z [ 0.006112] [0000bc47] libusb: debug [process_new_device] found device with address 1 port = 9 parent = 0x0 at 0x60c000011efa
2023-12-03T12:08:49.4803100Z [ 0.006261] [0000bc47] libusb: debug [darwin_get_cached_device] finding cached device for sessionID 0x53eb1193
2023-12-03T12:08:49.4805320Z [ 0.006302] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x53eb1193/0x7c00000 against cached device with sessionID/locationID 0x506615a4/0x7900000
2023-12-03T12:08:49.4819650Z [ 0.006307] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x53eb1193/0x7c00000 against cached device with sessionID/locationID 0x0/0x7000000
2023-12-03T12:08:49.4822870Z [ 0.006310] [0000bc47] libusb: debug [darwin_get_cached_device] caching new device with sessionID 0x53eb1193
2023-12-03T12:08:49.4824240Z [ 0.006785] [0000bc47] libusb: debug [darwin_cache_device_descriptor] cached device descriptor:
2023-12-03T12:08:49.4825520Z [ 0.006800] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDescriptorType:    0x01
2023-12-03T12:08:49.4826810Z [ 0.006804] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdUSB:             0x0200
2023-12-03T12:08:49.4828080Z [ 0.006806] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceClass:       0x00
2023-12-03T12:08:49.4829350Z [ 0.006808] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceSubClass:    0x00
2023-12-03T12:08:49.4830630Z [ 0.006810] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceProtocol:    0x00
2023-12-03T12:08:49.4831900Z [ 0.006812] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bMaxPacketSize0:    0x40
2023-12-03T12:08:49.4833400Z [ 0.006814] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idVendor:           0x1d9e
2023-12-03T12:08:49.4834700Z [ 0.006816] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idProduct:          0x0006
2023-12-03T12:08:49.4835970Z [ 0.006818] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdDevice:          0x0100
2023-12-03T12:08:49.4837240Z [ 0.006820] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iManufacturer:      0x00
2023-12-03T12:08:49.4838500Z [ 0.006822] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iProduct:           0x00
2023-12-03T12:08:49.4839770Z [ 0.006824] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iSerialNumber:      0x00
2023-12-03T12:08:49.4841040Z [ 0.006826] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bNumConfigurations: 0x01
2023-12-03T12:08:49.4842340Z [ 0.006844] [0000bc47] libusb: debug [darwin_check_configuration] active config: 1, first config: 1
2023-12-03T12:08:49.4843920Z [ 0.006855] [0000bc47] libusb: debug [process_new_device] allocating new device in context 0x617000000080 for with session 0x53eb1193
2023-12-03T12:08:49.4845710Z [ 0.006860] [0000bc47] libusb: debug [process_new_device] found device with address 2 port = 12 parent = 0x0 at 0x60c00001207a
2023-12-03T12:08:49.4847410Z [ 0.007010] [0000bc47] libusb: debug [darwin_get_cached_device] finding cached device for sessionID 0x57aa2b9e
2023-12-03T12:08:49.4850130Z [ 0.007074] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x57aa2b9e/0x7d00000 against cached device with sessionID/locationID 0x53eb1193/0x7c00000
2023-12-03T12:08:49.4852840Z [ 0.007080] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x57aa2b9e/0x7d00000 against cached device with sessionID/locationID 0x506615a4/0x7900000
2023-12-03T12:08:49.4855430Z [ 0.007083] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x57aa2b9e/0x7d00000 against cached device with sessionID/locationID 0x0/0x7000000
2023-12-03T12:08:49.4857430Z [ 0.007086] [0000bc47] libusb: debug [darwin_get_cached_device] caching new device with sessionID 0x57aa2b9e
2023-12-03T12:08:49.4858790Z [ 0.007628] [0000bc47] libusb: debug [darwin_cache_device_descriptor] cached device descriptor:
2023-12-03T12:08:49.4860060Z [ 0.007634] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDescriptorType:    0x01
2023-12-03T12:08:49.4861350Z [ 0.007636] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdUSB:             0x0200
2023-12-03T12:08:49.4862620Z [ 0.007638] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceClass:       0x00
2023-12-03T12:08:49.4863890Z [ 0.007640] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceSubClass:    0x00
2023-12-03T12:08:49.4865160Z [ 0.007643] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceProtocol:    0x00
2023-12-03T12:08:49.4866440Z [ 0.007645] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bMaxPacketSize0:    0x40
2023-12-03T12:08:49.4868110Z [ 0.007647] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idVendor:           0x1d9e
2023-12-03T12:08:49.4869380Z [ 0.007650] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idProduct:          0x0007
2023-12-03T12:08:49.4870660Z [ 0.007653] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdDevice:          0x0100
2023-12-03T12:08:49.4871930Z [ 0.007655] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iManufacturer:      0x00
2023-12-03T12:08:49.4873200Z [ 0.007657] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iProduct:           0x00
2023-12-03T12:08:49.4874440Z [ 0.007659] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iSerialNumber:      0x00
2023-12-03T12:08:49.4875720Z [ 0.007661] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bNumConfigurations: 0x01
2023-12-03T12:08:49.4877020Z [ 0.007680] [0000bc47] libusb: debug [darwin_check_configuration] active config: 1, first config: 1
2023-12-03T12:08:49.4878600Z [ 0.007692] [0000bc47] libusb: debug [process_new_device] allocating new device in context 0x617000000080 for with session 0x57aa2b9e
2023-12-03T12:08:49.4880380Z [ 0.007698] [0000bc47] libusb: debug [process_new_device] found device with address 3 port = 13 parent = 0x0 at 0x60c0000121fa
2023-12-03T12:08:49.4881990Z [ 0.007825] [0000bc47] libusb: debug [darwin_get_cached_device] finding cached device for sessionID 0x5b6416f8
2023-12-03T12:08:49.4884070Z [ 0.007866] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5b6416f8/0x7a00000 against cached device with sessionID/locationID 0x57aa2b9e/0x7d00000
2023-12-03T12:08:49.4886710Z [ 0.007871] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5b6416f8/0x7a00000 against cached device with sessionID/locationID 0x53eb1193/0x7c00000
2023-12-03T12:08:49.4889330Z [ 0.007874] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5b6416f8/0x7a00000 against cached device with sessionID/locationID 0x506615a4/0x7900000
2023-12-03T12:08:49.4891930Z [ 0.007877] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5b6416f8/0x7a00000 against cached device with sessionID/locationID 0x0/0x7000000
2023-12-03T12:08:49.4893920Z [ 0.007880] [0000bc47] libusb: debug [darwin_get_cached_device] caching new device with sessionID 0x5b6416f8
2023-12-03T12:08:49.4895650Z [ 0.008316] [0000bc47] libusb: debug [darwin_cache_device_descriptor] cached device descriptor:
2023-12-03T12:08:49.4896960Z [ 0.008322] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDescriptorType:    0x01
2023-12-03T12:08:49.4898240Z [ 0.008325] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdUSB:             0x0200
2023-12-03T12:08:49.4899520Z [ 0.008327] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceClass:       0x00
2023-12-03T12:08:49.4900780Z [ 0.008329] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceSubClass:    0x00
2023-12-03T12:08:49.4902070Z [ 0.008331] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceProtocol:    0x00
2023-12-03T12:08:49.4903330Z [ 0.008333] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bMaxPacketSize0:    0x40
2023-12-03T12:08:49.4904610Z [ 0.008335] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idVendor:           0x1d9e
2023-12-03T12:08:49.4905890Z [ 0.008337] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idProduct:          0x0004
2023-12-03T12:08:49.4907170Z [ 0.008339] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdDevice:          0x0100
2023-12-03T12:08:49.4908520Z [ 0.008341] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iManufacturer:      0x00
2023-12-03T12:08:49.4909790Z [ 0.008343] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iProduct:           0x00
2023-12-03T12:08:49.4911040Z [ 0.008345] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iSerialNumber:      0x00
2023-12-03T12:08:49.4912570Z [ 0.008347] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bNumConfigurations: 0x01
2023-12-03T12:08:49.4913870Z [ 0.008362] [0000bc47] libusb: debug [darwin_check_configuration] active config: 1, first config: 1
2023-12-03T12:08:49.4915460Z [ 0.008365] [0000bc47] libusb: debug [process_new_device] allocating new device in context 0x617000000080 for with session 0x5b6416f8
2023-12-03T12:08:49.4917240Z [ 0.008369] [0000bc47] libusb: debug [process_new_device] found device with address 4 port = 10 parent = 0x0 at 0x60c00001237a
2023-12-03T12:08:49.4918840Z [ 0.008506] [0000bc47] libusb: debug [darwin_get_cached_device] finding cached device for sessionID 0x5f53f69e
2023-12-03T12:08:49.4920920Z [ 0.008566] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5f53f69e/0x7b00000 against cached device with sessionID/locationID 0x5b6416f8/0x7a00000
2023-12-03T12:08:49.4923560Z [ 0.008580] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5f53f69e/0x7b00000 against cached device with sessionID/locationID 0x57aa2b9e/0x7d00000
2023-12-03T12:08:49.4926210Z [ 0.008584] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5f53f69e/0x7b00000 against cached device with sessionID/locationID 0x53eb1193/0x7c00000
2023-12-03T12:08:49.4928850Z [ 0.008587] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5f53f69e/0x7b00000 against cached device with sessionID/locationID 0x506615a4/0x7900000
2023-12-03T12:08:49.4931440Z [ 0.008589] [0000bc47] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0x5f53f69e/0x7b00000 against cached device with sessionID/locationID 0x0/0x7000000
2023-12-03T12:08:49.4933430Z [ 0.008592] [0000bc47] libusb: debug [darwin_get_cached_device] caching new device with sessionID 0x5f53f69e
2023-12-03T12:08:49.4934790Z [ 0.009018] [0000bc47] libusb: debug [darwin_cache_device_descriptor] cached device descriptor:
2023-12-03T12:08:49.4936070Z [ 0.009033] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDescriptorType:    0x01
2023-12-03T12:08:49.4937340Z [ 0.009036] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdUSB:             0x0200
2023-12-03T12:08:49.4938610Z [ 0.009039] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceClass:       0x00
2023-12-03T12:08:49.4940220Z [ 0.009041] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceSubClass:    0x00
2023-12-03T12:08:49.4941540Z [ 0.009043] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bDeviceProtocol:    0x00
2023-12-03T12:08:49.4942800Z [ 0.009045] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bMaxPacketSize0:    0x40
2023-12-03T12:08:49.4944160Z [ 0.009047] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idVendor:           0x1d9e
2023-12-03T12:08:49.4945440Z [ 0.009049] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   idProduct:          0x0005
2023-12-03T12:08:49.4946710Z [ 0.009051] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bcdDevice:          0x0100
2023-12-03T12:08:49.4947990Z [ 0.009053] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iManufacturer:      0x00
2023-12-03T12:08:49.4949250Z [ 0.009055] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iProduct:           0x00
2023-12-03T12:08:49.4950510Z [ 0.009057] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   iSerialNumber:      0x00
2023-12-03T12:08:49.4951780Z [ 0.009060] [0000bc47] libusb: debug [darwin_cache_device_descriptor]   bNumConfigurations: 0x01
2023-12-03T12:08:49.4953080Z [ 0.009077] [0000bc47] libusb: debug [darwin_check_configuration] active config: 1, first config: 1
2023-12-03T12:08:49.4954660Z [ 0.009090] [0000bc47] libusb: debug [process_new_device] allocating new device in context 0x617000000080 for with session 0x5f53f69e
2023-12-03T12:08:49.4956430Z [ 0.009096] [0000bc47] libusb: debug [process_new_device] found device with address 5 port = 11 parent = 0x0 at 0x60c0000124fa
2023-12-03T12:08:49.4958370Z [ 0.009106] [0000bc47] libusb: debug [libusb_init_context] installing new context as implicit default
2023-12-03T12:08:49.4959390Z [ 0.009126] [0000bc47] libusb: debug [libusb_exit]  
2023-12-03T12:08:49.4960210Z [ 0.009131] [0000bc47] libusb: debug [libusb_unref_device] destroy device 7.5
2023-12-03T12:08:49.4961360Z [ 0.009139] [0000bc47] libusb: debug [libusb_unref_device] destroy device 7.4
2023-12-03T12:08:49.4962370Z [ 0.009141] [0000bc47] libusb: debug [libusb_unref_device] destroy device 7.3
2023-12-03T12:08:49.4963390Z [ 0.009144] [0000bc47] libusb: debug [libusb_unref_device] destroy device 7.2
2023-12-03T12:08:49.4964400Z [ 0.009146] [0000bc47] libusb: debug [libusb_unref_device] destroy device 7.1
2023-12-03T12:08:49.4965510Z [ 0.009197] [0000bc4f] libusb: debug [darwin_event_thread_main] darwin event thread exiting
2023-12-03T12:08:49.4966620Z [ 0.010092] [0000bc47] libusb: debug [usbi_remove_event_source] remove fd 4
2023-12-03T12:08:49.4967970Z [ 0.010113] [0000bc47] libusb: debug [libusb_init_context] libusb v1.0.26.11835

And here is the single "error" level message:

2023-12-03T12:08:54.5022160Z [ 1.855461] [0000bda4] libusb: debug [process_new_device] found device with address 5 port = 11 parent = 0x0 at 0x60c0000f9bba
2023-12-03T12:08:54.5022450Z [ 1.855488] [0000bda4] libusb: debug [libusb_get_device_list]
2023-12-03T12:08:54.5023080Z [ 1.855507] [0000bda1] libusb: error [darwin_open] CreateDeviceAsyncEventSource: unknown error (0xe00002bd)
2023-12-03T12:08:54.5023440Z [ 1.855523] [0000bda2] libusb: debug [darwin_open] device open for access
2023-12-03T12:08:54.5024020Z [ 1.855528] [0000bda2] libusb: debug [libusb_submit_transfer] transfer 0x612000010490
2023-12-03T12:08:54.5024570Z [ 1.855404] [0000bda9] libusb: debug [darwin_async_io_callback] an async io operation has completed
2023-12-03T12:08:54.5025240Z [ 1.855531] [0000bda1] libusb: debug [libusb_open] open 7.2 returns -99
2023-12-03T12:08:54.5025450Z [ 1.855543] [0000bda1] libusb: debug [libusb_exit]

@tormodvolden
Copy link
Contributor Author

The CI is running macOS 12.7.1. I have been trying to reproduce on 13.6.

Unless we have reason to believe this is a recent regression, I don't think we should block 1.0.27 on this issue. Especially if no one has seen it before or is able to reproduce it outside the CI.

@tormodvolden
Copy link
Contributor Author

The CI run on macOS 13.6 succeeded both with debug level 3 and 4.

@tormodvolden
Copy link
Contributor Author

Does anyone around have macOS 12 so that they can try to reproduce the failure on it?

@mcuee mcuee added macOS build_ci Build system, CI labels Dec 5, 2023
@mcuee
Copy link
Member

mcuee commented Dec 5, 2023

Does anyone around have macOS 12 so that they can try to reproduce the failure on it?

I sent an email to libusb-devel mailing to seek help from the community just now.

@sl1200mk2
Copy link

sl1200mk2 commented Dec 5, 2023

Hi,
I've compiled latest available code and run the stress_mt on a macOS 12.7.1 Intel and here's the results:

nico@love libusb-master % make  CFLAGS="-Og -DLIBUSB_DEBUG=3"

/Applications/Xcode.app/Contents/Developer/usr/bin/make  all-recursive
Making all in libusb
  CC       core.lo
  CC       descriptor.lo
  CC       hotplug.lo
  CC       io.lo
  CC       strerror.lo
  CC       sync.lo
  CC       os/events_posix.lo
  CC       os/threads_posix.lo
  CC       os/darwin_usb.lo
  CCLD     libusb-1.0.la
make[2]: Nothing to be done for `all-am'.
nico@love libusb-master % cd tests 
nico@love tests % make  CFLAGS="-Og -DLIBUSB_DEBUG=3"

  CC       stress.o
  CC       testlib.o
  CCLD     stress
  CC       stress_mt-stress_mt.o
  CCLD     stress_mt
  CC       set_option.o
  CCLD     set_option
  CC       init_context.o
  CCLD     init_context
nico@love tests % /Users/nico/daylight/lib/libusb-master/tests/stress_mt 
Running multithreaded init/exit test...
Starting 8 threads
Running multithreaded init/exit test with enumeration...
Starting 8 threads
All threads discovered 1 devices (0 not opened)
All done, 0 errors

@mcuee
Copy link
Member

mcuee commented Dec 5, 2023

Hi, I've compiled latest available code and run the stress_mt on a macOS 12.7.1 Intel and here's the results:

@sl1200mk2
Thanks for the help.
Is it possible for you to connect a few USB devices and then carry out the test again? Thanks.

@sl1200mk2
Copy link

sl1200mk2 commented Dec 5, 2023

nico@love tests % /Users/nico/daylight/lib/libusb-master/tests/stress_mt       
Running multithreaded init/exit test...
Starting 8 threads
Running multithreaded init/exit test with enumeration...
Starting 8 threads
All threads discovered 5 devices (0 not opened)
All done, 0 errors

@mcuee
Copy link
Member

mcuee commented Dec 5, 2023

@sl1200mk2
Thanks a lot for the help.

@tormodvolden
It seems to be specifi to the CI machine, maybe the problem is with the virtual USB devices it exposed. I think we can keep this issue open but no beed to block 1.0.27 release.

@tormodvolden
Copy link
Contributor Author

We might wanna bump the CI to macOS 13 (although considered beta there) so it doesn't distract us so much.

@hjelmn
Copy link
Member

hjelmn commented Dec 5, 2023

I can see if I can reproduce inside a VM and see if that makes a difference. I keep an Intel machine around for this reason. Will take a bit to get it back up and running. I can also try to reproduce in a VM in an M3 machine.

@tormodvolden tormodvolden added the DNM! DO NOT MERGE! label Dec 9, 2023
@tormodvolden
Copy link
Contributor Author

Tried to reproduce on 11.6.1 but no error.

@tormodvolden
Copy link
Contributor Author

The latest CI run timed out after 6 hours:

Mon, 11 Dec 2023 22:30:09 GMT /Applications/Xcode_14.2.app/Contents/Developer/usr/bin/make  check-TESTS
Mon, 11 Dec 2023 22:31:46 GMT PASS: stress
Tue, 12 Dec 2023 04:28:42 GMT Error: The operation was canceled.

Was it just very slow, or is an infinite loop possible?

@tormodvolden
Copy link
Contributor Author

Was it just very slow, or is an infinite loop possible?

Possibly unrelated but there is also reports of deadlock on Windows in #1376 (comment)

@seanm
Copy link
Contributor

seanm commented Jan 2, 2024

Does anyone around have macOS 12 so that they can try to reproduce the failure on it?

FYI At my work I have a build bot for every Mac OS from 10.10 onwards.

Maybe this is due to a threading bug. Could be related to:

@tormodvolden tormodvolden marked this pull request as draft February 1, 2024 11:49
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
build_ci Build system, CI DNM! DO NOT MERGE! macOS
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

6 participants