Unrecognised device after Asustor ADM 4.0.0 update

Submitted by mathotp@gmail.com on #1

Hi Guys,

After updating from ADM 3.5 to ADM 4.0.0 VirtualHere dies not work properly anymore. NAS model: AS1004T
While trying to use an MP600 canon printer
I was first getting :

2021-11-13T10:20:08.123371+01:00 Philous-NAS vhusbd[7591]: Error -1 resetting device 0x04a9/0x1718 for capture
2021-11-13T10:20:08.123584+01:00 Philous-NAS vhusbd[7591]: Error binding device 41 [04a9:1718] to connection 4, BIND_ERROR

The after uninstalling and restarting the NAS I'm now getting:

2021-11-13T10:44:40.968026+01:00 Philous-NAS vhusbd[7591]: Executed "" for onReset.04a9.1718
2021-11-13T10:44:40.968123+01:00 Philous-NAS vhusbd[7591]: Device 41 [04a9:1718] BOUND to connection 1
2021-11-13T10:44:41.275029+01:00 Philous-NAS vhusbd[7591]: Executed "" for onReset.04a9.1718
2021-11-13T10:44:42.098524+01:00 Philous-NAS vhusbd[7591]: Executed "" for onReset.04a9.1718
2021-11-13T10:44:42.926166+01:00 Philous-NAS vhusbd[7591]: Executed "" for onReset.04a9.1718
2021-11-13T10:44:43.755522+01:00 Philous-NAS vhusbd[7591]: Executed "" for onReset.04a9.1718
2021-11-13T10:44:46.008970+01:00 Philous-NAS kernel: [ 2460.105025] usbip-host 4-1:1.0: usbip-host: register new device (bus 4 dev 2 ifn 0)
2021-11-13T10:44:46.057623+01:00 Philous-NAS kernel: [ 2460.153259] usblp 4-1:1.1: usblp0: USB Bidirectional printer dev 2 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1718
2021-11-13T10:44:46.083105+01:00 Philous-NAS kernel: [ 2460.182588] usb-storage 4-1:1.2: USB Mass Storage device detected
2021-11-13T10:44:46.118915+01:00 Philous-NAS kernel: [ 2460.214709] scsi13 : usb-storage 4-1:1.2
2021-11-13T10:44:46.141884+01:00 Philous-NAS vhusbd[7591]: Device 41 [04a9:1718] UNBOUND from connection 1
2021-11-13T10:44:46.568884+01:00 Philous-NAS kernel: [ 2460.665061] usb 4-1: lock for reset
2021-11-13T10:44:46.588923+01:00 Philous-NAS kernel: [ 2460.688132] usblp0: removed

Under Windows 10 it clearly say that the device is not recognised as there is no info from the connected device and on Mac OS the device connects and then disconnects no further info.

What is really weird is that the printer has no "name" => Executed "" for onReset.04a9.1718

Not sure is this is a bug from VirtualHere or from ADM itself.

Anyone has an idea ?

Thanks
Phil

Submitted by Michael on Sun, 2021/11/14 - 07:32

#2

It looks like their built-in usbip server is conflicting with virtualhere. Do you have any other usb sharing packages installed on your ASUStore? If so uninstall them?

Submitted by mathotp@gmail.com on Tue, 2021/11/16 - 04:59

#3

Not that I know of, But I do indeed have issues while trying to set the settings back in the NAS setting from IP to shared, I get an error.

Do you think it would be possible to disable or at least stop the USBIP service ?

Submitted by Michael on Tue, 2021/11/16 - 06:27

#4

No i dont know how to uninstall that. Could you try this

In the virtualhere client, right click on the printer and select Custom Event Handler and paste in exactly this line and click ok.

onReset.$VENDOR_ID$.$PRODUCT_ID$=REMOVE

Now try to use it again via virtualhere. Does that resolve the issue?

Submitted by mathotp@gmail.com on Mon, 2021/11/22 - 02:14

#5

Hi Michael,

sorry for the late reply.
removing the productID creates a bind error on the NAS:

2021-11-21T17:12:01.371828+01:00 Philous-NAS vhusbd[7591]: Error -1 resetting device 0x04a9/0x1718 for capture
2021-11-21T17:12:01.372107+01:00 Philous-NAS vhusbd[7591]: Error binding device 41 [04a9:1718] to connection 26, BIND_ERROR

Submitted by Michael on Mon, 2021/11/22 - 10:09

#6

The only thing i can think of is its that the new version of ADM might be auto-suspending the printer. (When a reset returns -1 it means the hardware (printer) itself is not responding propertly, its not related to software)

Im thinking perhaps the ADM 4.0 is making the printer sleep and then when virtualhere goes to grab it, it doesnt wake up properly.

If you know a bit about linux you can disable autosuspend (e.g https://logfile.ch/linux/2017/06/15/disable-usb-autosuspend-linux/) then you could disable that for that port and see if that resolves it. If you dont know linux you might have to open a ticket with asustor support and ask them if there is (or can they add) a configuration setting in ADM to turn off usb power saving

Submitted by mathotp@gmail.com on Mon, 2021/11/22 - 18:26

#7

Hi Michael,

I think its deeper than this, if you check the new logs generated after I restart the vhusbd, you can see the following:

021-11-22T09:03:45.124555+01:00 Philous-NAS kernel: [773994.795389] usb 4-1: reset high-speed USB device number 4 using xhci-hcd
2021-11-22T09:03:45.138437+01:00 Philous-NAS vhusbd[1729]: Device 41 [04a9:1718] BOUND to connection 1
2021-11-22T09:03:45.374528+01:00 Philous-NAS kernel: [773995.045391] usb 4-1: reset high-speed USB device number 4 using xhci-hcd
2021-11-22T09:03:46.044624+01:00 Philous-NAS kernel: [773995.715436] usbip-host 4-1:1.0: usbip-host: register new device (bus 4 dev 4 ifn 0)
2021-11-22T09:03:46.084460+01:00 Philous-NAS kernel: [773995.755232] usblp 4-1:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1718
2021-11-22T09:03:46.114593+01:00 Philous-NAS kernel: [773995.785502] usb-storage 4-1:1.2: USB Mass Storage device detected
2021-11-22T09:03:46.144606+01:00 Philous-NAS kernel: [773995.815934] scsi17 : usb-storage 4-1:1.2
2021-11-22T09:03:46.404572+01:00 Philous-NAS kernel: [773996.076213] usb 4-1: usbfs: process 1748 (vhusbd) did not claim interface 2 before use
2021-11-22T09:03:46.437614+01:00 Philous-NAS kernel: [773996.110344] usb 4-1: usbfs: process 1739 (vhusbd) did not claim interface 2 before use
2021-11-22T09:03:46.464567+01:00 Philous-NAS kernel: [773996.138632] usblp0: removed
2021-11-22T09:03:46.644554+01:00 Philous-NAS kernel: [773996.315425] usb 4-1: reset high-speed USB device number 4 using xhci-hcd
2021-11-22T09:03:46.716399+01:00 Philous-NAS kernel: [773996.337020] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342c0
2021-11-22T09:03:46.716446+01:00 Philous-NAS kernel: [773996.345627] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342ec
2021-11-22T09:03:46.716573+01:00 Philous-NAS kernel: [773996.354239] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705c0
2021-11-22T09:03:46.716590+01:00 Philous-NAS kernel: [773996.362828] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705ec
2021-11-22T09:03:46.716620+01:00 Philous-NAS kernel: [773996.371441] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b680
2021-11-22T09:03:46.716630+01:00 Philous-NAS kernel: [773996.380013] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6ac
2021-11-22T09:03:46.716638+01:00 Philous-NAS kernel: [773996.388583] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6d8
2021-11-22T09:03:46.739840+01:00 Philous-NAS kernel: [773996.410715] usblp 4-1:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1718
2021-11-22T09:03:46.764599+01:00 Philous-NAS kernel: [773996.441375] usblp0: removed
2021-11-22T09:03:46.944605+01:00 Philous-NAS kernel: [773996.615495] usb 4-1: reset high-speed USB device number 4 using xhci-hcd
2021-11-22T09:03:47.006409+01:00 Philous-NAS kernel: [773996.647074] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342c0
2021-11-22T09:03:47.006460+01:00 Philous-NAS kernel: [773996.655697] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342ec
2021-11-22T09:03:47.006470+01:00 Philous-NAS kernel: [773996.664379] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705c0
2021-11-22T09:03:47.006478+01:00 Philous-NAS kernel: [773996.673022] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705ec
2021-11-22T09:03:47.006486+01:00 Philous-NAS kernel: [773996.681646] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b680
2021-11-22T09:03:47.018063+01:00 Philous-NAS kernel: [773996.690278] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6ac
2021-11-22T09:03:47.026820+01:00 Philous-NAS kernel: [773996.699055] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6d8
2021-11-22T09:03:47.045638+01:00 Philous-NAS kernel: [773996.716522] usblp 4-1:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1718
2021-11-22T09:03:47.064594+01:00 Philous-NAS kernel: [773996.738684] usblp0: removed
2021-11-22T09:03:47.246306+01:00 Philous-NAS kernel: [773996.915516] usb 4-1: reset high-speed USB device number 4 using xhci-hcd
2021-11-22T09:03:47.316693+01:00 Philous-NAS kernel: [773996.936645] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342c0
2021-11-22T09:03:47.316745+01:00 Philous-NAS kernel: [773996.945216] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342ec
2021-11-22T09:03:47.316885+01:00 Philous-NAS kernel: [773996.953866] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705c0
2021-11-22T09:03:47.316902+01:00 Philous-NAS kernel: [773996.962476] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705ec
2021-11-22T09:03:47.316912+01:00 Philous-NAS kernel: [773996.971079] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b680
2021-11-22T09:03:47.316920+01:00 Philous-NAS kernel: [773996.979663] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6ac
2021-11-22T09:03:47.316933+01:00 Philous-NAS kernel: [773996.988247] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6d8
2021-11-22T09:03:47.334744+01:00 Philous-NAS kernel: [773997.006993] scsi 17:0:0:0: Direct-Access Canon MP600Storage 0104 PQ: 0 ANSI: 2
2021-11-22T09:03:47.365803+01:00 Philous-NAS kernel: [773997.036686] usblp 4-1:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1718
2021-11-22T09:03:47.414566+01:00 Philous-NAS kernel: [773997.088258] sd 17:0:0:0: Attached scsi generic sg4 type 0
2021-11-22T09:03:47.434596+01:00 Philous-NAS kernel: [773997.107100] sd 17:0:0:0: [sde] Attached SCSI removable disk
2021-11-22T09:03:47.474604+01:00 Philous-NAS kernel: [773997.145663] usblp0: removed
2021-11-22T09:03:47.594613+01:00 Philous-NAS kernel: [773997.265643] usb 4-1: reset high-speed USB device number 4 using xhci-hcd
2021-11-22T09:03:47.686423+01:00 Philous-NAS kernel: [773997.306715] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342c0
2021-11-22T09:03:47.686482+01:00 Philous-NAS kernel: [773997.315428] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342ec
2021-11-22T09:03:47.686492+01:00 Philous-NAS kernel: [773997.324018] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705c0
2021-11-22T09:03:47.686501+01:00 Philous-NAS kernel: [773997.332627] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705ec
2021-11-22T09:03:47.686509+01:00 Philous-NAS kernel: [773997.341246] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b680
2021-11-22T09:03:47.686517+01:00 Philous-NAS kernel: [773997.349898] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6ac
2021-11-22T09:03:47.686524+01:00 Philous-NAS kernel: [773997.358513] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6d8
2021-11-22T09:03:47.798276+01:00 Philous-NAS kernel: [773997.469122] usblp 4-1:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1718
2021-11-22T09:03:47.836613+01:00 Philous-NAS kernel: [773997.509196] usb 4-1: usbfs: process 1739 (vhusbd) did not claim interface 2 before use
2021-11-22T09:03:47.905614+01:00 Philous-NAS kernel: [773997.578263] usb 4-1: usbfs: process 1739 (vhusbd) did not claim interface 2 before use
2021-11-22T09:03:47.994602+01:00 Philous-NAS kernel: [773997.665652] usblp0: removed
2021-11-22T09:03:48.114602+01:00 Philous-NAS kernel: [773997.785519] usb 4-1: reset high-speed USB device number 4 using xhci-hcd
2021-11-22T09:03:48.162881+01:00 Philous-NAS kernel: [773997.826480] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342c0
2021-11-22T09:03:48.162936+01:00 Philous-NAS kernel: [773997.835064] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342ec
2021-11-22T09:03:48.162955+01:00 Philous-NAS kernel: [773997.843735] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705c0
2021-11-22T09:03:48.180183+01:00 Philous-NAS kernel: [773997.852392] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705ec
2021-11-22T09:03:48.180238+01:00 Philous-NAS kernel: [773997.861014] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b680
2021-11-22T09:03:48.197416+01:00 Philous-NAS kernel: [773997.869629] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6ac
2021-11-22T09:03:48.197474+01:00 Philous-NAS kernel: [773997.878239] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6d8
2021-11-22T09:03:48.251382+01:00 Philous-NAS kernel: [773997.922256] usblp 4-1:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1718
2021-11-22T09:03:48.400485+01:00 Philous-NAS kernel: [773998.072764] usb 4-1: usbfs: interface 0 claimed by usbip-host while 'vhusbd' sets config #1
2021-11-22T09:03:48.510964+01:00 Philous-NAS kernel: [773998.183241] usb 4-1: usbfs: interface 0 claimed by usbip-host while 'vhusbd' sets config #1
2021-11-22T09:03:48.564576+01:00 Philous-NAS kernel: [773998.235585] usblp0: removed
2021-11-22T09:03:48.684602+01:00 Philous-NAS kernel: [773998.355467] usb 4-1: reset high-speed USB device number 4 using xhci-hcd
2021-11-22T09:03:48.722807+01:00 Philous-NAS kernel: [773998.386389] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342c0
2021-11-22T09:03:48.722855+01:00 Philous-NAS kernel: [773998.395028] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep c32342ec
2021-11-22T09:03:48.722874+01:00 Philous-NAS kernel: [773998.403643] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705c0
2021-11-22T09:03:48.740027+01:00 Philous-NAS kernel: [773998.412259] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep d1f705ec
2021-11-22T09:03:48.740079+01:00 Philous-NAS kernel: [773998.420855] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b680
2021-11-22T09:03:48.757241+01:00 Philous-NAS kernel: [773998.429466] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6ac
2021-11-22T09:03:48.757292+01:00 Philous-NAS kernel: [773998.438094] xhci-hcd f10f8000.usb3: xHCI xhci_drop_endpoint called with disabled ep dd98b6d8
2021-11-22T09:03:48.784724+01:00 Philous-NAS kernel: [773998.455610] usblp 4-1:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1718
2021-11-22T09:03:48.899744+01:00 Philous-NAS kernel: [773998.572018] usb 4-1: usbfs: interface 0 claimed by usbip-host while 'vhusbd' sets config #1

Checking closer you can see the apparently vhusbd did not claim the device before use:

2021-11-22T09:03:46.404572+01:00 Philous-NAS kernel: [773996.076213] usb 4-1: usbfs: process 1748 (vhusbd) did not claim interface 2 before use

Submitted by Michael on Mon, 2021/11/22 - 18:55

#8

OK thats not good. "xHCI xhci_drop_endpoint called with disabled ep" is a kernel bug actually. E.g https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1371233

Can you type

uname -a

paste the output here

The "did not claim interface" message is fine, its not a problem.

Submitted by mathotp@gmail.com on Mon, 2021/11/22 - 20:32

#9

Linux Philous-NAS 3.10.70 #1 SMP Fri Nov 5 00:31:58 CST 2021 armv7l GNU/Linux

Submitted by Michael on Mon, 2021/11/22 - 21:04

#10

Ok yeah thats way out of date and i suspect has that USB 3 bug... you will need to either go back to 3.5 ADM or ask asus to fix that linux bug with a patch.

Submitted by mathotp@gmail.com on Mon, 2021/11/22 - 21:10

#11

yeah seen that bug in 2014....
Not sure why they use a so old version of Linux.
I opened a bug with them just now.

I'm unable to go back to 3.5, according to them once going forward you can't go back in version without screwing up your arrays....

Well Michael, thank you very much for your help on this.
have a great day