Re: USV control with repeated USB disconnects

From: Frank Behrens <frank_at_harz2022.behrens.de>
Date: Tue, 27 Sep 2022 19:11:19 UTC
Hans Petter,

thank you very much for your support! With your hints I could connect my 
USV.

Am 27.09.2022 um 19:41 schrieb Hans Petter Selasky:
> sysctl hw.usb.uhub.debug=15
>
> This will show if the device initiates the disconnect or not.

I could not read the disconnect reason from the log (if interested there 
is also a full usb dump in the debug log archive mentioned in my 1st email):
Sep 27 19:53:08 <kern.crit> moon kernel: ugen6.2: <CPS VP1200ELCD> at usbus6
Sep 27 19:53:09 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe008cefadb0
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028cc000 addr=1
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0303, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe00841c4db0
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028ce000 addr=1
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe008cd64db0
Sep 27 19:53:09 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe000ff5fdb0
Sep 27 19:53:09 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe0083e9bdb0
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:09 <kern.crit> moon syslogd: last message repeated 1 times
Sep 27 19:53:09 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028cb000 addr=1
Sep 27 19:53:09 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028d4000 addr=1
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff80002912000 addr=1
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe0083d00db0
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe008d090cd8
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:09 <kern.crit> moon syslogd: last message repeated 1 times
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028c9000 addr=1
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028d3000 addr=1
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 3, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 4, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 5, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 6, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe0084031cd8
Sep 27 19:53:09 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028cd000 addr=1
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 3, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 4, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 5, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:09 <kern.crit> moon kernel: uhub_read_port_status: port 6, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe008cefadb0
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028cc000 addr=1
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0303, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe00841c4db0
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028ce000 addr=1
Sep 27 19:53:13 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe000ff5fdb0
Sep 27 19:53:13 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe0083e9bdb0
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe008cd64db0
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe0083d00db0
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:13 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028d4000 addr=1
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:13 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028d3000 addr=1
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff80002912000 addr=1
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028cb000 addr=1
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe0084031cd8
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe008d090cd8
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028cd000 addr=1
Sep 27 19:53:13 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028c9000 addr=1
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 3, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 4, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 5, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 6, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 3, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 4, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 5, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:13 <kern.crit> moon kernel: uhub_read_port_status: port 6, 
wPortStatus=0x0500, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:16 <kern.crit> moon kernel: usb_needs_explore:
Sep 27 19:53:16 <kern.crit> moon kernel: usb_bus_powerd: 
bus=0xfffffe008cefadb0
Sep 27 19:53:16 <kern.crit> moon kernel: usb_bus_powerd: Recomputing 
power masks
Sep 27 19:53:16 <kern.crit> moon kernel: uhub_explore: 
udev=0xfffff800028cc000 addr=1
Sep 27 19:53:16 <kern.crit> moon kernel: uhub_read_port_status: port 1, 
wPortStatus=0x0100, wPortChange=0x0000, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:16 <kern.crit> moon kernel: uhub_read_port_status: port 2, 
wPortStatus=0x0100, wPortChange=0x0003, err=USB_ERR_NORMAL_COMPLETION
Sep 27 19:53:16 <kern.crit> moon kernel: uhub_reattach_port: reattaching 
port 2
Sep 27 19:53:16 <kern.crit> moon kernel: ugen6.2: <CPS VP1200ELCD> at 
usbus6 (disconnected)


> Please also read this thread:
> "Flickering connection to UPS (again, but now I'm sure it is Ok under 
> Windows)" on this list.
In this thread is the same behavior described. With these hints I could 
connect the NUT driver and the usb device did not disconnect further.

To record the solution:
1. I don't know the reason of usb disconnect on OS level.
2. The nut/usbhid-ups driver does not use 'root' permissions, even when 
started as this user. It switches by default to 'uucp'.
3. With some permission changes I could connect the nut/usbhid-ups 
driver during the time the device was visible (devfs rules to enable 
access for 'uucp' to usb device).

These articles brought me closer to the solution:
https://forums.freebsd.org/threads/nut-port-configuration-no-such-file.35205/
https://thr3ads.net/nut-upsuser/2012/12/2163459-Blazer_usb-Permissions-problem-Input-output-error

Thanks again for your fast und useful help!
Best regards,
    Frank
-- 

Frank Behrens
Osterwieck, Germany