Bug 240201 - smsc floods console with warning messages "Failed to read register 0x114" and "MII is busy"
Summary: smsc floods console with warning messages "Failed to read register 0x114" and...
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: arm (show other bugs)
Version: CURRENT
Hardware: arm64 Any
: --- Affects Some People
Assignee: freebsd-arm mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-08-29 21:46 UTC by iz-rpi03
Modified: 2019-09-08 12:28 UTC (History)
1 user (show)

See Also:


Attachments
Start of panic stack backtrace (641.63 KB, image/png)
2019-09-08 11:58 UTC, iz-rpi03
no flags Details
Somewhere in the middle of panic stack backtrace (894.50 KB, image/png)
2019-09-08 11:59 UTC, iz-rpi03
no flags Details
End of the panic stack backtrace (802.73 KB, image/png)
2019-09-08 12:00 UTC, iz-rpi03
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description iz-rpi03 2019-08-29 21:46:32 UTC
In some rare to repoduce circumstances the smsc driver starts flooding the
console and syslog with

% Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
% Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: MII is busy

messages. This seems to be an old flaw
  https://lists.freebsd.org/pipermail/freebsd-arm/2015-July/011970.html
which is also seen by other people
 https://forums.freebsd.org/threads/smsc0-problem-in-raspberry-pi1-b.69936/
recently.

Now it looks like I am able to reproduce the needed circumstances.

It is a RaspberryPI 3B, running a CURRENT GENERIC-NODEBUG at r351477,
with a mirrored ZFS root pool.

When trying to write around 2.2GByte in several files from the network into
the filesystem those smsc warning messages show up.

make installkernel, installworld, mergemaster or building and installing
something from ports, e.g. python, does not trigger the warning messages.

The system seems to stay somehow responsible, as the warnings get logged
into /var/log/messages, but the USB keyboard is dead.

At the moment it is possible to let the system as it is to aid debugging.


Some additional information:

# zpool status
...
        NAME           STATE     READ WRITE CKSUM
        rootpool       ONLINE       0     0     0
          mirror-0     ONLINE       0     0     0
            mmcsd0s2a  ONLINE       0     0     0
            da0s2a     ONLINE       0     0     0

errors: No known data errors
# 

The beginning of one flooding:
Aug 23 20:43:43 rpi3-b ....
Aug 23 22:00:55 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:00:55 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:00:55 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:00:55 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:00:55 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:00:55 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:00:55 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:00:55 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:00:55 rpi3-b kernel: (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 01 24 d3 b8 00 00 80 00 
Aug 23 22:00:55 rpi3-b kernel: (da0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
Aug 23 22:00:55 rpi3-b kernel: (da0:umass-sim0:0:0:0): Retrying command, 3 more tries remain
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:01:34 rpi3-b kernel: ue0: link state changed to DOWN
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: MII is busy
Aug 23 22:01:34 rpi3-b kernel: smsc0: error: usb error on tx: USB_ERR_TIMEOUT
Aug 23 22:01:34 rpi3-b kernel: (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 01 24 d3 b8 00 00 80 00 
Aug 23 22:01:34 rpi3-b kernel: (da0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
Aug 23 22:01:34 rpi3-b kernel: (da0:umass-sim0:0:0:0): Retrying command, 2 more tries remain
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 23 22:01:34 rpi3-b kernel: smsc0: warning: MII is busy

Here is one from today:
Aug 29 10:22:37 rpi3-b ...
Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:09:48 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:09:48 rpi3-b kernel: (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 00 bc 4b 90 00 00 80 00 
Aug 29 16:09:48 rpi3-b kernel: (da0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
Aug 29 16:09:48 rpi3-b kernel: (da0:umass-sim0:0:0:0): Retrying command, 3 more tries remain
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:10:22 rpi3-b kernel: ue0: link state changed to DOWN
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:10:22 rpi3-b kernel: smsc0: error: usb error on tx: USB_ERR_TIMEOUT
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: Failed to read register 0x114
Aug 29 16:10:22 rpi3-b kernel: smsc0: warning: MII is busy
Aug 29 16:10:22 rpi3-b kernel: (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 00 bc 4b 90 00 00 80 00 
Aug 29 16:10:22 rpi3-b kernel: (da0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
Aug 29 16:10:22 rpi3-b kernel: (da0:umass-sim0:0:0:0): Retrying command, 2 more tries remain

Best regards, Ralf
Comment 1 Bob Bishop 2019-08-30 11:02:58 UTC
I've seen behaviour like this on an RPi B when the power supply isn't up to the job. I think the common denominator is disruption of the USB stack.
Comment 2 iz-rpi03 2019-08-30 18:51:24 UTC
(In reply to Bob Bishop from comment #1)
The RPi3 B is powered by an original power supply for an RPI3 B.

Plugged in the USB ports are the keyboard and the low profile single port
SD card reader. Also the ethernet and HDMI interfaces are in use.

A power meter shows 2.0 W going into the power supply.
2.1 W if the keyboard's num-lock LED is in use.

So I think there is still enough power available to rule out the power supply.
Comment 3 iz-rpi03 2019-09-08 11:58:09 UTC
Created attachment 207281 [details]
Start of panic stack backtrace

Trying to repoduce the problem with a GENERIC kernel, I get a panic which
stack backtrace consists of more lines than fit on the screen.

With the panic I lost the USB keyboards console input, so I am unable to give
the debugger any commands.

So I make a movie of the panic and took three screenshots.
a) contains the cause of the panic and the start of the stack backtrace.
b) is somewhere in the middle of the backtrace
c) contains the end of the backtrace with the debigger prompt.
Comment 4 iz-rpi03 2019-09-08 11:59:42 UTC
Created attachment 207282 [details]
Somewhere in the middle of panic stack backtrace
Comment 5 iz-rpi03 2019-09-08 12:00:24 UTC
Created attachment 207283 [details]
End of the panic stack backtrace
Comment 6 iz-rpi03 2019-09-08 12:28:45 UTC
The attached screenshots show a panic occuring with a GENERIC r352023 kernel
while tyring to reproduce the problem.

I also did some investigation what happend to older reports of
"smsc0: warning: Failed to read register 0x114 / smsc0: warning: MII is busy"
kernel messages. It looks like those got fixed in base r288447
(review D3722) but removed/ifdef'd out during the transfer to ARM_INTRNG
(e.g. base r296825, base r297581). If those fixes showed up at an other
place in ARM_INTRNG I missed them, sorry.


Maybe the following is related to the smsc-problem, may be it is not.
But it is also related to the pmap as well as the panic.

Without panicing, the same kernel informs about a lock order reversal.

Password:lock order reversal:
 1st 0xfffffd0000cf4a80 abd_chunk (UMA zone) @ /usr/src/sys/vm/uma_core.c:4232
 2nd 0xffff00000121d728 pmap (pmap) @ /usr/src/sys/arm64/arm64/pmap.c:5819
stack backtrace:
#0 0xffff0000004668e4 at witness_debugger+0x64
#1 0xffff0000003dfca4 at __mtx_lock_flags+0xb0
#2 0xffff0000007346e0 at pmap_fault+0x1bc
#3 0xffff000000736520 at data_abort+0xc0
#4 0xffff00000073635c at do_el1h_sync+0x128
#5 0xffff00000071c074 at handle_el1h_sync+0x74
#6 0xffff0000006b6e04 at uma_dbg_free+0x50
#7 0xffff0000006b5ed8 at uma_zfree_arg+0x13c
#8 0xffff0000015d6510 at abd_free+0xc0
#9 0xffff0000015da314 at arc_hdr_free_pabd+0x94
#10 0xffff0000015e15a0 at arc_write+0x1f0
#11 0xffff0000015f6ab4 at dbuf_write+0x638
#12 0xffff0000015f509c at dbuf_sync_indirect+0x2b0
#13 0xffff0000015f4d6c at dbuf_sync_list+0xa4
#14 0xffff0000015f50d0 at dbuf_sync_indirect+0x2e4
#15 0xffff0000015f4d6c at dbuf_sync_list+0xa4
#16 0xffff0000015f50d0 at dbuf_sync_indirect+0x2e4
#17 0xffff0000015f4d6c at dbuf_sync_list+0xa4

Last login: Sun Sep  8 11:22:45 on ttyv0