Bug 235625

Summary: Repeated excessive logging about unsuccessful port reset during device enumeration
Product: Base System Reporter: Max <maxsteciuk>
Component: usbAssignee: freebsd-usb mailing list <usb>
Status: In Progress ---    
Severity: Affects Only Me CC: hselasky
Priority: --- Keywords: patch
Version: CURRENT   
Hardware: amd64   
OS: Any   
Attachments:
Description Flags
Simple patch for decreasing log level
none
Patch for implementing simple log throttling of the message
none
Patch for implementing simple log throttling of the message
none
Patch for log message throttling with lower threshold none

Description Max 2019-02-09 20:22:20 UTC
Since FreeBSD 12 build around last summer it was noticed the syslog was flooded with the following messages
>>>Jan 29 20:18:44 kernel: uhub_reattach_port: giving up port reset - device vanished

Although the log message is displayed the USB devices and hubs are functional: successfully connected and working.


The following sysctl configuration  helps to get rid of excessive logging but the downside that certain USB devices (e.g. Create SoundBlaster) are not even getting recognized by USB hub controller.

>>>hw.usb.disable_enumeration=1


As a quick solution I decreased  log level for the message from 0 to 1 so that at least to reduce log noise. 
Here is a small proposed patch for decreasing log level: https://github.com/trueos/trueos/pull/283/files


As a more elaborate solution I was thinking about possibility to implement log throttling for this warning so it logs a  suficient number of times to bring to attention but not inifinitely.

Another question is  whether this is a symptom of a larger problem: is something broken (e.g. sys/dev/usb/usb_hub.c , /sys/dev/usb_device.c)  or not functioning as expected...


Thanks,
Max
Comment 1 Hans Petter Selasky freebsd_committer 2019-02-09 21:11:59 UTC
Patch looks good to me. Will look more at it on Monday.

--HPS
Comment 2 Max 2019-02-10 17:56:09 UTC
Created attachment 201900 [details]
Simple patch for decreasing log level

Please find a simple patch which decreases log level of the message by 1

Thanks,
Max
Comment 3 Max 2019-02-10 17:57:56 UTC
Created attachment 201901 [details]
Patch for implementing simple log throttling of the message

Please find  the alternative patch for throttling the log message attached.

Thanks,
Max
Comment 4 Max 2019-02-10 18:00:32 UTC
Created attachment 201902 [details]
Patch for implementing simple log throttling of the message

Corrected the diff in the second patch

Thanks,
Max
Comment 5 Max 2019-02-10 21:14:55 UTC
Created attachment 201906 [details]
Patch for log message throttling with lower threshold

Please find the patch for the mentioned log message throttling with a lower maximum threshold attached

So these  are three versions of the patch depending how important the message is.

Thanks,
Max
Comment 6 Hans Petter Selasky freebsd_committer 2019-02-15 09:30:34 UTC
> Since FreeBSD 12 build around last summer it was noticed the syslog was flooded > with the following messages
>>>Jan 29 20:18:44 kernel: uhub_reattach_port: giving up port reset - device vanished


Can you enable:

sysctl hw.usb.uhub.debug=17

Then collect dmesg while these prints are happening.

It is likely a bug somewhere else we need to fix.

--HPS
Comment 7 Max 2019-02-18 21:34:22 UTC
Hello 
Here is  captured syslog snippet with the message. It appears after uhub_read_port_status call.
The below conditional expects either right-most bit to be set for port_change or unset for port_status.
As per log snippet wPortStatus = 0x07fb and wPortChange = 0x00fb which seem to satisfy the condition for the error message...`

>>>                if ((sc->sc_st.port_change & UPS_C_CONNECT_STATUS) ||
>>>                    (!(sc->sc_st.port_status & UPS_CURRENT_CONNECT_STATUS))) {



>>>Feb 18 16:17:48  kernel: uhub_reattach_port: Port 3 is in Host Mode
>>>Feb 18 16:17:49  kernel: usb_needs_explore: 
>>>Feb 18 16:17:49  kernel: uhub_read_port_status: port 3, wPortStatus=0x07fb, wPortChange=0x00fb, err=USB_ERR_NORMAL_COMPLETION
>>>Feb 18 16:17:49  kernel: uhub_reattach_port: giving up port reset - device vanished
>>>Feb 18 16:17:49  kernel: uhub_suspend_resume_port: port 3
>>>Feb 18 16:17:49  kernel: uhub_read_port_status: port 3, wPortStatus=0x07fb, wPortChange=0x00fb, err=USB_ERR_NORMAL_COMPLETION
>>>Feb 18 16:17:49  kernel: uhub_suspend_resume_port: suspended=0


Please let me know if more information is needed

Thanks,
Max
Comment 8 Max 2019-02-18 21:37:51 UTC
Also there is the following event seen a few seconds later for the port in the snippet:

>>>Feb 18 16:16:44  kernel: uhub_explore: Overcurrent on port 3.
>>>Feb 18 16:16:44  kernel: uhub_reattach_port: reattaching port 3

Thanks,
Max