Bug 235625 - Repeated excessive logging about unsuccessful port reset during device enumeration
Summary: Repeated excessive logging about unsuccessful port reset during device enumer...
Status: In Progress
Alias: None
Product: Base System
Classification: Unclassified
Component: usb (show other bugs)
Version: CURRENT
Hardware: amd64 Any
: --- Affects Only Me
Assignee: freebsd-usb mailing list
URL:
Keywords: patch
Depends on:
Blocks:
 
Reported: 2019-02-09 20:22 UTC by Max
Modified: 2019-07-14 21:03 UTC (History)
1 user (show)

See Also:


Attachments
Simple patch for decreasing log level (424 bytes, patch)
2019-02-10 17:56 UTC, Max
no flags Details | Diff
Patch for implementing simple log throttling of the message (1.01 KB, patch)
2019-02-10 17:57 UTC, Max
no flags Details | Diff
Patch for implementing simple log throttling of the message (1022 bytes, patch)
2019-02-10 18:00 UTC, Max
no flags Details | Diff
Patch for log message throttling with lower threshold (1.23 KB, patch)
2019-02-10 21:14 UTC, Max
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
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
Comment 9 Max 2019-07-14 21:03:01 UTC
Hello,

FYI: The symptoms of the issue still keep occurring on the latest *FreeBSD-13.0-CURRENT* such as extremely excessive logging about USB port status

Could you please let me know whether you found something on your side?

Thanks
Max