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 (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-02-09 20:22 UTC by Max
Modified: 2022-12-30 10:08 UTC (History)
2 users (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 freebsd_triage 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 freebsd_triage 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
Comment 10 Max 2020-03-01 23:18:11 UTC
Hello all
Sorry for delay
It appeared that excessive logging came out because of USB device (keyboard in my case) which was connected to the machine via USB hub (Dell monitor built-in). If I am not using that USB hub then the syslog is clean

By the way logging appeared on 12.1-STABLE as well


Thanks
Max
Comment 11 Graham Perrin freebsd_committer freebsd_triage 2022-12-29 15:59:22 UTC
Triage: 

* the patch keyword is deprecated

* helasky@ would you like to take the bug? 

In progress (status) normally applies only where assignment is personal; usb@ is nobody, not a person.

Thanks
Comment 12 Graham Perrin freebsd_committer freebsd_triage 2022-12-30 10:08:25 UTC
For clarity, re: comment #11

> usb@ is nobody, not a person.

Sorry, I meant not _one_ person. 

No-one in particular. 

It's the email list – with a '(Nobody)' representation here in Bugzilla, which I can't change. 

----

Also, from a handful of reports, I'm aware that suggested criteria, for 'In progress', do not suit all workflows. <https://wiki.freebsd.org/Bugzilla/DosAndDonts#DON.27TS> is updated accordingly. #freebsd-bugs in Libera Chat for anyone who'd like to discuss, thanks.