composite devices about usbip-win

[cezuni]

@koudis : usbip-win seems to send a correct packet counts of iso transfer.(Upper verbose my comments were from my mistake) But the linux host denies the iso request generating the log that the count is invalid. This phenomenon has been reported only by @kmvi-dev .

[koudis]

@kmvi-dev
Did you try newer kernel? At least >=4.13? Debian stretch has 4.9. After 4.13 there can be some incompatibility changes between 4.13 and <4.13. (The changes in >=4.13 is not intended to break backward compatibility, but who knows).

The USIP is test on 4.15 (according to readme)

[kmvi-dev]

Thanks, I missed the Linux kernel version to work with the server part.

[kmvi-dev]

Jan, your webcam worked in this functional bundle Windows10 (x64 )client + Linux kernel >=4.15 server ?

[koudis]

I did not test webcam. I had simillar problem with USB HW auth token and kernel >=4.15 solved my issue.
Thats why I suggest to try newer Linux kernel.

Note - you need not only kernel, but linux tools too (for appopriate Linux Kernel). On Ubuntu or other debian based platforms usbip command is bundled as separate .deb package. (so only kernel update did nopt solve my issue with HW Token)

[kmvi-dev]

Thank you. I will check the cameras on Ubuntu, as you advise me

[kmvi-dev]

Hello .
As suggested to me, I changed the kernel version (installed Ubuntu 18.04 and linux-tools-4.18.0.25-generic).
launched a script that many users of the USBIP program know:

#!/bin/sh
PATH=/etc:/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin
bindID='2-1.3'
usbipd -D
usbip bind -b $bindID
usbip attach --remote=localhost --busid=$bindID
sleep 2
usbip detach --port=00

checked the presence of the camera in the list of available devices (Windows 10 (x64))

E:\TestDrv>usbip list -r 192.168.11.249

Exportable USB devices

-192.168.11.249
3-5: Logitech, Inc. : Webcam C170 (046d:082b)
: /sys/devices/pci0000:00/0000:00:14.0/usb3/3-5
: Miscellaneous Device / ? / Interface Association (ef/02/01)
: 0 - Video / Video Control / unknown protocol (0e/01/00)
: 1 - Video / Video Streaming / unknown protocol (0e/02/00)
: 2 - Audio / Control Device / unknown protocol (01/01/00)
: 3 - Audio / Streaming / unknown protocol (01/02/00)
then
E:\TestDrv>usbip attach -r 192.168.11.249 -b 3-5

after play with WindowsCamera.exe.

the result is the same as described at the beginning of this topic 2 days ago
How can I identify a problem because of which composite devices do not work?

[koudis]

@kmvi-dev
Sorry I have no idea.
It seems that USBIP Windows client has problem with composite devices. Like in #25.

[kmvi-dev]

Thank you , Jan . I will study the topic you suggested to me.

[cezuni]

@kmvi-dev : I had tested webcam (Please refer #9) Can I review your debugging logs?

[kmvi-dev]

@cezuni
Yes, of course. What kind of debug logs would you like to receive?

[cezuni]

@kmvi-dev : Sorry, I can look into logs which you had uploaded on google drive. I was confused that the file does not exist. I'll try to inspect it.

[kmvi-dev]

Ок,nothing wrong, thanks

[kmvi-dev]

@cezuni
last log (usbip_vhci driver Windows 10(x64)) for device .Microskope Digital.B006(Genesys Logic)
https://drive.google.com/open?id=1mw6QoN_mto6q-jElyLghrKkMOpr0WYLz

[cezuni]

@kmvi-dev : Did you stop usbip attach command ? IOCTL_USBIP_VHCI_UNPLUG_HARDWARE in first log file implies that detach routine was invoked. Before unplugging, it seems to have been going well. How long did it take for the error to occur?

[kmvi-dev]

@cezani
No. I did not interrupt the process. Interruption occurred after start play with WindowsCamera 10-20 seconds

[cezuni]

No. I did not interrupt the process. Interruption occurred after start play with WindowsCamera 10-20 seconds

Then, it was likely that a forwarding routine did raise an error and detach process proceeded. Can you enable forwarding routine's debugging and share usbip packet forwarding logs ? https://github.com/cezuni/usbip-win/blob/4b2d7cefe506cfdef9deafca94a64d9ed722a560/userspace/lib/usbip_forward.c#L33

Just define macro DEBUG_PDU to enable debuggging.

[kmvi-dev]

@cezuni
yes, of course.

[kmvi-dev]

@cezuni
debug_pdu.log
https://drive.google.com/open?id=1veJaggFhrtl_wPxvDFVABRXJwfLh9krI

[cezuni]

The last log entry in debug_pdu.log shows that -ESHUTDOWN(-108) occurred on server side(stub).

DUMP: RET_SUBMIT,seq:242,devid:0,dir:out,ep:0
  st:-108,al:0,sf:0,#p:0,ec:0

Can you share server-side logs?

[kmvi-dev]

Hi. Of course. Just tell me how.

[kmvi-dev]

The server part is at Debian 9.9, usbip installed from the distribution
https://drive.google.com/open?id=1spFrRozEfSkTe2UCMhC0WGbnFTlHW1y4

[cezuni]

Hi. Of course. Just tell me how.

dmesg ? To view linux kernel logs.
For more verbose debugging logs, # insmod usbip-core.ko usbip_debug_flag=0xffffffff

[kmvi-dev]

@cezuni
dmesg.log ,Sorry to delay to answer
https://drive.google.com/open?id=1_JCaie53Axbj2Vi-CDxFWMHO1tfAjVNG

[cezuni]

dmesg.log ,Sorry to delay to answer

It's not the sorry. :)

[ 1872.490158] usbip-host 3-2: unlinked by a call to usb_unlink_urb()
[ 1872.490186] vhci_hcd: unlink->seqnum 58
[ 1872.490187] vhci_hcd: urb->status -104

Did you install vhci-hcd kernel module? Can you retry after removing vhci-hcd ?
It's very weird..

[kmvi-dev]

@cezuni
yes, I ican repeat.

usbip-core
usbip-host
vhci-hcd
Drivers are added to the / etc / modules file and after restar usbip works with a flash drive and scanner, but does not work with a printer and webcam

[kmvi-dev]

@cezuni
I clarify, you need a dmesg.log from the server with the unloaded driver vhci-hcd?

[cezuni]

I clarify, you need a log from the server with the unloaded driver vhci-hcd?

Yes, sure!!

[kmvi-dev]

@cezuni
https://drive.google.com/open?id=1ZMGc8I96mjXkSsUpZfWt4Hgs445Mj4bM
screenshot from client after rmmod vhci-hcd and start WindowsCamera exe
http://prntscr.com/oayu52

[kmvi-dev]

@cezuni
dmesg was run with param --follow

[cezuni]

Please, share window kernel log and forwarding log. They are same with previous logs?

[kmvi-dev]

so as not to get confused, let's start over.
write down the points please, what to do.
I will remove three drivers from auto loading
usbip-core
usbip-host
vhci-hcd

[kmvi-dev]

@cezuni
and if it's not difficult for you, write what I need to do to get the necessary information for You

[cezuni]

If linux is a usbip server, usbip-core and usbip-host modules shoud be loaded. vhci-hcd module is not required. Your first kernel log had vhci-hcd related entries. But second one does not have those entries.

I found some clues from your second linux kernel log. But DebugView log(I mentioned it as windows kernel log) and debug_pdu.log(I mentioned it as forwarding log) are needed in order to detect an exact problem.

[cezuni]

Bug or problem related logs

[  413.777376] usbip-host 3-2: CMD_SUBMIT: isoc invalid num packets 128
[  413.777382] usbip_core: unknown command
[  413.777385] usbip-host 3-2: recv invalid request
[  413.777527] usbip-host 3-2: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[  413.895707] usbip-host 3-2: reset high-speed USB device number 2 using xhci_hcd
[  414.098661] usbip-host 3-2: device reset

[kmvi-dev]

Ok. Now I’ll upload usb-core and usb-host , and prepare the necessary logs for you.

[kmvi-dev]

@cezuni
to work with the server part usbip I work with a script

[Unit]
Description=USBIPd

[Service]
ExecStart=/scripts/usbipd
Type=oneshot
RemainAfterExit=yes

[Install]
WantedBy=multi-user.target

if the driver vhci-hcd is not loaded, the script does not start

[cezuni]

How about removing vhci_hcd module before testing ?

# rmmod vhci_hcd

[kmvi-dev]

yes
script error
root@debian-vm:/home/iridan# systemctl status usbipd
● usbipd.service - USBIPd
Loaded: loaded (/etc/systemd/system/usbipd.service; disabled; vendor preset:
Active: failed (Result: exit-code) since Fri 2019-07-05 15:14:50 MSK; 11s ago
Process: 1528 ExecStart=/scripts/usbipd (code=exited, status=1/FAILURE)
Main PID: 1528 (code=exited, status=1/FAILURE)

июл 05 15:14:45 debian-vm usbipd[1530]: usbipd: info: connection from 127.0.0.1:
июл 05 15:14:45 debian-vm usbipd[1528]: libusbip: error: udev_device_new_from_su
июл 05 15:14:45 debian-vm usbipd[1528]: usbip: error: open vhci_driver
июл 05 15:14:45 debian-vm usbipd[1528]: usbip: error: query
июл 05 15:14:50 debian-vm usbipd[1528]: libusbip: error: udev_device_new_from_su
июл 05 15:14:50 debian-vm usbipd[1528]: usbip: error: open vhci_driver
июл 05 15:14:50 debian-vm systemd[1]: usbipd.service: Main process exited, code=
июл 05 15:14:50 debian-vm systemd[1]: Failed to start USBIPd.
июл 05 15:14:50 debian-vm systemd[1]: usbipd.service: Unit entered failed state.
июл 05 15:14:50 debian-vm systemd[1]: usbipd.service: Failed with result 'exit-c
lines 1-16/16 (END)...skipping...
● usbipd.service - USBIPd
Loaded: loaded (/etc/systemd/system/usbipd.service; disabled; vendor preset: enabled)
Active: failed (Result: exit-code) since Fri 2019-07-05 15:14:50 MSK; 11s ago
Process: 1528 ExecStart=/scripts/usbipd (code=exited, status=1/FAILURE)
Main PID: 1528 (code=exited, status=1/FAILURE)

июл 05 15:14:45 debian-vm usbipd[1530]: usbipd: info: connection from 127.0.0.1:38800
июл 05 15:14:45 debian-vm usbipd[1528]: libusbip: error: udev_device_new_from_subsystem_sysname failed
июл 05 15:14:45 debian-vm usbipd[1528]: usbip: error: open vhci_driver
июл 05 15:14:45 debian-vm usbipd[1528]: usbip: error: query
июл 05 15:14:50 debian-vm usbipd[1528]: libusbip: error: udev_device_new_from_subsystem_sysname failed
июл 05 15:14:50 debian-vm usbipd[1528]: usbip: error: open vhci_driver
июл 05 15:14:50 debian-vm systemd[1]: usbipd.service: Main process exited, code=exited, status=1/FAILURE
июл 05 15:14:50 debian-vm systemd[1]: Failed to start USBIPd.
июл 05 15:14:50 debian-vm systemd[1]: usbipd.service: Unit entered failed state.
июл 05 15:14:50 debian-vm systemd[1]: usbipd.service: Failed with result 'exit-code'.

[kmvi-dev]

июл 05 15:14:50 debian-vm usbipd[1528]: usbip: error: open vhci_driver

[kmvi-dev]

server on debian 9.9 ,usbip was install from distribution

[kmvi-dev]

@cezuni
what to do next? load vhci-hcd again ?

[cezuni]

Maybe linux usbipd requires vhci_hcd. I'm sorry for bothering you.

Anyway, didn't you unload vhci-hcd when you got second dmesg logs ? However, two dmesg logs seem to be very different.

[kmvi-dev]

Therefore, I suggest we start the process of getting logs from the beginning with you, to avoid confusion :)
load vhci-hcd again and restart the process?

[kmvi-dev]

From widows client
http://prntscr.com/ob0k9r- Screenshot
https://drive.google.com/open?id=1CV9CRG1BNWfpNc5H7BRxSbvY6tzMVkJD -logs
from server debian
https://drive.google.com/open?id=1UQG4SBcbIpnbFXBKBG4_VjFjCQYCPUba

[cezuni]

@kmvi-dev : I'm not sure what's the problem but there's wrong isochronous transfer logs in debug_pdu.log.

DUMP: CMD_SUBMIT,seq:258,devid:10002,dir:in,ep:2
  flags:2,len:60000,sf:0,#p:80,intv:1
  setup: 685316e904e3ffff
  o:0,l:3072,al:0,st:0
  o:3072,l:3072,al:0,st:0
  o:6144,l:3072,al:0,st:0

I think that length should be 3072 * 80(packet count) not 60000. This invalid value may cause iso packet count check to fail in linux kernel. More investigation needed.

[kmvi-dev]

Thanks @cezuni ,You will close the topic?

[cezuni]

You will close the topic?

No.. The issue is not resolved.

I made a patch for testing which adjusts number of iso packets according to transfer buffer length.

iso_n_pkts_patch.txt

This patch is not tested at all, so it may incur BSOD. But I hope that you'll dare to try it.

[kmvi-dev]

Sure, no problem

[kmvi-dev]

@cezuni
files after patch(in build )
https://drive.google.com/open?id=1pBG3A7PAeGuCO8saBJm9rEW8KVi-ITl-
logs
https://drive.google.com/open?id=1klSjSAbxUdIXKRmbRcEM_tnEE6c95Z2e
11:00 (GMT+3)
Sorry, I forgot to add the client driver log. This is a replay process
https://drive.google.com/open?id=1fITRsOmNJyywBsBchAcc69mrcQXYSLM6

[cezuni]

@kmvi-dev : Your usbip failure logs are very different from each other. Last log file(after patch) show that usbip attach had stopped before isochronous transfer started. So sadly, the patched code was not executed. Two or more bugs or problems may exist in your tests.
I'll try to inspect all your logs. And you missed windows kernel log when uploading last logs. Please upload it if the log is available.

[kmvi-dev]

windows kernel log -> usbip-driver.log
https://drive.google.com/open?id=1fITRsOmNJyywBsBchAcc69mrcQXYSLM6

[kmvi-dev]

The testing algorithm is as follows.
on linux station:
stop script usbipd -> systemctl stop usbipd
dmesg --follow> /var/log/dsmeg.log
start script usbipd -> systemctl start usbipd

on windows client station
remove previous driver
installing a new driver
running debugview
usbip attach -r 192.168.11.249 -b 1-2
after connecting to the camera on linux station
WindowsCamera.exe start

[kmvi-dev]

If there is a need, I can repeat the test of changes in the code

[kmvi-dev]

If there is a need, I can repeat the test of changes in the code

@kmvi-dev : I'm not sure what's the problem but there's wrong isochronous transfer logs in debug_pdu.log.

DUMP: CMD_SUBMIT,seq:258,devid:10002,dir:in,ep:2
  flags:2,len:60000,sf:0,#p:80,intv:1
  setup: 685316e904e3ffff
  o:0,l:3072,al:0,st:0
  o:3072,l:3072,al:0,st:0
  o:6144,l:3072,al:0,st:0

I think that length should be 3072 * 80(packet count) not 60000. This invalid value may cause iso packet count check to fail in linux kernel. More investigation needed.

0x60000 = 3072*0x80? (may be hex?)
dbg_to_file(" flags:%x,len:%x,sf:%x,#p:%x,intv:%x\n",
and if it's not difficult , you can comment on the decryption of abbreviations in the pdu.log?
ep:
flags:
sf:
intv:

[cezuni]

Following linux kernel log means that USB disconnection occurred at server side.

[ 5921.394156] usbip-host 1-2: unlinked by a call to usb_unlink_urb()
[ 5921.856881] usbip-host 1-2: usb_set_interface done: inf 3 alt 0
[ 5948.746478] usbip-host 1-2: usb_set_interface done: inf 1 alt 1
[ 5948.750207] usbip-host 1-2: USB disconnect, device number 6
[ 5948.750504] usbip-host 1-2: device removed?
[ 5948.753312] usbip-host 1-2: recv a header, 0

This linux kernel logs means that weird isochronous transfer issued by usbip client(windows)

[  197.523960] usbip-host 1-2: usb_set_interface done: inf 3 alt 0
[  228.281684] usbip-host 1-2: usb_set_interface done: inf 1 alt 1
[  229.470559] usbip-host 1-2: CMD_SUBMIT: isoc invalid num packets 128
[  229.470567] usbip_core: unknown command

For first case, check your USB connection or something other.(not usbip-win related issue)
For second case, we have no such logs generated by a patched vhci driver. You need to do more tests.. 😄

[cezuni]

0x60000 = 3072*0x80? (may be hex?)

You're right!! I'm confused.. It's hex.
The log is not invalid. I should reconsider.. Maybe patched code is useless.. :(

ep: endpoint
flags: flags
sf: start frame
intv: interval

[cezuni]

[ 229.470559] usbip-host 1-2: CMD_SUBMIT: isoc invalid num packets 128

Upper log is generated by following linux kernel code.(drivers/usb/usbip/stub_rx.c)

        if (usb_endpoint_xfer_isoc(epd)) {
                /* validate packet size and number of packets */
                unsigned int maxp, packets, bytes;

                maxp = usb_endpoint_maxp(epd);
                maxp *= usb_endpoint_maxp_mult(epd);
                bytes = pdu->u.cmd_submit.transfer_buffer_length;
                packets = DIV_ROUND_UP(bytes, maxp);

                if (pdu->u.cmd_submit.number_of_packets < 0 ||
                    pdu->u.cmd_submit.number_of_packets > packets) {
                        dev_err(&sdev->udev->dev,
                                "CMD_SUBMIT: isoc invalid num packets %d\n",
                                pdu->u.cmd_submit.number_of_packets);
                        return -1;
                }
                if (dir == USBIP_DIR_OUT)
                        return usb_sndisocpipe(udev, epnum);
                else
                        return usb_rcvisocpipe(udev, epnum);
        }

[kmvi-dev]

Thanks :)

[cezuni]

@kmvi-dev : The detailed usb descriptors of your testing USB device would be helpful. You can get via lsusb -v from linux server while the device is directly attached to linux host.

[koudis]

Just for my info: If I understand correctly the bug is about "bad number_of_packets sent from usbipwin to linux host"?

[kmvi-dev]

@cezuni
I started the USBIP server on Ubuntu 18.04 (kernel version 4.18.0-25-generic), as advised @koudis. Playback from the camera is now possible. But it happens by chance. Sometimes the camera starts up immediately, sometimes you have to run it several times.

[koudis]

@kmvi-dev
It works with or without @cezuni patch? How fast is your network between Server <--> Client? Is the USB camera attached/detached, bind/unbind correctly? (You can see that from usbipd on linux side. If you run as "usbipd -d" it runs in debug mode and you can see if attach command end with success).

[kmvi-dev]

@koudis
on the points :)
1.usb / IP latest version from repository https://github.com/cezuni/usbip-win
2. Network speed -100 Mbps
3. The camera connects to the network using a script that is described at the very beginning of the topic.
4. The connection to the client is always successful, but sometimes when you start WindoswCamera.exe, the playback does not occur and the camera on the server disconnects. You need to restart the script several times on the server so that playback starts on the client

[cezuni]

But it happens by chance. Sometimes the camera starts up immediately, sometimes you have to run it several times.

Can you compare differences of the logs between a successful case and a failed one? The previous observation is that a linux host disconnects usbip connection due to iso packet count mismatch. Was there no such a log on a linux host when a camera was successfully attached?

[kmvi-dev]

@cezuni
Yes of course, but logs I can only prepare for you tomorrow

[kmvi-dev]

@cezuni,@koudis
apologize for the wrong information.
I did not wait for the device to initialize on the client when I run WindowsCamera.exe.

After launching usbip attach -r 192.168.11.249 -b 3-2 I expect about 30 seconds and run WindowsCamera.exe. Playback in this case runs stably.But when playing video there are artifacts. Logs and a screenshot
https://drive.google.com/open?id=1OSz7q5nAUlrMMrUGmeAAOrj6YXn9Q4q4

[cezuni]

@kmvi-dev : Good to hear.. We can almost close the issue. 😄 But 30 seconds waiting is too long. Release build may help to decrease the time. The reason why the camera app fails with ongoing usbip-win session may be investigated in another issue.

[kmvi-dev]

Well :) , I do not mind, close the topic

[mankitty]

@kmvi-dev
Did you try newer kernel? At least >=4.13? Debian stretch has 4.9. After 4.13 there can be some incompatibility changes between 4.13 and <4.13. (The changes in >=4.13 is not intended to break backward compatibility, but who knows).

The USIP is test on 4.15 (according to readme)

Sorry, because of other things, I recently forgot to pay attention to this matter. I tried a kernel above 4.15, but the composite device still doesn't work, thank you