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

nut_libusb_open get some values failed, retrying... #1548

Open
masterwishx opened this issue Aug 7, 2024 · 63 comments · May be fixed by #1558
Open

nut_libusb_open get some values failed, retrying... #1548

masterwishx opened this issue Aug 7, 2024 · 63 comments · May be fixed by #1558
Labels
question Technical support, will be closed if deemed not a libusb issue. Please use mailing list.

Comments

@masterwishx
Copy link

Not sure if related to libusb , but maybe any help from here would help to recognize some values for libusb NUT for Eaton 9E UPS
networkupstools/nut#2571
networkupstools/nut#1925

@mcuee mcuee added the question Technical support, will be closed if deemed not a libusb issue. Please use mailing list. label Aug 7, 2024
@mcuee
Copy link
Member

mcuee commented Aug 7, 2024

Please help to provide more info -- OS, libusb version used, more info about the device, etc.
https://github.com/libusb/libusb/wiki/Troubleshooting

@masterwishx
Copy link
Author

Please help to provide more info -- OS, libusb version used, more info about the device, etc. https://github.com/libusb/libusb/wiki/Troubleshooting

Oh I'm sorry, this is:
Unraid x64 v6.12.11 (Slackware 15)
libusb-1.0.26(api: 0x1000108)
Driver: usbhid-ups
NUT plugin for Eaton 9E2000i ups

@masterwishx
Copy link
Author

Again, im not sure that is issue with libusb , but if you can confirm or give a hint ?

So using NUT plugin for Unraid by @desertwitch nut-2.8.2-x86_64-1stable.ssl11

also in networkupstools/nut#2562
the networkupstools developer @jimklimov tryed to help me recognize usb device Eaton 9E 2000i UPS , that now is: unknown 2000 for device.model and ups.model. But lsusb shows the info :

Bus 003 Device 002: ID 0463:ffff MGE UPS Systems UPS
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               1.10
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0         8
  idVendor           0x0463 MGE UPS Systems
  idProduct          0xffff UPS
  bcdDevice            2.02
  iManufacturer           1 EATON
  iProduct                2 Eaton 9E
  iSerial                 4 GExxxxxx  #hidden by me
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x0022
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0 
    bmAttributes         0x80
      (Bus Powered)
    MaxPower               20mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           1
      bInterfaceClass         3 Human Interface Device
      bInterfaceSubClass      0 
      bInterfaceProtocol      0 
      iInterface              0 
        HID Device Descriptor:
          bLength                 9
          bDescriptorType        33
          bcdHID               1.10
          bCountryCode           33 US
          bNumDescriptors         1
          bDescriptorType        34 Report
          wDescriptorLength    1014
         Report Descriptors: 
           ** UNAVAILABLE **
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0008  1x 8 bytes
        bInterval              20
can't get debug descriptor: Resource temporarily unavailable
Device Status:     0x0001
  Self Powered

but :

nut_libusb_open get iManufacturer failed, retrying...
nut_libusb_open get iProduct failed, retrying...
nut_libusb_open get iSerialNumber failed, retrying...

https://github.com/user-attachments/files/16457007/nut.log usbhid-ups log

networkupstools/nut#2571 (comment) more info from developer

@tormodvolden
Copy link
Contributor

Please see https://github.com/libusb/libusb/wiki/FAQ#user-content-Does_libusb_support_USB_HID_devices

@jimklimov
Copy link

Thanks for the link. Currently NUT does not use HIDAPI, and I don't think anyone offered to contribute code to that extent, although that would be welcome :)

NUT is a libusb user since 2003 (maybe before) though, with shims to use either libusb-0.1 or 1.0 in mainline for a couple of years now, and not only HID devices in the loop.

If the API concepts are similar, same shims could be expanded to cover HIDAPI, I suppose, but I am probably not the one to figure out and do it well :( Despite the years of maintainership of largely other people's code, I am sadly vague about even the terminology, so please bear with me.

Back to the original topic: from what I've gathered from the logs and discussions about this issue in NUT tracker, detailed e.g. here: networkupstools/nut#2571 (comment) our driver gets the report descriptor of about 2KB in size, and walks it to interpret particular reports. While there are no issues with most of the data points, queries for these 3 identification strings return an "Input/Output Error" code.

  • The "unknown 2000" placeholder of a name is constructed by the driver from a NULL model and known wattage of the UPS.
  • The device has MGE/Eaton identification (vendorid 0x0463) which could have been subject to "quirks" historically. I think we did rule this out for the case in question: the kernel parameter usbhid.quirks=0x0463:0xffff:0x08 recommended elsewhere did not help.

The puzzle here is that the same approach works for most of the other devices quite well (not 100%, I occasionally do see similar reports - usually in conjunction with inadequate udev setup or virtualization pass-through getting in the way). Tools like lsusb, udevadm info and allegedly apcupsd do not have any problem reporting those strings; at least the latter is AFAIK a pure libusb consumer too.

So I guess the question for this tracker is whether we have stumbled on some well-known gardening equipment here, "do X or don't do Y, and the ailment is gone" sort of stuff?

@jimklimov
Copy link

FWIW, HIDAPI was mentioned in the NUT issue tracker... once I think - right in the thread about getting libusb-1.0 into the mainline codebase: networkupstools/nut#300 (comment)

@tormodvolden
Copy link
Contributor

queries for these 3 identification strings return an "Input/Output Error" code.

Are your queries control transfers for requesting the device strings? I suppose you get the same error when running examples/xusb on the device?

For getting these strings from the OS instead, there is work going on in PR #1532. I think lsusb and udevadm get these string values from the udev database without sending USB requests.

@jimklimov
Copy link

Thanks for the quick reply! I'll try to track down the answer to how the info is queried, though likely tomorrow (now commuting home).

I would defer to @masterwishx about building and running the example program against the actual device.

@masterwishx
Copy link
Author

Thanks for the quick reply! I'll try to track down the answer to how the info is queried, though likely tomorrow (now commuting home).

I would defer to @masterwishx about building and running the example program against the actual device.

I'm here to test when needed just need @desertwitch to compile or provide me config for compile in case.

BTW now using the preview build for nut plugin from master where you added pr for Eaton 9E.

@tormodvolden
Copy link
Contributor

To build xusb and other examples:

./configure --enable-tests-build --enable-examples-build     # Or if from a git checkout: ./autogen.sh
make
./examples/xusb -d 0x0463:0xffff    # or whatever the VID:PID is   # -d enables debug output

@masterwishx
Copy link
Author

To build xusb and other examples:

./configure --enable-tests-build --enable-examples-build     # Or if from a git checkout: ./autogen.sh
make
./examples/xusb -d 0x0463:0xffff    # or whatever the VID:PID is   # -d enables debug output

im using Unraid (Slackware 15) and NUT plugin for Unraid maintained by @desertwitch , so i have build.slack from his package but also need config file that he is using , but he was kindly compiled for me before for pr's by @jimklimov

@masterwishx
Copy link
Author

To build xusb and other examples:

./configure --enable-tests-build --enable-examples-build     # Or if from a git checkout: ./autogen.sh
make
./examples/xusb -d 0x0463:0xffff    # or whatever the VID:PID is   # -d enables debug output

Oh do you mean for xusb, but how it will work with nut?

@tormodvolden
Copy link
Contributor

You can run it independently of nut, to see if you can read out the device descriptor strings, or if you get some error.

@masterwishx
Copy link
Author

You can run it independently of nut, to see if you can read out the device descriptor strings, or if you get some error.

Thanks i will try

@masterwishx
Copy link
Author

To build xusb and other examples:

./configure --enable-tests-build --enable-examples-build     # Or if from a git checkout: ./autogen.sh
make
./examples/xusb -d 0x0463:0xffff    # or whatever the VID:PID is   # -d enables debug output

@jimklimov do you think it can help?
Also I should stop nut plugin befor?

@tormodvolden
Copy link
Contributor

You should run this independently of nut, so yes, stop nut while doing these tests.

@tormodvolden
Copy link
Contributor

tormodvolden commented Aug 21, 2024

@jimklimov

  • I looked at above linked nut.log, but there is no libusb debug output in it. You can for instance at an appropriate debug level also enable libusb debug output, that would help in debugging these cases. For now can you please explain masterwish how to set env var LIBUSB_DEBUG=4 for the process? I don't know how the process is started.
  • the log says libusb 1.0.26 is used. Slackware 15 is at 1.0.24 according to repology. Are you bundling another libusb? It would be good if this can be tested with 1.0.27 as well.
  • are libusb hotplug callbacks in use?
  • "same approach works for most of the other devices quite well" - does this correlate with devices using HID and not?
Aug  1 16:04:47 DaRKNaS rc.nut:    0.330997#011[D2:14407] Claimed interface 0 successfully
Aug  1 16:04:47 DaRKNaS rc.nut:    0.331000#011[D3:14407] nut_usb_set_altinterface: skipped libusb_set_interface_alt_setting(udev, 0, 0)
Aug  1 16:04:47 DaRKNaS rc.nut:    0.352192#011[D1:14407] nut_libusb_open get iManufacturer failed, retrying...
  • is nut_libusb_open here trying to open a device that was already opened and claimed?

@masterwishx
Copy link
Author

@jimklimov

  • I looked at above linked nut.log, but there is no libusb debug output in it. You can for instance at an appropriate debug level also enable libusb debug output, that would help in debugging these cases. For now can you please explain masterwish how to set env var LIBUSB_DEBUG=4 for the process? I don't know how the process is started.
  • the log says libusb 1.0.26 is used. Slackware 15 is at 1.0.24 according to repology. Are you bundling another libusb? It would be good if this can be tested with 1.0.27 as well.
  • are libusb hotplug callbacks in use?
  • "same approach works for most of the other devices quite well" - does this correlate with devices using HID and not?

Unraid v6.12.11 that I'm using has libusb v1.0.26, I think I tryed to use v1.0.27 but it's not working with current unraid version.

But like I said befor Unraid 7 beta2 has libusb-1.0.27.
But I need update Unraid for check it.

Maybe @desertwitch also know how to debug libusb in Unraid?

@tormodvolden
Copy link
Contributor

@masterwishx Please try 1.0.27 then. You can run "sudo make install" after the "make" above if you have the 1.0.27 or git master sources, or get it from your distribution - sometimes there are possibilities of upgrading single packages.

But please test xusb as instructed above first. Then afterwards you can back to debugging nut again.

@desertwitch
Copy link

Sorry I don't really have anything useful to add here nor the time to help out with further diagnosis, considering this is for the most part an optical and not a functional, road-blocking issue for you (as we've established in the various other issues and repositories this has popped up in over the past weeks). I really don't mean this in a rude way but please, for sake of general etiquette, don't tag and ping me continuously everywhere - I would chime in if I had something useful to add or time to help out. For what it's worth, the compilation process on Slackware (which is the underlying OS of Unraid) is the same as with most other distributions - no special configurations or anything are really needed (those of my packaging process are unneeded for testing).

@masterwishx
Copy link
Author

Sorry I don't really have anything useful to add here nor the time to help out with further diagnosis, considering this is for the most part an optical and not a functional, road-blocking issue for you (as we've established in the various other issues and repositories this has popped up in over the past weeks). I really don't mean this in a rude way but please, for sake of general etiquette, don't tag and ping me continuously everywhere - I would chime in if I had something useful to add or time to help out. For what it's worth, the compilation process on Slackware (which is the underlying OS of Unraid) is the same as with most other distributions - no special configurations or anything are really needed (those of my packaging process are unneeded for testing).

OK, I'm really sorry for this, but it's not only optic problem but some values not avaliable becose of it. Optic problem not important for me. Sorry again I got it. Thanks for your help

@masterwishx
Copy link
Author

@masterwishx Please try 1.0.27 then. You can run "sudo make install" after the "make" above if you have the 1.0.27 or git master sources, or get it from your distribution - sometimes there are possibilities of upgrading single packages.

But please test xusb as instructed above first. Then afterwards you can back to debugging nut again.

Thanks will try

@jimklimov
Copy link

jimklimov commented Aug 22, 2024

queries for these 3 identification strings return an "Input/Output Error" code.

Are your queries control transfers for requesting the device strings? I suppose you get the same error when running examples/xusb on the device?

For getting these strings from the OS instead, there is work going on in PR #1532. I think lsusb and udevadm get these string values from the udev database without sending USB requests.

Thanks for the quick reply! I'll try to track down the answer to how the info is queried, though likely tomorrow (now commuting home).

So, by the looks of it, in the initial device identification (where we loop to check if vendorid, productid and other criteria tell us that this driver likes this device), we:

In case of usbhid-ups driver, the callback method is at https://github.com/networkupstools/nut/blob/master/drivers/usbhid-ups.c#L1629

The big data dump ought to be HIDDumpTree() called at https://github.com/networkupstools/nut/blob/master/drivers/usbhid-ups.c#L1704 implemented at https://github.com/networkupstools/nut/blob/master/drivers/libhid.c#L406 and its visible work ends at log line Aug 1 16:04:53 DaRKNaS rc.nut: 5.523237#011[D2:14407] get_model_name(unknown, 2000)

I think that's all the digging I can wrap my head around at the moment...

@masterwishx
Copy link
Author

To build xusb and other examples:

./configure --enable-tests-build --enable-examples-build     # Or if from a git checkout: ./autogen.sh
make
./examples/xusb -d 0x0463:0xffff    # or whatever the VID:PID is   # -d enables debug output

have error when trying ./configure --enable-tests-build --enable-examples-build :

image

@masterwishx
Copy link
Author

image

@jimklimov
Copy link

Did you install the build toolkits? I suppose those listed in NUT docs/config-prereqs.txt would cover a lot (and more, for NUT's other dependencies) if not all libusb needs.

@masterwishx
Copy link
Author

masterwishx commented Aug 24, 2024

Did you install the build toolkits? I suppose those listed in NUT docs/config-prereqs.txt would cover a lot (and more, for NUT's other dependencies) if not all libusb needs.

No, I had only experience to compile in Slackware VM or same but in docker AutoSlackPack.
Thanks i will check it...

@masterwishx
Copy link
Author

make clean

/app/libusb-1.0.27/examples: No such file or directory

it seems becose it stored container path : /app/libusb-1.0.27/examples and im running from unraid terminal but it worked befor with 1.0.26

@masterwishx
Copy link
Author

tryed some times but get the same , also have:

image

./examples/xusb: line 202: cd: /app/libusb/examples: No such file or directory
/usr/bin/ld: cannot find crt1.o: No such file or directory
/usr/bin/ld: cannot find crti.o: No such file or directory
/usr/bin/ld: cannot find xusb.o: No such file or directory
/usr/bin/ld: cannot find ../libusb/.libs/libusb-1.0.so: No such file or directory
collect2: error: ld returned 1 exit status

howere v 1.0.26 worked , here also have in compile last line , but no success: config.status: executing libtool commands

@tormodvolden
Copy link
Contributor

Do "make clean" again and this time do "make CFLAGS=-static". Then the examples/xusb binary will have libusb embedded and you can copy it over and run anywhere without libtool coming in the way.

@masterwishx
Copy link
Author

Do "make clean" again and this time do "make CFLAGS=-static". Then the examples/xusb binary will have libusb embedded and you can copy it over and run anywhere without libtool coming in the way.

Thanks, I will try it

@masterwishx
Copy link
Author

Do "make clean" again and this time do "make CFLAGS=-static". Then the examples/xusb binary will have libusb embedded and you can copy it over and run anywhere without libtool coming in the way.

Thanks for advice ,have this after runned :

Using libusb v1.0.27.11882

[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.000014] [00000ce1] libusb: debug [libusb_init_context] created default context
[ 0.000029] [00000ce1] libusb: debug [libusb_init_context] libusb v1.0.27.11882
[ 0.000054] [00000ce1] libusb: debug [usbi_add_event_source] add fd 3 events 1
[ 0.000077] [00000ce1] libusb: debug [usbi_io_init] using timer for timeouts
[ 0.000080] [00000ce1] libusb: debug [usbi_add_event_source] add fd 4 events 1
[ 0.000106] [00000ce1] libusb: debug [get_kernel_version] reported kernel version is 6.1.106-Unraid
[ 0.000127] [00000ce1] libusb: debug [op_init] found usbfs at /dev/bus/usb
[ 0.000130] [00000ce1] libusb: debug [op_init] max iso packet length is (likely) 98304 bytes
[ 0.000143] [00000ce1] libusb: debug [op_init] sysfs is available
[ 0.000338] [00000ce2] libusb: debug [linux_udev_event_thread_main] udev event thread entering
[ 0.001273] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: usb3 detached: 0
[ 0.001280] [00000ce1] libusb: debug [linux_get_device_address] scan usb3
[ 0.001311] [00000ce1] libusb: debug [linux_get_device_address] bus=3 dev=1
[ 0.001329] [00000ce1] libusb: debug [linux_enumerate_device] busnum 3 devaddr 1 session_id 769
[ 0.001340] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 3/1 (session 769)
[ 0.001401] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: 3-3 detached: 0
[ 0.001406] [00000ce1] libusb: debug [linux_get_device_address] scan 3-3
[ 0.001428] [00000ce1] libusb: debug [linux_get_device_address] bus=3 dev=2
[ 0.001431] [00000ce1] libusb: debug [linux_enumerate_device] busnum 3 devaddr 2 session_id 770
[ 0.001435] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 3/2 (session 770)
[ 0.001462] [00000ce1] libusb: debug [linux_get_parent_info] dev 0x438e00 (3-3) has parent 0x43a940 (usb3) port 3
[ 0.001489] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: 3-4 detached: 0
[ 0.001492] [00000ce1] libusb: debug [linux_get_device_address] scan 3-4
[ 0.001514] [00000ce1] libusb: debug [linux_get_device_address] bus=3 dev=3
[ 0.001517] [00000ce1] libusb: debug [linux_enumerate_device] busnum 3 devaddr 3 session_id 771
[ 0.001519] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 3/3 (session 771)
[ 0.001542] [00000ce1] libusb: debug [linux_get_parent_info] dev 0x439020 (3-4) has parent 0x43a940 (usb3) port 4
[ 0.001566] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: 3-6 detached: 0
[ 0.001570] [00000ce1] libusb: debug [linux_get_device_address] scan 3-6
[ 0.001592] [00000ce1] libusb: debug [linux_get_device_address] bus=3 dev=4
[ 0.001596] [00000ce1] libusb: debug [linux_enumerate_device] busnum 3 devaddr 4 session_id 772
[ 0.001605] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 3/4 (session 772)
[ 0.001634] [00000ce1] libusb: debug [linux_get_parent_info] dev 0x4390d0 (3-6) has parent 0x43a940 (usb3) port 6
[ 0.001660] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: usb4 detached: 0
[ 0.001663] [00000ce1] libusb: debug [linux_get_device_address] scan usb4
[ 0.001686] [00000ce1] libusb: debug [linux_get_device_address] bus=4 dev=1
[ 0.001689] [00000ce1] libusb: debug [linux_enumerate_device] busnum 4 devaddr 1 session_id 1025
[ 0.001692] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 4/1 (session 1025)
[ 0.001734] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: usb1 detached: 0
[ 0.001738] [00000ce1] libusb: debug [linux_get_device_address] scan usb1
[ 0.001759] [00000ce1] libusb: debug [linux_get_device_address] bus=1 dev=1
[ 0.001762] [00000ce1] libusb: debug [linux_enumerate_device] busnum 1 devaddr 1 session_id 257
[ 0.001765] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 1/1 (session 257)
[ 0.001816] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: 1-1 detached: 0
[ 0.001819] [00000ce1] libusb: debug [linux_get_device_address] scan 1-1
[ 0.001848] [00000ce1] libusb: debug [linux_get_device_address] bus=1 dev=2
[ 0.001858] [00000ce1] libusb: debug [linux_enumerate_device] busnum 1 devaddr 2 session_id 258
[ 0.001866] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 1/2 (session 258)
[ 0.001930] [00000ce1] libusb: debug [linux_get_parent_info] dev 0x4289b0 (1-1) has parent 0x4287d0 (usb1) port 1
[ 0.001956] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: usb2 detached: 0
[ 0.001959] [00000ce1] libusb: debug [linux_get_device_address] scan usb2
[ 0.001984] [00000ce1] libusb: debug [linux_get_device_address] bus=2 dev=1
[ 0.001987] [00000ce1] libusb: debug [linux_enumerate_device] busnum 2 devaddr 1 session_id 513
[ 0.001995] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 2/1 (session 513)
[ 0.002035] [00000ce1] libusb: debug [linux_get_device_address] getting address for device: 2-1 detached: 0
[ 0.002039] [00000ce1] libusb: debug [linux_get_device_address] scan 2-1
[ 0.002059] [00000ce1] libusb: debug [linux_get_device_address] bus=2 dev=2
[ 0.002062] [00000ce1] libusb: debug [linux_enumerate_device] busnum 2 devaddr 2 session_id 514
[ 0.002064] [00000ce1] libusb: debug [linux_enumerate_device] allocating new device for 2/2 (session 514)
[ 0.002083] [00000ce1] libusb: debug [linux_get_parent_info] dev 0x428d90 (2-1) has parent 0x428bb0 (usb2) port 1
Opening device 0463:FFFF...
[ 0.002137] [00000ce1] libusb: debug [libusb_get_device_list]  
[ 0.002165] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
[ 0.002169] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
[ 0.002170] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
[ 0.002178] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
[ 0.002182] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
[ 0.002184] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
[ 0.002189] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
[ 0.002194] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
[ 0.002196] [00000ce1] libusb: debug [libusb_open] open 3.2
[ 0.002213] [00000ce1] libusb: debug [usbi_add_event_source] add fd 7 events 4

Reading device descriptor:
[ 0.002220] [00000ce1] libusb: debug [libusb_get_device_descriptor]  
            length: 18
      device class: 0
               S/N: 4
           VID:PID: 0463:FFFF
         bcdDevice: 0202
   iMan:iProd:iSer: 1:2:4
          nb confs: 1

[ 0.002239] [00000ce1] libusb: debug [libusb_submit_transfer] transfer 0x429050
[ 0.002242] [00000ce1] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.002277] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.002281] [00000ce1] libusb: debug [handle_events] event sources modified, reallocating event data
[ 0.002286] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.002409] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.002414] [00000ce1] libusb: debug [reap_for_handle] urb type=2 status=-32 transferred=0
[ 0.002417] [00000ce1] libusb: debug [handle_control_completion] handling completion status -32
[ 0.002420] [00000ce1] libusb: debug [handle_control_completion] unsupported control request
[ 0.002423] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.002426] [00000ce1] libusb: debug [usbi_handle_transfer_completion] transfer 0x429050 has callback 0x410c17
[ 0.002429] [00000ce1] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.002433] [00000ce1] libusb: debug [libusb_free_transfer] transfer 0x429050
Reading BOS descriptor: no descriptor

Reading first configuration descriptor:
[ 0.002442] [00000ce1] libusb: debug [libusb_get_config_descriptor] index 0
              total length: 34
         descriptor length: 9
             nb interfaces: 1
              interface[0]: id = 0
interface[0].altsetting[0]: num endpoints = 1
   Class.SubClass.Protocol: 03.00.00
       endpoint[0].address: 81
           max packet size: 0008
          polling interval: 14

[ 0.002472] [00000ce1] libusb: debug [libusb_kernel_driver_active] interface 0
Kernel driver attached for interface 0: none

Claiming interface 0...
[ 0.002492] [00000ce1] libusb: debug [libusb_claim_interface] interface 0

Reading string descriptors:
[ 0.002507] [00000ce1] libusb: debug [libusb_submit_transfer] transfer 0x4291a0
[ 0.002509] [00000ce1] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.002518] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.002520] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.023645] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.023664] [00000ce1] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.023683] [00000ce1] libusb: debug [handle_control_completion] handling completion status 0
[ 0.023686] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.023691] [00000ce1] libusb: debug [usbi_handle_transfer_completion] transfer 0x4291a0 has callback 0x410c17
[ 0.023694] [00000ce1] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.023698] [00000ce1] libusb: debug [libusb_free_transfer] transfer 0x4291a0
langid for string 1 returned 4

  00000000  04 00 03 00                                      ....
[ 0.023713] [00000ce1] libusb: debug [libusb_submit_transfer] transfer 0x429290
[ 0.023716] [00000ce1] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.023729] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.023742] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.044848] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.044895] [00000ce1] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.044900] [00000ce1] libusb: debug [handle_control_completion] handling completion status 0
[ 0.044905] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.044909] [00000ce1] libusb: debug [usbi_handle_transfer_completion] transfer 0x429290 has callback 0x410c17
[ 0.044913] [00000ce1] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.044925] [00000ce1] libusb: debug [libusb_free_transfer] transfer 0x429290
[ 0.044931] [00000ce1] libusb: debug [libusb_submit_transfer] transfer 0x429380
[ 0.044934] [00000ce1] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.044957] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.044974] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.066147] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.066180] [00000ce1] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.066188] [00000ce1] libusb: debug [handle_control_completion] handling completion status 0
[ 0.066196] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.066206] [00000ce1] libusb: debug [usbi_handle_transfer_completion] transfer 0x429380 has callback 0x410c17
[ 0.066213] [00000ce1] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.066223] [00000ce1] libusb: debug [libusb_free_transfer] transfer 0x429380
langid for string 2 returned 4

  00000000  04 00 03 00                                      ....
[ 0.066260] [00000ce1] libusb: debug [libusb_submit_transfer] transfer 0x429470
[ 0.066270] [00000ce1] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.066298] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.066307] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.087543] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.087571] [00000ce1] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.087577] [00000ce1] libusb: debug [handle_control_completion] handling completion status 0
[ 0.087584] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.087594] [00000ce1] libusb: debug [usbi_handle_transfer_completion] transfer 0x429470 has callback 0x410c17
[ 0.087603] [00000ce1] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.087613] [00000ce1] libusb: debug [libusb_free_transfer] transfer 0x429470
[ 0.087624] [00000ce1] libusb: debug [libusb_submit_transfer] transfer 0x429560
[ 0.087632] [00000ce1] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.087656] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.087664] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.108866] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.108909] [00000ce1] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.108916] [00000ce1] libusb: debug [handle_control_completion] handling completion status 0
[ 0.108923] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.108933] [00000ce1] libusb: debug [usbi_handle_transfer_completion] transfer 0x429560 has callback 0x410c17
[ 0.108939] [00000ce1] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.108948] [00000ce1] libusb: debug [libusb_free_transfer] transfer 0x429560
langid for string 4 returned 4

  00000000  04 00 03 00                                      ....
[ 0.109003] [00000ce1] libusb: debug [libusb_submit_transfer] transfer 0x429650
[ 0.109010] [00000ce1] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.109035] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.109043] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.130199] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.130227] [00000ce1] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.130229] [00000ce1] libusb: debug [handle_control_completion] handling completion status 0
[ 0.130233] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.130238] [00000ce1] libusb: debug [usbi_handle_transfer_completion] transfer 0x429650 has callback 0x410c17
[ 0.130254] [00000ce1] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.130258] [00000ce1] libusb: debug [libusb_free_transfer] transfer 0x429650

[ 0.130267] [00000ce1] libusb: debug [libusb_submit_transfer] transfer 0x429740
[ 0.130269] [00000ce1] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.130282] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.130286] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 1.130300] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.130316] [00000ce1] libusb: debug [libusb_cancel_transfer] transfer 0x429740
[ 1.130429] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 1.130451] [00000ce1] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.130454] [00000ce1] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 1.130459] [00000ce1] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.130465] [00000ce1] libusb: debug [reap_for_handle] urb type=2 status=-2 transferred=0
[ 1.130471] [00000ce1] libusb: debug [handle_control_completion] handling completion status -2
[ 1.130473] [00000ce1] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 1.130476] [00000ce1] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 1.130487] [00000ce1] libusb: debug [usbi_handle_transfer_completion] transfer 0x429740 has callback 0x410c17
[ 1.130490] [00000ce1] libusb: debug [sync_transfer_cb] actual_length=0
[ 1.130493] [00000ce1] libusb: debug [libusb_free_transfer] transfer 0x429740
Reading OS string descriptor: no descriptor

Reading interface association descriptors (IADs) for first configuration:
[ 1.130501] [00000ce1] libusb: debug [libusb_get_interface_association_descriptors] IADs for config index 0
    nb IADs: 0

Releasing interface 0...
[ 1.130510] [00000ce1] libusb: debug [libusb_release_interface] interface 0
Closing device...
[ 2.800275] [00000ce1] libusb: debug [libusb_close]  
[ 2.800282] [00000ce1] libusb: debug [usbi_remove_event_source] remove fd 7
[ 2.800289] [00000ce1] libusb: debug [libusb_exit] destroying default context
[ 2.800292] [00000ce1] libusb: debug [libusb_unref_device] destroy device 2.2
[ 2.800294] [00000ce1] libusb: debug [libusb_unref_device] destroy device 2.1
[ 2.800297] [00000ce1] libusb: debug [libusb_unref_device] destroy device 1.2
[ 2.800299] [00000ce1] libusb: debug [libusb_unref_device] destroy device 1.1
[ 2.800301] [00000ce1] libusb: debug [libusb_unref_device] destroy device 4.1
[ 2.800303] [00000ce1] libusb: debug [libusb_unref_device] destroy device 3.4
[ 2.800305] [00000ce1] libusb: debug [libusb_unref_device] destroy device 3.3
[ 2.800307] [00000ce1] libusb: debug [libusb_unref_device] destroy device 3.2
[ 2.800310] [00000ce1] libusb: debug [libusb_unref_device] destroy device 3.1
[ 2.800322] [00000ce2] libusb: debug [linux_udev_event_thread_main] udev event thread exiting
[ 2.800392] [00000ce1] libusb: debug [usbi_remove_event_source] remove fd 4
[ 2.800398] [00000ce1] libusb: debug [usbi_remove_event_source] remove fd 3

@masterwishx
Copy link
Author

config libusb-1.0.27.log
config libusb-1.0.26.log

@tormodvolden please check compile logs , becose as i said befor i dont have success on compile , its just stop when:

config.status: creating config.h
config.status: executing depfiles commands
config.status: executing libtool commands     **<-   last line**

@masterwishx
Copy link
Author

config libusb-1.0.27.log config libusb-1.0.26.log

@tormodvolden please check compile logs , becose as i said befor i dont have success on compile , its just stop when:

config.status: creating config.h
config.status: executing depfiles commands
config.status: executing libtool commands     **<-   last line**

Or as you mentioned it seems also OK?

@tormodvolden
Copy link
Contributor

Thanks, now I can see what is wrong:

langid for string 1 returned 4

  00000000  04 00 03 00            

This is a bug in the device firmware. It should have returned a valid descriptor listing which languages are supported for its string descriptors. On a typical device that includes the code 0x0409 for en_US language, which would give the byte sequence 04 (length of descriptor) 03 (type of descriptor) 09 04 (0x0409 in little-endian).
In this case the returned descriptor type is 0 which is not a valid value, and libusb rejects it. I am pretty sure the language code is not meant to be 0x0003 either. I think the firmware authors goofed and returned the 16-bit numbers 04 and 03 instead and maybe the actual language code (e.g. 0x0409) follows these first 4 bytes.

@jimklimov
Copy link

CC @arnaudquette-eaton

@masterwishx
Copy link
Author

maybe the actual language code (e.g. 0x0409) follows these first 4 bytes.

Should I check also next 4 bytes if it will help?

r = libusb_get_string_descriptor(handle, 0, 0, (unsigned char*)string, 8);

@tormodvolden
Copy link
Contributor

Yes, thanks, it would be interesting!

@masterwishx
Copy link
Author

Strange, have the same ?

Using libusb v1.0.27.11882

[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.000025] [000004d3] libusb: debug [libusb_init_context] created default context
[ 0.000046] [000004d3] libusb: debug [libusb_init_context] libusb v1.0.27.11882
[ 0.000078] [000004d3] libusb: debug [usbi_add_event_source] add fd 3 events 1
[ 0.000106] [000004d3] libusb: debug [usbi_io_init] using timer for timeouts
[ 0.000113] [000004d3] libusb: debug [usbi_add_event_source] add fd 4 events 1
[ 0.000153] [000004d3] libusb: debug [get_kernel_version] reported kernel version is 6.1.106-Unraid
[ 0.000185] [000004d3] libusb: debug [op_init] found usbfs at /dev/bus/usb
[ 0.000200] [000004d3] libusb: debug [op_init] max iso packet length is (likely) 98304 bytes
[ 0.000211] [000004d3] libusb: debug [op_init] sysfs is available
[ 0.001326] [000004d3] libusb: debug [linux_get_device_address] getting address for device: usb3 detached: 0
[ 0.001348] [000004d3] libusb: debug [linux_get_device_address] scan usb3
[ 0.001381] [000004d3] libusb: debug [linux_get_device_address] bus=3 dev=1
[ 0.001404] [000004d3] libusb: debug [linux_enumerate_device] busnum 3 devaddr 1 session_id 769
[ 0.001431] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 3/1 (session 769)
[ 0.001533] [000004d3] libusb: debug [linux_get_device_address] getting address for device: 3-3 detached: 0
[ 0.001547] [000004d3] libusb: debug [linux_get_device_address] scan 3-3
[ 0.001576] [000004d3] libusb: debug [linux_get_device_address] bus=3 dev=2
[ 0.001585] [000004d3] libusb: debug [linux_enumerate_device] busnum 3 devaddr 2 session_id 770
[ 0.001592] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 3/2 (session 770)
[ 0.001629] [000004d3] libusb: debug [linux_get_parent_info] dev 0x43a6e0 (3-3) has parent 0x439820 (usb3) port 3
[ 0.001669] [000004d3] libusb: debug [linux_get_device_address] getting address for device: 3-4 detached: 0
[ 0.001678] [000004d3] libusb: debug [linux_get_device_address] scan 3-4
[ 0.001707] [000004d3] libusb: debug [linux_get_device_address] bus=3 dev=3
[ 0.001719] [000004d3] libusb: debug [linux_enumerate_device] busnum 3 devaddr 3 session_id 771
[ 0.001726] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 3/3 (session 771)
[ 0.001752] [000004d3] libusb: debug [linux_get_parent_info] dev 0x43a900 (3-4) has parent 0x439820 (usb3) port 4
[ 0.001800] [000004d3] libusb: debug [linux_get_device_address] getting address for device: 3-6 detached: 0
[ 0.001811] [000004d3] libusb: debug [linux_get_device_address] scan 3-6
[ 0.001838] [000004d3] libusb: debug [linux_get_device_address] bus=3 dev=4
[ 0.001847] [000004d3] libusb: debug [linux_enumerate_device] busnum 3 devaddr 4 session_id 772
[ 0.001853] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 3/4 (session 772)
[ 0.001896] [000004d3] libusb: debug [linux_get_parent_info] dev 0x43ab20 (3-6) has parent 0x439820 (usb3) port 6
[ 0.001948] [000004d3] libusb: debug [linux_get_device_address] getting address for device: usb4 detached: 0
[ 0.001959] [000004d3] libusb: debug [linux_get_device_address] scan usb4
[ 0.001988] [000004d3] libusb: debug [linux_get_device_address] bus=4 dev=1
[ 0.001996] [000004d3] libusb: debug [linux_enumerate_device] busnum 4 devaddr 1 session_id 1025
[ 0.002009] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 4/1 (session 1025)
[ 0.002073] [000004d3] libusb: debug [linux_get_device_address] getting address for device: usb1 detached: 0
[ 0.002085] [000004d3] libusb: debug [linux_get_device_address] scan usb1
[ 0.002114] [000004d3] libusb: debug [linux_get_device_address] bus=1 dev=1
[ 0.002123] [000004d3] libusb: debug [linux_enumerate_device] busnum 1 devaddr 1 session_id 257
[ 0.002129] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 1/1 (session 257)
[ 0.002183] [000004d3] libusb: debug [linux_get_device_address] getting address for device: 1-1 detached: 0
[ 0.002194] [000004d3] libusb: debug [linux_get_device_address] scan 1-1
[ 0.002220] [000004d3] libusb: debug [linux_get_device_address] bus=1 dev=2
[ 0.002228] [000004d3] libusb: debug [linux_enumerate_device] busnum 1 devaddr 2 session_id 258
[ 0.002235] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 1/2 (session 258)
[ 0.002278] [000004d3] libusb: debug [linux_get_parent_info] dev 0x428790 (1-1) has parent 0x43a590 (usb1) port 1
[ 0.002324] [000004d3] libusb: debug [linux_get_device_address] getting address for device: usb2 detached: 0
[ 0.002338] [000004d3] libusb: debug [linux_get_device_address] scan usb2
[ 0.002364] [000004d3] libusb: debug [linux_get_device_address] bus=2 dev=1
[ 0.002373] [000004d3] libusb: debug [linux_enumerate_device] busnum 2 devaddr 1 session_id 513
[ 0.002394] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 2/1 (session 513)
[ 0.002451] [000004d3] libusb: debug [linux_get_device_address] getting address for device: 2-1 detached: 0
[ 0.002461] [000004d3] libusb: debug [linux_get_device_address] scan 2-1
[ 0.002473] [000004d4] libusb: debug [linux_udev_event_thread_main] udev event thread entering
[ 0.002507] [000004d3] libusb: debug [linux_get_device_address] bus=2 dev=2
[ 0.002516] [000004d3] libusb: debug [linux_enumerate_device] busnum 2 devaddr 2 session_id 514
[ 0.002522] [000004d3] libusb: debug [linux_enumerate_device] allocating new device for 2/2 (session 514)
[ 0.002549] [000004d3] libusb: debug [linux_get_parent_info] dev 0x428b90 (2-1) has parent 0x4289b0 (usb2) port 1
Opening device 0463:FFFF...
[ 0.002628] [000004d3] libusb: debug [libusb_get_device_list]  
[ 0.002668] [000004d3] libusb: debug [libusb_get_device_descriptor]  
[ 0.002679] [000004d3] libusb: debug [libusb_get_device_descriptor]  
[ 0.002686] [000004d3] libusb: debug [libusb_get_device_descriptor]  
[ 0.002692] [000004d3] libusb: debug [libusb_get_device_descriptor]  
[ 0.002698] [000004d3] libusb: debug [libusb_get_device_descriptor]  
[ 0.002704] [000004d3] libusb: debug [libusb_get_device_descriptor]  
[ 0.002711] [000004d3] libusb: debug [libusb_get_device_descriptor]  
[ 0.002717] [000004d3] libusb: debug [libusb_get_device_descriptor]  
[ 0.002740] [000004d3] libusb: debug [libusb_open] open 3.2
[ 0.002764] [000004d3] libusb: debug [usbi_add_event_source] add fd 7 events 4

Reading device descriptor:
[ 0.002787] [000004d3] libusb: debug [libusb_get_device_descriptor]  
            length: 18
      device class: 0
               S/N: 4
           VID:PID: 0463:FFFF
         bcdDevice: 0202
   iMan:iProd:iSer: 1:2:4
          nb confs: 1

[ 0.002854] [000004d3] libusb: debug [libusb_submit_transfer] transfer 0x428e50
[ 0.002862] [000004d3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.002918] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.002930] [000004d3] libusb: debug [handle_events] event sources modified, reallocating event data
[ 0.002940] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.003280] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.003301] [000004d3] libusb: debug [reap_for_handle] urb type=2 status=-32 transferred=0
[ 0.003311] [000004d3] libusb: debug [handle_control_completion] handling completion status -32
[ 0.003318] [000004d3] libusb: debug [handle_control_completion] unsupported control request
[ 0.003325] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.003335] [000004d3] libusb: debug [usbi_handle_transfer_completion] transfer 0x428e50 has callback 0x410c17
[ 0.003342] [000004d3] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.003357] [000004d3] libusb: debug [libusb_free_transfer] transfer 0x428e50
Reading BOS descriptor: no descriptor

Reading first configuration descriptor:
[ 0.003380] [000004d3] libusb: debug [libusb_get_config_descriptor] index 0
              total length: 34
         descriptor length: 9
             nb interfaces: 1
              interface[0]: id = 0
interface[0].altsetting[0]: num endpoints = 1
   Class.SubClass.Protocol: 03.00.00
       endpoint[0].address: 81
           max packet size: 0008
          polling interval: 14

[ 0.003479] [000004d3] libusb: debug [libusb_kernel_driver_active] interface 0
Kernel driver attached for interface 0: yes

Claiming interface 0...
[ 0.003523] [000004d3] libusb: debug [libusb_claim_interface] interface 0

Reading string descriptors:
[ 0.005176] [000004d3] libusb: debug [libusb_submit_transfer] transfer 0x428f70
[ 0.005185] [000004d3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.005207] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.005220] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.026355] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.026376] [000004d3] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.026381] [000004d3] libusb: debug [handle_control_completion] handling completion status 0
[ 0.026386] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.026391] [000004d3] libusb: debug [usbi_handle_transfer_completion] transfer 0x428f70 has callback 0x410c17
[ 0.026395] [000004d3] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.026400] [000004d3] libusb: debug [libusb_free_transfer] transfer 0x428f70
langid for string 1 returned 4

  00000000  04 00 03 00                                      ....
[ 0.026417] [000004d3] libusb: debug [libusb_submit_transfer] transfer 0x429060
[ 0.026420] [000004d3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.026434] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.026438] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.047765] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.047785] [000004d3] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.047789] [000004d3] libusb: debug [handle_control_completion] handling completion status 0
[ 0.047793] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.047798] [000004d3] libusb: debug [usbi_handle_transfer_completion] transfer 0x429060 has callback 0x410c17
[ 0.047801] [000004d3] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.047806] [000004d3] libusb: debug [libusb_free_transfer] transfer 0x429060
[ 0.047811] [000004d3] libusb: debug [libusb_submit_transfer] transfer 0x429150
[ 0.047813] [000004d3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.047828] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.047833] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.069005] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.069021] [000004d3] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.069026] [000004d3] libusb: debug [handle_control_completion] handling completion status 0
[ 0.069031] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.069037] [000004d3] libusb: debug [usbi_handle_transfer_completion] transfer 0x429150 has callback 0x410c17
[ 0.069041] [000004d3] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.069045] [000004d3] libusb: debug [libusb_free_transfer] transfer 0x429150
langid for string 2 returned 4

  00000000  04 00 03 00                                      ....
[ 0.069058] [000004d3] libusb: debug [libusb_submit_transfer] transfer 0x429240
[ 0.069060] [000004d3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.069072] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.069076] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.090180] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.090206] [000004d3] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.090209] [000004d3] libusb: debug [handle_control_completion] handling completion status 0
[ 0.090212] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.090216] [000004d3] libusb: debug [usbi_handle_transfer_completion] transfer 0x429240 has callback 0x410c17
[ 0.090219] [000004d3] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.090223] [000004d3] libusb: debug [libusb_free_transfer] transfer 0x429240
[ 0.090227] [000004d3] libusb: debug [libusb_submit_transfer] transfer 0x429330
[ 0.090230] [000004d3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.090242] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.090244] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.111467] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.111486] [000004d3] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.111489] [000004d3] libusb: debug [handle_control_completion] handling completion status 0
[ 0.111492] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.111496] [000004d3] libusb: debug [usbi_handle_transfer_completion] transfer 0x429330 has callback 0x410c17
[ 0.111499] [000004d3] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.111503] [000004d3] libusb: debug [libusb_free_transfer] transfer 0x429330
langid for string 4 returned 4

  00000000  04 00 03 00                                      ....
[ 0.111515] [000004d3] libusb: debug [libusb_submit_transfer] transfer 0x429420
[ 0.111518] [000004d3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.111530] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.111532] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.133043] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.133081] [000004d3] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.133085] [000004d3] libusb: debug [handle_control_completion] handling completion status 0
[ 0.133090] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.133096] [000004d3] libusb: debug [usbi_handle_transfer_completion] transfer 0x429420 has callback 0x410c17
[ 0.133100] [000004d3] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.133107] [000004d3] libusb: debug [libusb_free_transfer] transfer 0x429420

[ 0.133119] [000004d3] libusb: debug [libusb_submit_transfer] transfer 0x429510
[ 0.133122] [000004d3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.133142] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.133145] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 1.133134] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.133149] [000004d3] libusb: debug [libusb_cancel_transfer] transfer 0x429510
[ 1.133227] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 1.133237] [000004d3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.133239] [000004d3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 1.133243] [000004d3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.133248] [000004d3] libusb: debug [reap_for_handle] urb type=2 status=-2 transferred=0
[ 1.133251] [000004d3] libusb: debug [handle_control_completion] handling completion status -2
[ 1.133253] [000004d3] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 1.133256] [000004d3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 1.133258] [000004d3] libusb: debug [usbi_handle_transfer_completion] transfer 0x429510 has callback 0x410c17
[ 1.133261] [000004d3] libusb: debug [sync_transfer_cb] actual_length=0
[ 1.133264] [000004d3] libusb: debug [libusb_free_transfer] transfer 0x429510
Reading OS string descriptor: no descriptor

Reading interface association descriptors (IADs) for first configuration:
[ 1.133272] [000004d3] libusb: debug [libusb_get_interface_association_descriptors] IADs for config index 0
    nb IADs: 0

Releasing interface 0...
[ 1.133284] [000004d3] libusb: debug [libusb_release_interface] interface 0
Closing device...
[ 2.803901] [000004d3] libusb: debug [libusb_close]  
[ 2.803910] [000004d3] libusb: debug [usbi_remove_event_source] remove fd 7
[ 2.803918] [000004d3] libusb: debug [libusb_exit] destroying default context
[ 2.803922] [000004d3] libusb: debug [libusb_unref_device] destroy device 2.2
[ 2.803924] [000004d3] libusb: debug [libusb_unref_device] destroy device 2.1
[ 2.803926] [000004d3] libusb: debug [libusb_unref_device] destroy device 1.2
[ 2.803928] [000004d3] libusb: debug [libusb_unref_device] destroy device 1.1
[ 2.803930] [000004d3] libusb: debug [libusb_unref_device] destroy device 4.1
[ 2.803932] [000004d3] libusb: debug [libusb_unref_device] destroy device 3.4
[ 2.803934] [000004d3] libusb: debug [libusb_unref_device] destroy device 3.3
[ 2.803936] [000004d3] libusb: debug [libusb_unref_device] destroy device 3.2
[ 2.803938] [000004d3] libusb: debug [libusb_unref_device] destroy device 3.1
[ 2.803948] [000004d4] libusb: debug [linux_udev_event_thread_main] udev event thread exiting
[ 2.804023] [000004d3] libusb: debug [usbi_remove_event_source] remove fd 4
[ 2.804029] [000004d3] libusb: debug [usbi_remove_event_source] remove fd 3

@masterwishx
Copy link
Author

image

@jimklimov
Copy link

Seems the reply is 4 bytes long, unbothered by being given an 8-byte buffer (just not using all of it).

I wonder how those other programs got the strings though - ignored bogus output and assumed English? Had some other query? There's some other option to return 8/16-bit words instead of just 8-bit we expect here?..

@tormodvolden
Copy link
Contributor

The Linux kernel makes great efforts to workaround buggy devices. In this case, with a broken language identifier, it will assume en_US and request the en_US version of the string descriptor.

If this is important to nut, I would recommend implementing a custom version of libusb_get_string_descriptor_ascii() which falls back to en_US (or simply assumes en_US in the case of Eaton devices).

@masterwishx
Copy link
Author

The Linux kernel makes great efforts to workaround buggy devices. In this case, with a broken language identifier, it will assume en_US and request the en_US version of the string descriptor.

If this is important to nut, I would recommend implementing a custom version of libusb_get_string_descriptor_ascii() which falls back to en_US (or simply assumes en_US in the case of Eaton devices).

@tormodvolden Thanks a lot for your help I think I can close the issue now...

@jimklimov I hope finally we found where the bug was...
If you need test on fixing, I'm still here..
Please confirm I can close issue here.

@jimklimov
Copy link

jimklimov commented Aug 26, 2024

I guess we can at least explore the path. I'm traveling for the bext half a month so not sure when I'd get some quality computer time though.

For the sake of future versions, I hope @arnaudquette-eaton can pass the bug to firmware team. :)

Kudos to @tormodvolden for helping make sense of the bytes and knowing where to find them :)

@tormodvolden
Copy link
Contributor

On the libusb side we should maybe add a warning to make this easier to spot the next time.

@tormodvolden
Copy link
Contributor

@arnaudquette-eaton Do you perform any USB compliance testing on the devices?

tormodvolden added a commit to tormodvolden/libusb that referenced this issue Aug 28, 2024
@tormodvolden tormodvolden linked a pull request Aug 28, 2024 that will close this issue
@tormodvolden
Copy link
Contributor

@aquette You don't have to disclose any individual company's practices :) but I am curious about what manufacturers typically would do. I thought they had to run through some standard compliance tests before they can print the USB logo on their devices. There is for instance a test program at https://www.usb.org/compliancetools#anchor_usb3cv that according to the documentation will check the langid descriptor and string descriptors among other things.

@masterwishx
Copy link
Author

@aquette You don't have to disclose any individual company's practices :) but I am curious about what manufacturers typically would do. I thought they had to run through some standard compliance tests before they can print the USB logo on their devices. There is for instance a test program at https://www.usb.org/compliancetools#anchor_usb3cv that according to the documentation will check the langid descriptor and string descriptors among other things.

I don't think I have any usb logo on my ups 9E2000i only usb port. :)

If for real, as you can see from NUT issue it was not solved for 1.5 years until you helped, however eaton devs was there :(

@arnaudquette-eaton
Copy link

arnaudquette-eaton commented Sep 4, 2024

@masterwishx as an OSS leader and dev, I'm retired for 6 years+
As an Eaton guy, I'd say even more... it's only persistence of vision ;)
And I was the only dev, and mainly not with Eaton cap on!
more seriously, I'm too busy at work, and far away from SW communication for almost a decade.
Still, I do my best to continue supporting my baby NUT... And still have that specific issue in mind

@tormodvolden would need to recheck. Keep in mind that I committed all these USB related things (kernel, libusb, NUT USB driver) 20 years ago... And as for all my OSS benevolent work (despite a potential interest for my employers), once done, I moved to something else...
Side note: that USB firmware dev that I worked with for 23 years (since MGE time) has just retired in June... which doesn't help too. For now, forwarded to the new guy in charge, who's off until Sept. 14th...

@masterwishx
Copy link
Author

@tormodvolden sorry to bother you again as this issue was solved and maybe need to close it ?

But have other issue if it is :
seems i have a lot of nut_libusb_get_interrupt: Connection timed out in debug log and
maybe also affect on networkupstools/nut#2643
or its just closing connection every time for cycle of reading data?

Mostly looks like this :

send_to_all: SETINFO driver.state "quiet"
Sep 27 09:37:30 DaRKNaS usbhid-ups[24218]: [D6:24218] send_to_all: write 29 bytes to socket 16 succeeded (ret=29): SETINFO driver.state "quiet"
Sep 27 09:37:31 DaRKNaS usbhid-ups[24218]: [D5:24218] send_to_all: SETINFO driver.state "updateinfo"
Sep 27 09:37:31 DaRKNaS usbhid-ups[24218]: [D6:24218] send_to_all: write 34 bytes to socket 16 succeeded (ret=34): SETINFO driver.state "updateinfo"
Sep 27 09:37:31 DaRKNaS usbhid-ups[24218]: [D1:24218] upsdrv_updateinfo...
Sep 27 09:37:32 DaRKNaS usbhid-ups[24218]: [D2:24218] nut_libusb_get_interrupt: Connection timed out
Sep 27 09:37:32 DaRKNaS usbhid-ups[24218]: [D1:24218] Got 0 HID objects...
Sep 27 09:37:32 DaRKNaS usbhid-ups[24218]: [D1:24218] Quick update...
Sep 27 09:37:32 DaRKNaS usbhid-ups[24218]: [D4:24218] 

image

@tormodvolden
Copy link
Contributor

@masterwishx Yes, if you have issues with interrupt transfers I would think it is a completely unrelated issue.

@masterwishx
Copy link
Author

@masterwishx Yes, if you have issues with interrupt transfers I would think it is a completely unrelated issue.

Thanks, so it's related to NUT libusb or/and I can test it also with xusb as befor?

@masterwishx
Copy link
Author

@masterwishx Yes, if you have issues with interrupt transfers I would think it is a completely unrelated issue.

i opened issue networkupstools/nut#2644 or i need open here also ?
if you can give some advices for test it will be cool

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
question Technical support, will be closed if deemed not a libusb issue. Please use mailing list.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants