Pi USB switch restarted in the middle of a playback session

[linknum23]

A customer's log showed the Pi's USB switch getting disconnected and reconnecting. That reinitializes the cmedia chip and the ethernet interface.

We've never seen this before but need to document it in case it happens again.

Here's the relevant log:

Oct 01 20:11:58 amplipro-laundry kernel: 
Oct 01 20:11:58 amplipro-laundry kernel: ERROR::dwc_otg_hcd_urb_enqueue:501: Not connected
Oct 01 20:11:58 amplipro-laundry dhcpcd[532]: eth0: carrier lost
Oct 01 20:11:58 amplipro-laundry avahi-daemon[459]: Interface eth0.IPv6 no longer relevant for mDNS.
Oct 01 20:11:58 amplipro-laundry avahi-daemon[459]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::4af8:39dc:89b6:a5c.
Oct 01 20:11:58 amplipro-laundry kernel: usb 1-1: USB disconnect, device number 2
Oct 01 20:11:58 amplipro-laundry kernel: usb 1-1.1: USB disconnect, device number 3
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: unregister 'smsc95xx' usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: Failed to read reg index 0x00000114: -19
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: Error reading MII_ACCESS
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: __smsc95xx_mdio_read: MII is busy
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: Failed to read reg index 0x00000114: -19
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: Error reading MII_ACCESS
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: __smsc95xx_mdio_read: MII is busy
Oct 01 20:11:58 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Oct 01 20:11:58 amplipro-laundry avahi-daemon[459]: Interface eth0.IPv4 no longer relevant for mDNS.
Oct 01 20:11:58 amplipro-laundry avahi-daemon[459]: Leaving mDNS multicast group on interface eth0.IPv4 with address 10.0.99.7.
Oct 01 20:11:58 amplipro-laundry avahi-daemon[459]: Withdrawing address record for fe80::4af8:39dc:89b6:a5c on eth0.
Oct 01 20:11:58 amplipro-laundry avahi-daemon[459]: Withdrawing address record for 10.0.99.7 on eth0.
Oct 01 20:11:58 amplipro-laundry dhcpcd[532]: eth0: deleting address fe80::4af8:39dc:89b6:a5c
Oct 01 20:11:58 amplipro-laundry kernel: usb 1-1.3: USB disconnect, device number 4
Oct 01 20:11:58 amplipro-laundry dhcpcd[532]: eth0: deleting route to 10.0.99.0/24
Oct 01 20:11:58 amplipro-laundry dhcpcd[532]: eth0: deleting default route via 10.0.99.1
Oct 01 20:11:58 amplipro-laundry thd[453]: Error reading device '/dev/input/event0'
Oct 01 20:11:58 amplipro-laundry dhcpcd[532]: eth0: removing interface
Oct 01 20:11:59 amplipro-laundry kernel: Indeed it is in host mode hprt0 = 00021501
Oct 01 20:11:59 amplipro-laundry kernel: usb 1-1: new high-speed USB device number 5 using dwc_otg
Oct 01 20:11:59 amplipro-laundry kernel: Indeed it is in host mode hprt0 = 00001101
Oct 01 20:11:59 amplipro-laundry kernel: usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
Oct 01 20:11:59 amplipro-laundry kernel: usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Oct 01 20:11:59 amplipro-laundry kernel: hub 1-1:1.0: USB hub found
Oct 01 20:11:59 amplipro-laundry kernel: hub 1-1:1.0: 5 ports detected
Oct 01 20:11:59 amplipro-laundry kernel: usb 1-1.1: new high-speed USB device number 6 using dwc_otg
Oct 01 20:11:59 amplipro-laundry kernel: usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
Oct 01 20:11:59 amplipro-laundry kernel: usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Oct 01 20:11:59 amplipro-laundry kernel: smsc95xx v2.0.0
Oct 01 20:12:00 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:4e:c4:9b
Oct 01 20:12:00 amplipro-laundry mtp-probe[1695]: checking bus 1, device 6: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1"
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: new full-speed USB device number 7 using dwc_otg
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: New USB device found, idVendor=0d8c, idProduct=0102, bcdDevice= 0.10
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: New USB device strings: Mfr=0, Product=2, SerialNumber=0
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: Product: USB Sound Device        
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: current rate 30464 is different from the runtime rate 96000
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: Warning! Unlikely big volume range (=8065), cval->res is probably wrong.
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: [9] FU [Mic Playback Volume] ch = 2, val = -6144/1921/1
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: Warning! Unlikely big volume range (=8065), cval->res is probably wrong.
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: [11] FU [Line Playback Volume] ch = 2, val = -6144/1921/1
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: Warning! Unlikely big volume range (=6928), cval->res is probably wrong.
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: [8] FU [Mic Capture Volume] ch = 2, val = -4096/2832/1
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: Warning! Unlikely big volume range (=6928), cval->res is probably wrong.
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: [15] FU [Line Capture Volume] ch = 2, val = -4096/2832/1
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: Warning! Unlikely big volume range (=6928), cval->res is probably wrong.
Oct 01 20:12:00 amplipro-laundry kernel: usb 1-1.3: [2] FU [PCM Capture Volume] ch = 2, val = -4096/2832/1
Oct 01 20:12:00 amplipro-laundry kernel: input: USB Sound Device         as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.3/0003:0D8C:0102.0002/input/input1
Oct 01 20:12:00 amplipro-laundry mtp-probe[1695]: bus: 1, device: 6 was not an MTP device
Oct 01 20:12:00 amplipro-laundry kernel: hid-generic 0003:0D8C:0102.0002: input,hidraw0: USB HID v1.00 Device [USB Sound Device        ] on usb-3f980000.usb-1.3/input3
Oct 01 20:12:00 amplipro-laundry mtp-probe[1697]: checking bus 1, device 7: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3"
Oct 01 20:12:00 amplipro-laundry mtp-probe[1697]: bus: 1, device: 7 was not an MTP device
Oct 01 20:12:00 amplipro-laundry systemd-udevd[1628]: Using default interface naming scheme 'v240'.
Oct 01 20:12:00 amplipro-laundry mtp-probe[1707]: checking bus 1, device 6: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1"
Oct 01 20:12:00 amplipro-laundry mtp-probe[1707]: bus: 1, device: 6 was not an MTP device
Oct 01 20:12:00 amplipro-laundry dhcpcd[532]: eth0: waiting for carrier
Oct 01 20:12:00 amplipro-laundry dhcpcd[532]: eth0: carrier acquired
Oct 01 20:12:00 amplipro-laundry kernel: SMSC LAN8700 usb-001:006:01: attached PHY driver [SMSC LAN8700] (mii_bus:phy_addr=usb-001:006:01, irq=POLL)
Oct 01 20:12:00 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Oct 01 20:12:00 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down
Oct 01 20:12:00 amplipro-laundry dhcpcd[532]: eth0: IAID eb:4e:c4:9b
Oct 01 20:12:00 amplipro-laundry dhcpcd[532]: eth0: adding address fe80::4af8:39dc:89b6:a5c
Oct 01 20:12:00 amplipro-laundry avahi-daemon[459]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::4af8:39dc:89b6:a5c.
Oct 01 20:12:00 amplipro-laundry avahi-daemon[459]: New relevant interface eth0.IPv6 for mDNS.
Oct 01 20:12:00 amplipro-laundry avahi-daemon[459]: Registering new address record for fe80::4af8:39dc:89b6:a5c on eth0.*.
Oct 01 20:12:00 amplipro-laundry systemd-udevd[1635]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Oct 01 20:12:00 amplipro-laundry mtp-probe[1717]: checking bus 1, device 7: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3"
Oct 01 20:12:00 amplipro-laundry mtp-probe[1717]: bus: 1, device: 7 was not an MTP device
Oct 01 20:12:00 amplipro-laundry dhcpcd[532]: eth0: carrier lost
Oct 01 20:12:00 amplipro-laundry dhcpcd[532]: eth0: deleting address fe80::4af8:39dc:89b6:a5c
Oct 01 20:12:00 amplipro-laundry avahi-daemon[459]: Withdrawing address record for fe80::4af8:39dc:89b6:a5c on eth0.
Oct 01 20:12:00 amplipro-laundry avahi-daemon[459]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::4af8:39dc:89b6:a5c.
Oct 01 20:12:00 amplipro-laundry avahi-daemon[459]: Interface eth0.IPv6 no longer relevant for mDNS.
Oct 01 20:12:02 amplipro-laundry dhcpcd[532]: eth0: carrier acquired
Oct 01 20:12:02 amplipro-laundry kernel: smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off
Oct 01 20:12:02 amplipro-laundry kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Oct 01 20:12:02 amplipro-laundry dhcpcd[532]: eth0: IAID eb:4e:c4:9b
Oct 01 20:12:02 amplipro-laundry dhcpcd[532]: eth0: adding address fe80::4af8:39dc:89b6:a5c
Oct 01 20:12:02 amplipro-laundry avahi-daemon[459]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::4af8:39dc:89b6:a5c.
Oct 01 20:12:02 amplipro-laundry avahi-daemon[459]: New relevant interface eth0.IPv6 for mDNS.
Oct 01 20:12:02 amplipro-laundry avahi-daemon[459]: Registering new address record for fe80::4af8:39dc:89b6:a5c on eth0.*.
Oct 01 20:12:03 amplipro-laundry dhcpcd[532]: eth0: rebinding lease of 10.0.99.7
Oct 01 20:12:03 amplipro-laundry dhcpcd[532]: eth0: soliciting an IPv6 router
Oct 01 20:12:04 amplipro-laundry python[840]: 2024-10-01 20:12:04.620 | ERROR    | amplipi.display.common:get_info:329 - Failed to get IP address: KeyError
Oct 01 20:12:04 amplipro-laundry python[840]: 2024-10-01 20:12:04.623 | INFO     | amplipi.display.einkdisplay:update_display:154 - E-Ink Display: Changed Status to 1
Oct 01 20:12:07 amplipro-laundry dhcpcd[532]: eth0: probing address 10.0.99.7/24
Oct 01 20:12:09 amplipro-laundry authbind[839]: amplipi.zeroconf: WARNING - Unable to register service on one of <filter object at 0x7322bef0>,           they all are either not available or have no IP address.
Oct 01 20:12:09 amplipro-laundry authbind[839]: amplipi.zeroconf: INFO - IP address changed from 10.0.99.7 (eth0) to None (None)
Oct 01 20:12:09 amplipro-laundry authbind[839]: amplipi.zeroconf: INFO - Registration change needed
Oct 01 20:12:09 amplipro-laundry authbind[839]: amplipi.zeroconf: INFO - Unregistering service
Oct 01 20:12:12 amplipro-laundry dhcpcd[532]: eth0: leased 10.0.99.7 for 86400 seconds
Oct 01 20:12:12 amplipro-laundry dhcpcd[532]: eth0: adding route to 10.0.99.0/24
Oct 01 20:12:12 amplipro-laundry dhcpcd[532]: eth0: adding default route via 10.0.99.1
Oct 01 20:12:12 amplipro-laundry avahi-daemon[459]: Joining mDNS multicast group on interface eth0.IPv4 with address 10.0.99.7.
Oct 01 20:12:12 amplipro-laundry avahi-daemon[459]: New relevant interface eth0.IPv4 for mDNS.
Oct 01 20:12:12 amplipro-laundry avahi-daemon[459]: Registering new address record for 10.0.99.7 on eth0.IPv4.
Oct 01 20:12:13 amplipro-laundry python[840]: 2024-10-01 20:12:13.595 | INFO     | amplipi.display.einkdisplay:update_display:154 - E-Ink Display: Changed Status to â–¶x1 â¹x1
Oct 01 20:12:14 amplipro-laundry authbind[839]: amplipi.zeroconf: INFO - Registering service: ServiceInfo(type='_amplipi._tcp.local.', name='amplipi-b8:27:eb:4e:c4:9b._amplipi._tcp.local.', addresses=[b'\n\x00c\x07'], port=80, weight=0, priority=0, server='amplipro-laundry.local.', properties={'path': '/api/', 'name': 'AmpliPi', 'vendor': 'MicroNova', 'version': '0.4.4', 'web_app': 'http://amplipro-laundry.local/', 'documentation': 'http://amplipro-laundry.local/doc'}, interface_index=None)
Oct 01 20:12:15 amplipro-laundry authbind[839]: amplipi.zeroconf: INFO - Finished registering service
Oct 01 20:12:16 amplipro-laundry dhcpcd[532]: eth0: no IPv6 Routers available