I have some UART logs captured of a shutdown, reboot, and poweron. This is from an MCM Gen2 running Fox’s DSM firmware. It looks like the shutdown/reboot isn’t completing due to these SMI timeouts, which look related to the ethernet driver. Lets take a look:
admin@toasteroven:/$ [ 205.409900] mvEthPhyRegRead: SMI busy timeout [ 205.415194] mvEthPhyRegRead: SMI busy timeout [ 205.420468] mvEthPhyRegRead: SMI busy timeout [ 205.425749] mvEthPhyRegRead: SMI busy timeout [ 205.842192] mvEthPhyRegRead: SMI busy timeout [ 205.847469] mvEthPhyRegRead: SMI busy timeout [ 205.852757] mvEthPhyRegRead: SMI busy timeout [ 205.858031] mvEthPhyRegRead: SMI busy timeout [ 206.410940] mvEthPhyRegRead: SMI busy timeout [ 206.416238] mvEthPhyRegRead: SMI busy timeout [ 206.421512] mvEthPhyRegRead: SMI busy timeout [ 206.426792] mvEthPhyRegRead: SMI busy timeout [ 207.411894] mvEthPhyRegRead: SMI busy timeout [ 207.417187] mvEthPhyRegRead: SMI busy timeout [ 207.422467] mvEthPhyRegRead: SMI busy timeout [ 207.427740] mvEthPhyRegRead: SMI busy timeout [ 208.412923] mvEthPhyRegRead: SMI busy timeout [ 208.418200] mvEthPhyRegRead: SMI busy timeout [ 208.423488] mvEthPhyRegRead: SMI busy timeout [ 208.428763] mvEthPhyRegRead: SMI busy timeout [ 209.413564] mvEthPhyRegRead: SMI busy timeout [ 209.418841] mvEthPhyRegRead: SMI busy timeout [ 209.424134] mvEthPhyRegRead: SMI busy timeout [ 209.429407] mvEthPhyRegRead: SMI busy timeout [ 210.413797] mvEthPhyRegRead: SMI busy timeout [ 210.419074] mvEthPhyRegRead: SMI busy timeout [ 210.424365] mvEthPhyRegRead: SMI busy timeout [ 210.429639] mvEthPhyRegRead: SMI busy timeout sudo[ 211.414799] mvEthPhyRegRead: SMI busy timeout [ 211.420077] mvEthPhyRegRead: SMI busy timeout [ 211.425369] mvEthPhyRegRead: SMI busy timeout [ 211.430643] mvEthPhyRegRead: SMI busy timeout [ 211.873774] mvEthPhyRegRead: SMI busy timeout [ 211.879051] mvEthPhyRegRead: SMI busy timeout [ 211.884346] mvEthPhyRegRead: SMI busy timeout [ 211.889620] mvEthPhyRegRead: SMI busy timeout [ 212.415826] mvEthPhyRegRead: SMI busy timeout [ 212.421103] mvEthPhyRegRead: SMI busy timeout [ 212.426398] mvEthPhyRegRead: SMI busy timeout [ 212.431672] mvEthPhyRegRead: SMI busy timeout s[ 213.416825] mvEthPhyRegRead: SMI busy timeout [ 213.422122] mvEthPhyRegRead: SMI busy timeout [ 213.427397] mvEthPhyRegRead: SMI busy timeout [ 213.432680] mvEthPhyRegRead: SMI busy timeout hut[ 214.417826] mvEthPhyRegRead: SMI busy timeout [ 214.423123] mvEthPhyRegRead: SMI busy timeout [ 214.428398] mvEthPhyRegRead: SMI busy timeout [ 214.433678] mvEthPhyRegRead: SMI busy timeout down -[ 215.418052] mvEthPhyRegRead: SMI busy timeout [ 215.423346] mvEthPhyRegRead: SMI busy timeout [ 215.428620] mvEthPhyRegRead: SMI busy timeout [ 215.433902] mvEthPhyRegRead: SMI busy timeout h now[ 216.419058] mvEthPhyRegRead: SMI busy timeout [ 216.424352] mvEthPhyRegRead: SMI busy timeout [ 216.429625] mvEthPhyRegRead: SMI busy timeout [ 216.434906] mvEthPhyRegRead: SMI busy timeout [ 217.420032] mvEthPhyRegRead: SMI busy timeout [ 217.425326] mvEthPhyRegRead: SMI busy timeout [ 217.430600] mvEthPhyRegRead: SMI busy timeout [ 217.435878] mvEthPhyRegRead: SMI busy timeout
[ 217.903459] mvEthPhyRegRead: SMI busy timeout [ 217.908777] mvEthPhyRegRead: SMI busy timeout [ 217.914071] mvEthPhyRegRead: SMI busy timeout [ 217.919345] mvEthPhyRegRead: SMI busy timeout Password: [ 218.421088] mvEthPhyRegRead: SMI busy timeout [ 218.426386] mvEthPhyRegRead: SMI busy timeout [ 218.431660] mvEthPhyRegRead: SMI busy timeout [ 218.436941] mvEthPhyRegRead: SMI busy timeout [ 219.422078] mvEthPhyRegRead: SMI busy timeout [ 219.427354] mvEthPhyRegRead: SMI busy timeout [ 219.432641] mvEthPhyRegRead: SMI busy timeout [ 219.437914] mvEthPhyRegRead: SMI busy timeout
[ 220.422327] mvEthPhyRegRead: SMI busy timeout [ 220.427604] mvEthPhyRegRead: SMI busy timeout [ 220.432892] mvEthPhyRegRead: SMI busy timeout [ 220.438165] mvEthPhyRegRead: SMI busy timeout
Broadcast message from admin@toasteroven (/dev/console) at 16:03 ...
The system is going down for halt NOW! admin@toasteroven:/$ [ 220.669708] init: synonetd main process (1604) killed by TERM signal [ 220.681509] init: synostoraged main process (4151) terminated with status 15 [ 220.704596] init: hotplugd main process (4578) killed by TERM signal [ 220.738189] init: smbd main process (6056) killed by TERM signal [ 220.766097] init: nmbd main process (6538) killed by TERM signal [ 220.790026] init: synortc main process (6806) terminated with status 255 System is going to poweroff. [ 221.692336] init: Disconnected from D-Bus system bus [ 231.381319] md2: detected capacity change from 1995461165056 to 0 [ 231.387478] md: md2: set sda3 to auto_remap [0] [ 231.392040] md: md2 stopped. [ 231.394938] md: unbind<sda3> [ 231.452027] md: export_rdev(sda3) [ 231.458897] md3: detected capacity change from 1995461165056 to 0 [ 231.465045] md: md3: set sdb3 to auto_remap [0] [ 231.469593] md: md3 stopped. [ 231.472496] md: unbind<sdb3> [ 231.532025] md: export_rdev(sdb3) [ 233.048548] md: md0 in immediate safe mode [ 233.048570] md: md1 in immediate safe mode [ 233.057225] init: tty main process (4593) killed by KILL signal [ 233.063354] init: skip respawn tty during shutdown [ 233.082260] init: dhcp-client (eth0) main process (3651) killed by KILL signal [ 233.396524] EXT4-fs (md0): re-mounted. Opts: (null) [ 234.501446] sd 1:0:0:0: [sdb] Synchronizing SCSI cache [ 234.506723] sd 1:0:0:0: [sdb] Stopping disk [ 234.922125] sd 0:0:0:0: [sda] Synchronizing SCSI cache [ 234.927374] sd 0:0:0:0: [sda] Stopping disk [ 235.342429] xhci-hcd f10f8000.usb3: remove, state 1 [ 235.347336] usb usb4: USB disconnect, device number 1 [ 235.352643] xhci-hcd f10f8000.usb3: USB bus 4 deregistered [ 235.358161] xhci-hcd f10f8000.usb3: remove, state 1 [ 235.363070] usb usb3: USB disconnect, device number 1 [ 235.368357] xhci-hcd f10f8000.usb3: USB bus 3 deregistered [ 235.373890] xhci-hcd f10f0000.usb3: remove, state 1 [ 235.378791] usb usb2: USB disconnect, device number 1 [ 235.384047] xhci-hcd f10f0000.usb3: USB bus 2 deregistered [ 235.389557] xhci-hcd f10f0000.usb3: remove, state 1 [ 235.394468] usb usb1: USB disconnect, device number 1 [ 235.399732] xhci-hcd f10f0000.usb3: USB bus 1 deregistered [ 235.406029] Shutting Down Marvell Ethernet Driver [ 235.411652] mvEthPhyRegWrite: SMI busy timeout [ 235.417016] mvEthPhyRegWrite: SMI busy timeout [ 235.422380] mvEthPhyRegWrite: SMI busy timeout [ 235.426850] Power down.
Here are my thoughts and observations:
- Those SMI busy timeouts are always popping up. Others have reported seeing them flodding the dmesg output. They flood out the UART connection because that’s where all the dmesg entries go.
- The shutdown actually begins after it says “The system is going down for halt NOW!”. The SMI timeout messages end there, and processes are starting to get terminated. I see samba getting killed, and usb devices getting disconnected. And disks flushing and sopping. Last step is to shutdown the Marvel Ethernet Driver. Three SMI busy timeout messages appear. Then the final message is Power down.
- I would say the SMI busy timeouts are related to the Ethernet driver. Note that I don’t have the ethernet actually connected in this case.
- Not shown above, but booting takes ~35 seconds according to the timestamps. At that point I can log in with my admin account, but ~30 seconds later I first receive an SMI read-valid timeout. I’ll post a snippit below. After that it seems all the messages are about it being busy.
[ 32.579067] EXT4-fs (dm-3): mounted filesystem with writeback data mode. Opts: usrjquota=aquota.user,grpjquota=aquota.group,jqfmt=vfsv0,data=writeback,oldalloc [ 32.766539] EXT4-fs (dm-1): recovery complete [ 32.787407] EXT4-fs (dm-1): mounted filesystem with writeback data mode. Opts: usrjquota=aquota.user,grpjquota=aquota.group,jqfmt=vfsv0,data=writeback,oldalloc [ 33.628329] ata2.00: configured for UDMA/133 [ 33.632695] ata2: EH complete [ 33.636031] ata1.00: configured for UDMA/133 [ 33.640336] ata1: EH complete [ 33.694184] synobios_ioctl: un-defined ioctl number c0044b25 [ 34.167884] ehci-pci: EHCI PCI platform driver [ 34.382957] usbcore: registered new interface driver usb-storage [ 34.451668] usbcore: registered new interface driver usblp [ 34.653031] usbcore: registered new interface driver usbhid [ 34.658633] usbhid: USB HID core driver toasteroven login: [ 37.060644] ata1.00: configured for UDMA/133 [ 37.064979] ata1: EH complete [ 37.117163] ata2.00: configured for UDMA/133 [ 37.121483] ata2: EH complete [ 65.752749] md: md0: resync done. [ 65.768547] md: md0: current auto_remap = 0 [ 85.190921] mvEthPhyRegRead: SMI read-valid timeout [ 85.196770] mvEthPhyRegRead: SMI busy timeout [ 85.202061] mvEthPhyRegRead: SMI busy timeout [ 85.207334] mvEthPhyRegRead: SMI busy timeout [ 86.267187] mvEthPhyRegRead: SMI busy timeout [ 86.272499] mvEthPhyRegRead: SMI busy timeout [ 86.277777] mvEthPhyRegRead: SMI busy timeout [ 86.283078] mvEthPhyRegRead: SMI busy timeout [ 86.387545] mvEthPhyRegRead: SMI busy timeout [ 86.392871] mvEthPhyRegRead: SMI busy timeout [ 86.398159] mvEthPhyRegRead: SMI busy timeout [ 86.403487] mvEthPhyRegRead: SMI busy timeout
- I declare this powerdown not being successful, because the LED’s, fans, and ethernet is still powered, but maybe that’s not so accurate. The hard drives look powered down no? I just tried a reboot instead, and it also fails to really complete, so yea, i’d say this was not successful for very similar reasons.
admin@toasteroven:/$ Broadcast message from admin@toasteroven (/dev/console) at 16:03 ... The system is going down for reboot NOW! [ 201.363036] init: synonetd main process (1617) killed by TERM signal [ 201.369871] init: synostoraged main process (4183) terminated with status 15 [ 201.394674] init: hotplugd main process (4510) killed by TERM signal [ 201.439693] init: smbd main process (6265) killed by TERM signal [ 201.455840] init: nmbd main process (6567) killed by TERM signal [ 201.473629] init: synortc main process (6830) terminated with status 255 System is going to reboot. [ 202.429043] init: Disconnected from D-Bus system bus [ 212.117778] md2: detected capacity change from 1995461165056 to 0 [ 212.123936] md: md2: set sda3 to auto_remap [0] [ 212.128485] md: md2 stopped. [ 212.131381] md: unbind<sda3> [ 212.172002] md: export_rdev(sda3) [ 212.178868] md3: detected capacity change from 1995461165056 to 0 [ 212.185018] md: md3: set sdb3 to auto_remap [0] [ 212.189566] md: md3 stopped. [ 212.192470] md: unbind<sdb3> [ 212.232019] md: export_rdev(sdb3) [ 213.747950] md: md0 in immediate safe mode [ 213.752109] md: md1 in immediate safe mode [ 213.756751] init: tty main process (4523) killed by KILL signal [ 213.762937] init: skip respawn tty during shutdown [ 213.782286] init: dhcp-client (eth0) main process (3680) killed by KILL signal [ 214.052661] EXT4-fs (md0): re-mounted. Opts: (null) [ 215.134250] sd 1:0:0:0: [sdb] Synchronizing SCSI cache [ 215.139517] sd 0:0:0:0: [sda] Synchronizing SCSI cache [ 215.144842] xhci-hcd f10f8000.usb3: remove, state 1 [ 215.149749] usb usb4: USB disconnect, device number 1 [ 215.155071] xhci-hcd f10f8000.usb3: USB bus 4 deregistered [ 215.160582] xhci-hcd f10f8000.usb3: remove, state 1 [ 215.165495] usb usb3: USB disconnect, device number 1 [ 215.170774] xhci-hcd f10f8000.usb3: USB bus 3 deregistered [ 215.176316] xhci-hcd f10f0000.usb3: remove, state 1 [ 215.181218] usb usb2: USB disconnect, device number 1 [ 215.186469] xhci-hcd f10f0000.usb3: USB bus 2 deregistered [ 215.191979] xhci-hcd f10f0000.usb3: remove, state 1 [ 215.196890] usb usb1: USB disconnect, device number 1 [ 215.202166] xhci-hcd f10f0000.usb3: USB bus 1 deregistered [ 215.208375] Shutting Down Marvell Ethernet Driver [ 215.214008] mvEthPhyRegWrite: SMI busy timeout [ 215.219368] mvEthPhyRegWrite: SMI busy timeout [ 215.224732] mvEthPhyRegWrite: SMI busy timeout [ 215.229204] Restarting system. [ 216.228721] Reboot failed -- System halted
What do you guys think? Is this something you’ve encountered on your own platform Fox? Is there any more debug information that would be helpful?
