[Linux][LibUsbDotNet] Process shutdown without throwing any exceptions (libusb_exit)

[smdn]

LibUsbDotNet problem?

repro code

using System;

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Console;

using Smdn.Devices.MCP2221;

var services = new ServiceCollection();

services.AddLogging(
  builder => builder
    .AddSimpleConsole(static options => options.SingleLine = true)
    .AddFilter(static level => LogLevel.Trace <= level)
);

Smdn.Devices.UsbHid.Log.NativeLibraryLogLevel = LogLevel.Trace;

await using var device = await MCP2221.OpenAsync(services.BuildServiceProvider());

var address = new I2CAddress(0x20);

for (;;) {
  try {
    await device.I2C.WriteByteAsync(address, 0x00);  // This will fail after a certain point.
  }
  catch (I2CNAckException) {
  }
}

dotnet build /p:UsbHidDriver=LibUsbDotNet && dotnet run --no-build

case 1: "Assertion `ctx->pollfds_cnt >= internal_nfds' failed."

dmesg:

[ 3347.738701] mcp2221 0003:04D8:00DD.000C: hidraw4: USB HID v1.11 Device [Microchip Technology Inc. MCP2221 USB-I2C/UART Combo] on usb-0000:00:14.0-11.2/input2
[ 3364.322142] usb 1-11.2: usbfs: interface 0 claimed by cdc_acm while 'test' sets config #1
[ 3364.322868] usb 1-11.2: usbfs: interface 0 claimed by cdc_acm while 'test' sets config #0

log:

  :
  :
info: Smdn.Devices.MCP2221.MCP2221[10] I2C Write 1 bytes to 0x20
dbug: Smdn.Devices.MCP2221.MCP2221[10] WRITE_INIT
trce: Smdn.Devices.MCP2221.MCP2221[1] > 10-00-00-20-75-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
[12.529636] [00004326] libusb: debug [handle_events] poll() returned 1
[12.529644] [00004326] libusb: debug [reap_for_handle] urb type=1 status=0 transferred=64
[12.529647] [00004326] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[12.529650] [00004326] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[12.529653] [00004326] libusb: debug [disarm_timerfd] 
[12.529657] [00004326] libusb: debug [usbi_handle_transfer_completion] transfer 0x5651ff30ce80 has callback 0x7f917c084fc0
[12.529660] [00004326] libusb: debug [sync_transfer_cb] actual_length=64
[12.529663] [00004326] libusb: debug [libusb_free_transfer] transfer 0x5651ff30ce80
[12.529669] [00004326] libusb: debug [libusb_alloc_transfer] transfer 0x5651ff30ce80
[12.529671] [00004326] libusb: debug [libusb_submit_transfer] transfer 0x5651ff30ce80
[12.529674] [00004326] libusb: debug [add_to_flying_list] arm timerfd for timeout in 10000ms (first in line)
[12.529677] [00004326] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
[12.529683] [00004326] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[12.529686] [00004326] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[12.530622] [00004326] libusb: debug [handle_events] poll() returned 1
[12.530661] [00004326] libusb: debug [reap_for_handle] urb type=1 status=0 transferred=64
[12.530666] [00004326] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[12.530668] [00004326] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[12.530672] [00004326] libusb: debug [disarm_timerfd] 
[12.530676] [00004326] libusb: debug [usbi_handle_transfer_completion] transfer 0x5651ff30ce80 has callback 0x7f917c084fc0
[12.530679] [00004326] libusb: debug [sync_transfer_cb] actual_length=64
[12.530683] [00004326] libusb: debug [libusb_free_transfer] transfer 0x5651ff30ce80
trce: Smdn.Devices.MCP2221.MCP2221[2] < 10-00-00-21-00-00-00-00-25-01-00-00-00-00-75-00-40-00-10-28-40-60-01-01-00-00-F1-7D-F0-00-00-00-30-30-0B-30-10-23-13-24-04-00-00-26-90-14-41-36-31-32-FD-03-00-00-00-00-6E-02-6F-01-00-00-00-00
info: Smdn.Devices.MCP2221.MCP2221[11] STATUS/SET PARAMATERS: {I2CEngineState: StateMachineStateValue=0x25, Address=0x20, R/W=WRITE, BusStatus=NoSpecialOperation, RequestedTransferLength=1, AlreadyTransferredLength=0, ReadPendingValue=0, DataBufferCounter=0, CommunicationSpeedDividerValue=0x75, TimeoutValue=0, LineValueSCL=High, LineValueSDA=High}
warn: Smdn.Devices.MCP2221.MCP2221[11] STATUS/SET PARAMATERS: new I2C/SMBus communication speed is not considered
dbug: Smdn.Devices.MCP2221.MCP2221[10] WRITE_INIT
trce: Smdn.Devices.MCP2221.MCP2221[1] > 10-00-10-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
[12.530768] [00004326] libusb: debug [libusb_alloc_transfer] transfer 0x5651ff30ce80
[12.530773] [00004326] libusb: debug [libusb_submit_transfer] transfer 0x5651ff30ce80
[12.530776] [00004326] libusb: debug [add_to_flying_list] arm timerfd for timeout in 10000ms (first in line)
[12.530781] [00004326] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
[12.530790] [00004326] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[12.530793] [00004326] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[12.531503] [0000432e] libusb: debug [libusb_exit] 
[12.531516] [0000432e] libusb: debug [libusb_exit] destroying default context
[12.531520] [0000432e] libusb: debug [libusb_unref_device] destroy device 4.1
[12.531522] [0000432e] libusb: debug [libusb_unref_device] destroy device 3.1
[12.531525] [0000432e] libusb: debug [libusb_unref_device] destroy device 1.3
[12.531527] [0000432e] libusb: debug [libusb_unref_device] destroy device 1.4
[12.531530] [0000432e] libusb: debug [libusb_unref_device] destroy device 1.2
[12.531532] [0000432e] libusb: warning [libusb_exit] application left some devices open
[12.531534] [0000432e] libusb: debug [usbi_remove_pollfd] remove fd 84
[12.531567] [0000432e] libusb: debug [usbi_remove_pollfd] remove fd 86
[12.531576] [00004326] libusb: debug [handle_events] poll() returned 1
[12.531585] [00004326] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[12.531588] [00004326] libusb: debug [handle_events] poll fds modified, reallocating
test: ../../libusb/io.c:2146: handle_events: Assertion `ctx->pollfds_cnt >= internal_nfds' failed.
[12.531594] [00004333] libusb: debug [linux_udev_event_thread_main] udev event thread exiting

case 2: segfault

dmesg:

[ 3138.028704] mcp2221 0003:04D8:00DD.000A: hidraw4: USB HID v1.11 Device [Microchip Technology Inc. MCP2221 USB-I2C/UART Combo] on usb-0000:00:14.0-11.2/input2
[ 3154.665558] usb 1-11.2: usbfs: interface 0 claimed by cdc_acm while 'test' sets config #1
[ 3154.666208] usb 1-11.2: usbfs: interface 0 claimed by cdc_acm while 'test' sets config #0
[ 3155.192374] test[16576]: segfault at 7f9cb40008d0 ip 00007f9cb40008d0 sp 00007fffd3ce49e8 error 15
[ 3155.192376] Code: 00 00 00 10 02 00 00 00 00 00 00 10 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 95 02 00 00 00 00 00 00 <07> 00 03 00 01 00 01 00 01 00 00 00 01 00 02 00 06 00 02 00 00 00

log:

  :
  :
info: Smdn.Devices.MCP2221.MCP2221[10] I2C Write 1 bytes to 0x20
dbug: Smdn.Devices.MCP2221.MCP2221[10] WRITE_INIT
trce: Smdn.Devices.MCP2221.MCP2221[1] > 10-00-00-20-75-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
[10.903378] [000040c0] libusb: debug [libusb_alloc_transfer] transfer 0x5646d48e7e20
[10.903384] [000040c0] libusb: debug [libusb_submit_transfer] transfer 0x5646d48e7e20
[10.903386] [000040c0] libusb: debug [add_to_flying_list] arm timerfd for timeout in 10000ms (first in line)
[10.903392] [000040c0] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
[10.903400] [000040c0] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[10.903402] [000040c0] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[10.904087] [000040c0] libusb: debug [handle_events] poll() returned 1
[10.904097] [000040c0] libusb: debug [reap_for_handle] urb type=1 status=0 transferred=64
[10.904100] [000040c0] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[10.904103] [000040c0] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[10.904106] [000040c0] libusb: debug [disarm_timerfd] 
[10.904109] [000040c0] libusb: debug [usbi_handle_transfer_completion] transfer 0x5646d48e7e20 has callback 0x7f9d60467fc0
[10.904112] [000040c0] libusb: debug [sync_transfer_cb] actual_length=64
[10.904116] [000040c0] libusb: debug [libusb_free_transfer] transfer 0x5646d48e7e20
[10.904122] [000040c0] libusb: debug [libusb_alloc_transfer] transfer 0x5646d48e7e20
[10.904125] [000040c0] libusb: debug [libusb_submit_transfer] transfer 0x5646d48e7e20
[10.904127] [000040c0] libusb: debug [add_to_flying_list] arm timerfd for timeout in 10000ms (first in line)
[10.904131] [000040c0] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
[10.904137] [000040c0] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[10.904139] [000040c0] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[10.905049] [000040c8] libusb: debug [libusb_exit] 
[10.905062] [000040c8] libusb: debug [libusb_exit] destroying default context
[10.905068] [000040c8] libusb: debug [libusb_unref_device] destroy device 4.1
[10.905084] [000040c0] libusb: debug [handle_events] poll() returned 1
[10.905093] [000040c8] libusb: debug [libusb_unref_device] destroy device 3.1
[10.905103] [000040c0] libusb: debug [reap_for_handle] urb type=1 status=0 transferred=64
[10.905105] [000040c8] libusb: debug [libusb_unref_device] destroy device 1.3
[10.905106] [000040c0] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[10.905112] [000040c0] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[10.905108] [000040c8] libusb: debug [libusb_unref_device] destroy device 1.4
[10.905115] [000040c0] libusb: debug [disarm_timerfd] 
[10.905120] [000040c8] libusb: debug [libusb_unref_device] destroy device 1.2
[10.905133] [000040c8] libusb: warning [libusb_exit] application left some devices open
[10.905138] [000040c8] libusb: debug [usbi_remove_pollfd] remove fd 84
[10.905125] [000040c0] libusb: debug [usbi_handle_transfer_completion] transfer 0x5646d48e7e20 has callback 0x7f9d60467fc0
[10.905148] [000040c0] libusb: debug [sync_transfer_cb] actual_length=64
[10.905152] [000040c0] libusb: debug [libusb_free_transfer] transfer 0x5646d48e7e20
[10.905154] [000040c8] libusb: debug [usbi_remove_pollfd] remove fd 86
[10.905178] [000040cd] libusb: debug [linux_udev_event_thread_main] udev event thread exiting
[10.905209] [000040c0] libusb: debug [libusb_alloc_transfer] transfer 0x5646d48e7e20
[10.905212] [000040c0] libusb: debug [libusb_submit_transfer] transfer 0x5646d48e7e20
[10.905215] [000040c0] libusb: debug [add_to_flying_list] arm timerfd for timeout in 10000ms (first in line)
[10.905219] [000040c0] libusb: warning [add_to_flying_list] failed to arm first timerfd (errno 9)
[10.905223] [000040c0] libusb: debug [libusb_free_transfer] transfer 0x5646d48e7e20

env

.NET SDK (global.json を反映):
 Version:   5.0.202
 Commit:    db7cc87d51

ランタイム環境:
 OS Name:     ubuntu
 OS Version:  20.04
 OS Platform: Linux
 RID:         ubuntu.20.04-x64
 Base Path:   /usr/share/dotnet/sdk/5.0.202/

Host (useful for support):
  Version: 5.0.5
  Commit:  2f740adc14