Openbmc: Unable to find root file system intermittently on System

[geissonator]

Seems specific to the UBI update process. Something is happening to cause the boot variables to get out of synch, here's the trace from the udpate that led up to the fail:

Jan 05 23:02:10 witherspoon phosphor-version-software-manager[1230]: Untaring
Jan 05 23:02:10 witherspoon systemd[1]: Started SSH Per-Connection Server (9.41.165.103:48444).
Jan 05 23:02:11 witherspoon dropbear[2925]: Failed loading /var/lib/dropbear/dropbear_rsa_host_key
Jan 05 23:02:11 witherspoon dropbear[2925]: Failed loading /etc/dropbear/dropbear_dss_host_key
Jan 05 23:02:11 witherspoon dropbear[2925]: Failed loading /etc/dropbear/dropbear_ecdsa_host_key
Jan 05 23:02:11 witherspoon dropbear[2925]: Child connection from ::ffff:9.41.165.103:48444
Jan 05 23:02:11 witherspoon dropbear[2925]: PAM password auth succeeded for 'root' from ::ffff:9.41.165.103:48444
Jan 05 23:02:12 witherspoon systemd[1]: Started SSH Per-Connection Server (9.41.165.103:48446).
Jan 05 23:02:12 witherspoon dropbear[2930]: Failed loading /var/lib/dropbear/dropbear_rsa_host_key
Jan 05 23:02:12 witherspoon dropbear[2930]: Failed loading /etc/dropbear/dropbear_dss_host_key
Jan 05 23:02:12 witherspoon dropbear[2930]: Failed loading /etc/dropbear/dropbear_ecdsa_host_key
Jan 05 23:02:12 witherspoon dropbear[2930]: Child connection from ::ffff:9.41.165.103:48446
Jan 05 23:02:13 witherspoon dropbear[2930]: PAM password auth succeeded for 'root' from ::ffff:9.41.165.103:48446
Jan 05 23:02:14 witherspoon systemd[1]: Started SSH Per-Connection Server (9.41.165.103:48448).
Jan 05 23:02:14 witherspoon dropbear[2937]: Failed loading /var/lib/dropbear/dropbear_rsa_host_key
Jan 05 23:02:14 witherspoon dropbear[2937]: Failed loading /etc/dropbear/dropbear_dss_host_key
Jan 05 23:02:14 witherspoon dropbear[2937]: Failed loading /etc/dropbear/dropbear_ecdsa_host_key
Jan 05 23:02:14 witherspoon dropbear[2937]: Child connection from ::ffff:9.41.165.103:48448
Jan 05 23:02:15 witherspoon dropbear[2937]: PAM password auth succeeded for 'root' from ::ffff:9.41.165.103:48448
Jan 05 23:02:16 witherspoon systemd[1]: Started SSH Per-Connection Server (9.41.165.103:48450).
Jan 05 23:02:16 witherspoon dropbear[2941]: Failed loading /var/lib/dropbear/dropbear_rsa_host_key
Jan 05 23:02:16 witherspoon dropbear[2941]: Failed loading /etc/dropbear/dropbear_dss_host_key
Jan 05 23:02:16 witherspoon dropbear[2941]: Failed loading /etc/dropbear/dropbear_ecdsa_host_key
Jan 05 23:02:16 witherspoon dropbear[2941]: Child connection from ::ffff:9.41.165.103:48450
Jan 05 23:02:16 witherspoon dropbear[2941]: PAM password auth succeeded for 'root' from ::ffff:9.41.165.103:48450
Jan 05 23:02:19 witherspoon systemd[1]: Starting Set U-Boot environment variable...
Jan 05 23:02:19 witherspoon systemd[1]: Starting Set U-Boot environment variable...
Jan 05 23:02:19 witherspoon systemd[1]: Created slice system-obmc\x2dflash\x2dbmc\x2dupdateubootvars.slice.
Jan 05 23:02:20 witherspoon systemd[1]: Starting Updates the u-boot variable to point BMC version to 1be33b05...
Jan 05 23:02:20 witherspoon systemd[1]: Started Set U-Boot environment variable.
Jan 05 23:02:21 witherspoon systemd[1]: Started Set U-Boot environment variable.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-obmc\x2denable\x2dhost\x2dwatchdog.slice.
Jan 05 23:02:26 witherspoon kernel: watchdog: watchdog0: watchdog did not stop!
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-mapper\x2dsubtree\x2dremove.slice.
Jan 05 23:02:24 witherspoon dropbear[2916]: Exit (root): Terminated by signal
Jan 05 23:02:24 witherspoon systemd[1]: Stopping SSH Per-Connection Server (9.41.165.103:48432)...
Jan 05 23:02:24 witherspoon dropbear[2930]: Exit (root): Terminated by signal
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:24 witherspoon kernel[959]: [  813.340000] watchdog: watchdog0: watchdog did not stop!
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-mboxd\x2dreload.slice.
Jan 05 23:02:24 witherspoon dropbear[2941]: Exit (root): Terminated by signal
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dreboot\x2dhost.slice.
Jan 05 23:02:24 witherspoon dropbear[2937]: Exit (root): Terminated by signal
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:25 witherspoon avahi-daemon[1000]: Got SIGTERM, quitting.
Jan 05 23:02:24 witherspoon systemd[1]: Stopped target Power0 Off.
Jan 05 23:02:25 witherspoon avahi-daemon[1000]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::72e2:84ff:fe14:23e1.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:25 witherspoon avahi-daemon[1000]: Leaving mDNS multicast group on interface eth0.IPv4 with address 9.3.86.161.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dreset\x2dhost\x2dcheck.slice.
Jan 05 23:02:25 witherspoon avahi-daemon[1000]: avahi-daemon 0.6.32 exiting.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dfan\x2dpresence\x2dtach.slice.
Jan 05 23:02:25 witherspoon kernel[959]: klogd: exiting
Jan 05 23:02:24 witherspoon systemd[1]: Stopped Assert bmc_booted LED.
Jan 05 23:02:28 witherspoon dropbear[2925]: Exit (root): Terminated by signal
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dfan\x2dcontrol\x2dinit.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-fsi\x2dbind.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dfan\x2dcontrol.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-op\x2dreset\x2dchassis\x2don.slice.
Jan 05 23:02:24 witherspoon systemd[1]: witherspoon-fan-watchdog.service: Killing process 1401 (watchdog) with signal SIGKILL.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Witherspoon Fan Watchdog Daemon...
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-op\x2docc\x2denable.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopped Assert power_on LED.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-avsbus\x2denable.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-avsbus\x2ddisable.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopped target Stop Host0.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopped target System Time Synchronized.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopping SSH Per-Connection Server (9.41.165.103:48446)...
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-op\x2dreset\x2dchassis\x2drunning.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-vrm\x2dcontrol.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-pcie\x2dslot\x2ddetect.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-obmc\x2dflash\x2dbmc\x2dsetenv.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-power\x2dworkarounds.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-op\x2docc\x2ddisable.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopped Wait for /org/openbmc/HostIpmi/1.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dmax31785\x2dmsl.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Webserver...
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dfan\x2dmonitor\x2dinit.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-start_host.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dreset\x2dhost\x2drunning.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dgpio\x2dmonitor.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/control/host0.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/watchdog/host0.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-obmc\x2dconsole\x2dssh.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopping SSH Per-Connection Server (9.41.165.103:48450)...
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2ddiscover\x2dsystem\x2dstate.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-getty.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-obmc\x2dled\x2dgroup\x2dstart.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/led/groups/power_on.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dfan\x2dmonitor.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-obmc\x2dsync\x2dinventory\x2ditem.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-phosphor\x2dcooling\x2dtype.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-cfam_override.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-obmc\x2dled\x2dgroup\x2dstop.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-ir35221\x2don\x2dbind.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-op\x2dpower\x2dstart.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Removed slice system-ir35221\x2don\x2dunbind.slice.
Jan 05 23:02:24 witherspoon systemd[1]: Stopping SSH Per-Connection Server (9.41.165.103:48448)...
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:24 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/led/groups/bmc_booted.
Jan 05 23:02:24 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/network/config.
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Timers.
Jan 05 23:02:25 witherspoon systemd[1]: Stopped Daily Cleanup of Temporary Directories.
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 05 23:02:25 witherspoon systemd[1]: Removed slice system-fsi\x2dscan.slice.
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:25 witherspoon systemd[1]: Removed slice system-op\x2dwait\x2dpower\x2don.slice.
Jan 05 23:02:25 witherspoon systemd[1]: Stopped Wait for /org/openbmc/control/chassis0.
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller...
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Power0 Host Off.
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Chassis0 (Power Off).
Jan 05 23:02:25 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/state/chassis0.
Jan 05 23:02:25 witherspoon systemd[1]: Stopped Stop Power0.
Jan 05 23:02:25 witherspoon systemd[1]: Removed slice system-op\x2dpower\x2dstop.slice.
Jan 05 23:02:25 witherspoon systemd[1]: Stopped Wait for Power0 to turn off.
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Power0 Off (Pre).
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Host0 (Stopped).
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Host0 (Stopping).
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Stop Host0 (Pre).
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Phosphor System - Standby.
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Power Button0...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Dump core monitor....
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Host State Manager...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping OpenPOWER OCC controller...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Witherspoon Power Supply 1 Monitor...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Console Muxer listening on device /dev/ttyVUART0...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Version Software Manager...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor GPIO 0 Presence...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Download Manager...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor BMC Code Update...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping FRU Fault monitor service...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor DBus Monitor...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Network Manager...
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Multi-User System.
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Avahi mDNS/DNS-SD Stack...
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Containers.
Jan 05 23:02:25 witherspoon systemd[1]: Stopping System Logging Service...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Kernel Logging Service...
Jan 05 23:02:25 witherspoon systemd[1]: Stopped target Login Prompts.
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Serial Getty on ttyS4...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Hardware RNG Entropy Gatherer Daemon...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Download Manager...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor IPMI BT DBus Bridge...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor User Manager...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phoshpor System Manager...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Lightweight SLP Server...
Jan 05 23:02:25 witherspoon systemd[1]: Stopping Phosphor Time Manager daemon...
Jan 05 23:02:26 witherspoon systemd[1]: Stopping Phosphor BMC0 Control...
Jan 05 23:02:26 witherspoon systemd[1]: Stopping Phosphor Network Manager...
Jan 05 23:02:26 witherspoon systemd[1]: Stopping Phosphor Settings Daemon...
Jan 05 23:02:26 witherspoon systemd[1]: Stopping Phosphor MBOX Daemon...
Jan 05 23:02:26 witherspoon systemd[1]: Stopping Phosphor Dump Manager...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor Log Manager...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor Inventory Manager...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor Reset Button0...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor Power0 Control...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor BMC State Manager...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor Sensor Manager...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor Inband IPMI...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Witherspoon Power Supply 0 Monitor...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor Chassis0 Control...
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor GPIO 1 Presence...
Jan 05 23:02:27 witherspoon systemd[1]: Removed slice system-op\x2dwait\x2dpower\x2doff.slice.
Jan 05 23:02:27 witherspoon systemd[1]: Stopped Phosphor MSL Verification.
Jan 05 23:02:27 witherspoon systemd[1]: Stopping Phosphor Chassis State Manager...
Jan 05 23:02:28 witherspoon systemd[1]: Stopping SSH Per-Connection Server (9.41.165.103:48444)...
Jan 05 23:02:28 witherspoon systemd[1]: Removed slice system-phosphor\x2dwatchdog.slice.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Kernel Logging Service.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Download Manager.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Inventory Manager.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Sensor Manager.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Hardware RNG Entropy Gatherer Daemon.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Chassis0 Control.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Download Manager.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Network Manager.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Log Manager.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Settings Daemon.
Jan 05 23:02:31 witherspoon systemd[1]: Stopped Phosphor Dump core monitor..
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Console Muxer listening on device /dev/ttyVUART0.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor BMC0 Control.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor IPMI BT DBus Bridge.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped System Logging Service.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor User Manager.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Avahi mDNS/DNS-SD Stack.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor sysfs LED controller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Dump Manager.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Lightweight SLP Server.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Serial Getty on ttyS4.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Network Manager.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Webserver.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phoshpor System Manager.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor DBus Monitor.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped FRU Fault monitor service.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor GPIO 0 Presence.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor GPIO 1 Presence.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped OpenPOWER OCC controller.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor BMC Code Update.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Version Software Manager.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Inband IPMI.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Power Button0.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Chassis State Manager.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Power0 Control.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor Reset Button0.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Phosphor BMC State Manager.
Jan 05 23:02:32 witherspoon systemd[1]: Stopped Witherspoon Power Supply 0 Monitor.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Witherspoon Power Supply 1 Monitor.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Phosphor Host State Manager.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Phosphor MBOX Daemon.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Phosphor Time Manager daemon.
Jan 05 23:02:33 witherspoon systemd[1]: witherspoon-fan-watchdog.service: Main process exited, code=killed, status=9/KILL
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Witherspoon Fan Watchdog Daemon.
Jan 05 23:02:33 witherspoon systemd[1]: witherspoon-fan-watchdog.service: Unit entered failed state.
Jan 05 23:02:33 witherspoon systemd[1]: witherspoon-fan-watchdog.service: Failed with result 'signal'.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Phosphor Hwmon Poller.
Jan 05 23:02:33 witherspoon systemd[1]: Stopped SSH Per-Connection Server (9.41.165.103:48432).
Jan 05 23:02:33 witherspoon systemd[1]: Stopped SSH Per-Connection Server (9.41.165.103:48444).
Jan 05 23:02:33 witherspoon systemd[1]: Stopped SSH Per-Connection Server (9.41.165.103:48446).
Jan 05 23:02:33 witherspoon systemd[1]: Stopped SSH Per-Connection Server (9.41.165.103:48448).
Jan 05 23:02:33 witherspoon systemd[1]: Stopped SSH Per-Connection Server (9.41.165.103:48450).
Jan 05 23:02:33 witherspoon systemd[1]: [email protected]: Main process exited, code=killed, status=15/TERM
Jan 05 23:02:33 witherspoon systemd[1]: Stopped Updates the u-boot variable to point BMC version to 1be33b05.
Jan 05 23:02:33 witherspoon systemd[1]: [email protected]: Unit entered failed state.
Jan 05 23:02:33 witherspoon systemd[1]: [email protected]: Failed with result 'signal'.
Jan 05 23:02:34 witherspoon systemd[1]: Removed slice system-obmc\x2dflash\x2dbmc\x2dupdateubootvars.slice.
Jan 05 23:02:34 witherspoon systemd[1]: Removed slice system-dropbear.slice.
Jan 05 23:02:34 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/time/owner.
Jan 05 23:02:34 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/time/sync_method.
Jan 05 23:02:34 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/state/host0.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Check PNOR UBI format.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/control/host0/auto_reboot.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/inventory/system/chassis/powersupply1.
Jan 05 23:02:35 witherspoon systemd[1]: Removed slice system-witherspoon\x2dpower\x2dsupply\x2dmonitor.slice.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/inventory/system/chassis/powersupply0.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /org/openbmc/control/power0.
Jan 05 23:02:35 witherspoon systemd[1]: Removed slice system-org.openbmc.buttons.reset.slice.
Jan 05 23:02:35 witherspoon systemd[1]: Removed slice system-org.openbmc.control.Power.slice.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /org/openbmc/managers/System.
Jan 05 23:02:35 witherspoon systemd[1]: Removed slice system-org.openbmc.buttons.Power.slice.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /org/openbmc/settings/host0.
Jan 05 23:02:35 witherspoon systemd[1]: Stopping Phosphor Settings Manager...
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/control/host0/boot/one_time.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/control/host0/boot.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/control/host0/power_restore_policy.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Clear one time boot overrides.
Jan 05 23:02:35 witherspoon systemd[1]: Unmounting /etc...
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/control/host0/restriction_mode.
Jan 05 23:02:35 witherspoon systemd[1]: Stopping OpenBMC Software Update Manager...
Jan 05 23:02:35 witherspoon systemd[1]: Stopping OpenPower Software Update Manager...
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /org/openbmc/control/bmc0.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /org/openbmc/managers/Download.
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/inventory.
Jan 05 23:02:35 witherspoon systemd[1]: Stopping Phosphor Inventory Manager...
Jan 05 23:02:35 witherspoon systemd[1]: Removed slice system-phosphor\x2dgpio\x2dpresence.slice.
Jan 05 23:02:35 witherspoon dbus[988]: [system] Reloaded configuration
Jan 05 23:02:35 witherspoon systemd[1]: Stopped Wait for /xyz/openbmc_project/led/groups.
Jan 05 23:02:36 witherspoon systemd[1]: Removed slice system-mapper\x2dwait.slice.
Jan 05 23:02:36 witherspoon systemd[1]: Stopping Phosphor LED Group Management Daemon...
Jan 05 23:02:36 witherspoon systemd[1]: Stopped target Webserver (pre).
Jan 05 23:02:36 witherspoon systemd[1]: Removed slice system-xyz.openbmc_project.Hwmon.slice.
Jan 05 23:02:36 witherspoon systemd[1]: Stopping Permit User Sessions...
Jan 05 23:02:36 witherspoon systemd[1]: Removed slice system-serial\x2dgetty.slice.
Jan 05 23:02:36 witherspoon systemd[1]: Removed slice system-org.openbmc.control.Bmc.slice.
Jan 05 23:02:36 witherspoon systemd[1]: Removed slice system-obmc\x2dconsole.slice.
Jan 05 23:02:36 witherspoon systemd[1]: Removed slice system-org.openbmc.control.Chassis.slice.
Jan 05 23:02:36 witherspoon systemd[1]: Removed slice system-xyz.openbmc_project.led.controller.slice.
Jan 05 23:02:37 witherspoon systemd[1]: Stopped Phosphor LED Group Management Daemon.
Jan 05 23:02:37 witherspoon systemd[1]: Stopped Phosphor Inventory Manager.
Jan 05 23:02:37 witherspoon systemd[1]: Stopped OpenPower Software Update Manager.
Jan 05 23:02:37 witherspoon systemd[1]: Stopped OpenBMC Software Update Manager.
Jan 05 23:02:37 witherspoon systemd[1]: Stopped Phosphor Settings Manager.
Jan 05 23:02:37 witherspoon systemd[1]: Unmounted /etc.
Jan 05 23:02:37 witherspoon systemd[1]: Stopped Permit User Sessions.
Jan 05 23:02:37 witherspoon systemd[1]: Stopped target Remote File Systems.
Jan 05 23:02:37 witherspoon systemd[1]: Stopped target Network.
Jan 05 23:02:38 witherspoon systemd[1]: Stopping Network Service...
Jan 05 23:02:38 witherspoon systemd[1]: Stopped target Phosphor Object Mapper.
Jan 05 23:02:38 witherspoon systemd-timesyncd[955]: Network configuration changed, trying to establish connection.
Jan 05 23:02:38 witherspoon systemd[1]: Stopping Phosphor DBus Service Discovery Manager...
Jan 05 23:02:38 witherspoon systemd[1]: Stopped Network Service.
Jan 05 23:02:38 witherspoon systemd[1]: Stopped Phosphor DBus Service Discovery Manager.
Jan 05 23:02:38 witherspoon systemd[1]: Stopping D-Bus System Message Bus...
Jan 05 23:02:38 witherspoon systemd[1]: Stopped D-Bus System Message Bus.
Jan 05 23:02:38 witherspoon systemd[1]: Failed to propagate agent release message: Connection reset by peer
Jan 05 23:02:38 witherspoon systemd[1]: Failed to propagate agent release message: Transport endpoint is not connected
Jan 05 23:02:38 witherspoon systemd[1]: Stopped target Basic System.
Jan 05 23:02:38 witherspoon systemd[1]: Stopped target Slices.
Jan 05 23:02:38 witherspoon systemd[1]: Stopped target Sockets.
Jan 05 23:02:38 witherspoon systemd[1]: Closed Phosphor Host Console SSH Per-Connection socket.
Jan 05 23:02:38 witherspoon systemd[1]: Closed dropbear.socket.
Jan 05 23:02:38 witherspoon systemd[1]: Closed Avahi mDNS/DNS-SD Stack Activation Socket.
Jan 05 23:02:38 witherspoon systemd[1]: Closed Syslog Socket.
Jan 05 23:02:38 witherspoon systemd[1]: Closed phosphor-ipmi-net.socket.
Jan 05 23:02:38 witherspoon systemd[1]: Closed Phosphor DBUS Browser socket.
Jan 05 23:02:38 witherspoon systemd[1]: Closed Phosphor Webserver socket.
Jan 05 23:02:38 witherspoon systemd[1]: Stopped target Paths.
Jan 05 23:02:38 witherspoon systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.
Jan 05 23:02:38 witherspoon systemd[1]: Stopped Forward Password Requests to Wall Directory Watch.
Jan 05 23:02:38 witherspoon systemd[1]: Closed D-Bus System Message Bus Socket.
Jan 05 23:02:38 witherspoon systemd[1]: Stopped target System Initialization.
Jan 05 23:02:38 witherspoon systemd[1]: Stopping Network Time Synchronization...
Jan 05 23:02:38 witherspoon systemd[1]: Stopping Load/Save Random Seed...
Jan 05 23:02:38 witherspoon systemd[1]: Stopped Apply Kernel Variables.
Jan 05 23:02:38 witherspoon systemd[1]: Stopped Network Time Synchronization.
Jan 05 23:02:39 witherspoon systemd[1]: Stopped Load/Save Random Seed.
Jan 05 23:02:39 witherspoon systemd[1]: Stopped Create Volatile Files and Directories.
Jan 05 23:02:39 witherspoon systemd[1]: Stopped target Local File Systems.
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting /media/rofs-d30fb306...
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting /media/pnor-ro-8764baa3...
Jan 05 23:02:39 witherspoon systemd[1]: Stopping Bind mount volatile /srv...
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting /media/pnor-prsv...
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting /media/pnor-rw-8764baa3...
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting /media/rofs-1be33b05...
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting /srv...
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting /home...
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting /usr/local/share/pnor...
Jan 05 23:02:39 witherspoon systemd[1]: Unmounting Temporary Directory...
Jan 05 23:02:39 witherspoon kernel: UBIFS (ubi8:4): un-mount UBI device 8
Jan 05 23:02:39 witherspoon kernel: UBIFS (ubi8:4): background thread "ubifs_bgt8_4" stops
Jan 05 23:02:39 witherspoon kernel: UBIFS (ubi8:2): un-mount UBI device 8
Jan 05 23:02:39 witherspoon kernel: UBIFS (ubi8:2): background thread "ubifs_bgt8_2" stops
Jan 05 23:02:39 witherspoon kernel: UBIFS (ubi8:3): un-mount UBI device 8
Jan 05 23:02:39 witherspoon kernel: UBIFS (ubi8:3): background thread "ubifs_bgt8_3" stops
Jan 05 23:02:39 witherspoon systemd[1]: Unmounted /media/rofs-d30fb306.
Jan 05 23:02:39 witherspoon systemd[1]: Stopped Bind mount volatile /srv.
Jan 05 23:02:39 witherspoon systemd[1]: Unmounted /media/pnor-prsv.
Jan 05 23:02:39 witherspoon systemd[1]: Unmounted /media/pnor-rw-8764baa3.
Jan 05 23:02:39 witherspoon systemd[1]: srv.mount: Mount process exited, code=exited status=1
Jan 05 23:02:39 witherspoon systemd[1]: Unmounted /srv.
Jan 05 23:02:39 witherspoon systemd[1]: srv.mount: Unit entered failed state.
Jan 05 23:02:39 witherspoon systemd[1]: home.mount: Mount process exited, code=exited status=1
Jan 05 23:02:39 witherspoon systemd[1]: Failed unmounting /home.
Jan 05 23:02:39 witherspoon systemd[1]: Unmounted /usr/local/share/pnor.
Jan 05 23:02:39 witherspoon systemd[1]: Unmounted Temporary Directory.
Jan 05 23:02:40 witherspoon systemd[1]: Unmounted /media/pnor-ro-8764baa3.
Jan 05 23:02:40 witherspoon systemd[1]: media-rofs\x2d1be33b05.mount: Mount process exited, code=exited status=1
Jan 05 23:02:40 witherspoon systemd[1]: Unmounted /media/rofs-1be33b05.
Jan 05 23:02:40 witherspoon systemd[1]: media-rofs\x2d1be33b05.mount: Unit entered failed state.
Jan 05 23:02:40 witherspoon systemd[1]: Stopped target Swap.
Jan 05 23:02:40 witherspoon systemd[1]: Unmounting /usr/local...
Jan 05 23:02:40 witherspoon systemd[1]: Unmounting /var/volatile...
Jan 05 23:02:40 witherspoon systemd[1]: Unmounting /media...
Jan 05 23:02:40 witherspoon systemd[1]: Unmounted /usr/local.
Jan 05 23:02:40 witherspoon systemd[1]: Unmounted /var/volatile.
Jan 05 23:02:40 witherspoon systemd[1]: Unmounting /var...
Jan 05 23:02:40 witherspoon systemd[1]: media.mount: Mount process exited, code=exited status=1
Jan 05 23:02:40 witherspoon systemd[1]: Unmounted /media.
Jan 05 23:02:40 witherspoon systemd[1]: media.mount: Unit entered failed state.
Jan 05 23:02:40 witherspoon systemd[1]: var.mount: Mount process exited, code=exited status=1
Jan 05 23:02:40 witherspoon systemd[1]: Failed unmounting /var.
Jan 05 23:02:40 witherspoon systemd[1]: Reached target Unmount All Filesystems.
Jan 05 23:02:40 witherspoon systemd[1]: Stopped target Local File Systems (Pre).
Jan 05 23:02:40 witherspoon systemd[1]: Stopped Create Static Device Nodes in /dev.
Jan 05 23:02:40 witherspoon systemd[1]: Stopped Remount Root and Kernel File Systems.
Jan 05 23:02:40 witherspoon systemd[1]: Reached target Shutdown.
Jan 05 23:02:40 witherspoon systemd[1]: Reached target Final Step.
Jan 05 23:02:40 witherspoon systemd[1]: Starting Reboot...
Jan 05 23:02:41 witherspoon systemd[1]: Shutting down.
Jan 05 23:02:41 witherspoon systemd[1]: Hardware watchdog 'aspeed_wdt', version 0
Jan 05 23:02:41 witherspoon systemd[1]: Set hardware watchdog to 10min.
Jan 05 23:02:41 witherspoon kernel: watchdog: watchdog0: watchdog did not stop!
Jan 05 23:02:41 witherspoon kernel: systemd-shutdow: 58 output lines suppressed due to ratelimiting
Jan 05 23:02:42 witherspoon systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Jan 05 23:02:42 witherspoon systemd-journald[949]: Journal stopped

Here's the error:

[    7.640000] VFS: Cannot open root device "ubiblock4_0" or unknown-block(0,0): error -6
[    7.640000] Please append a correct "root=" boot option; here are the available partitions:
[    7.640000] 0100            4096 ram0 
[    7.640000]  (driver?)
[    7.640000] 0101            4096 ram1 
[    7.640000]  (driver?)
[    7.640000] 0102            4096 ram2 
[    7.640000]  (driver?)
[    7.640000] 0103            4096 ram3 
[    7.640000]  (driver?)
[    7.640000] 0104            4096 ram4 
[    7.640000]  (driver?)
[    7.640000] 0105            4096 ram5 
[    7.640000]  (driver?)
[    7.640000] 0106            4096 ram6 
[    7.640000]  (driver?)
[    7.640000] 0107            4096 ram7 
[    7.640000]  (driver?)
[    7.640000] 0108            4096 ram8 
[    7.640000]  (driver?)
[    7.640000] 0109            4096 ram9 
[    7.640000]  (driver?)
[    7.640000] 010a            4096 ram10 
[    7.640000]  (driver?)
[    7.640000] 010b            4096 ram11 
[    7.640000]  (driver?)
[    7.640000] 010c            4096 ram12 
[    7.640000]  (driver?)
[    7.640000] 010d            4096 ram13 
[    7.640000]  (driver?)
[    7.640000] 010e            4096 ram14 
[    7.640000]  (driver?)
[    7.640000] 010f            4096 ram15 
[    7.640000]  (driver?)
[    7.640000] 1f00           32768 mtdblock0 
[    7.640000]  (driver?)
[    7.640000] 1f01             384 mtdblock1 
[    7.640000]  (driver?)
[    7.910000] 1f02             128 mtdblock2 
[    7.910000]  (driver?)
[    7.910000] 1f03           32256 mtdblock3 
[    7.910000]  (driver?)
[    7.910000] 1f04           32768 mtdblock4 
[    7.910000]  (driver?)
[    7.910000] 1f05             384 mtdblock5 
[    7.910000]  (driver?)
[    7.910000] 1f06             128 mtdblock6 
[    7.910000]  (driver?)
[    7.910000] 1f07           32256 mtdblock7 
[    7.910000]  (driver?)
[    7.910000] 1f08          131072 mtdblock8 
[    7.910000]  (driver?)
[    7.910000] fe00           14940 ubiblock0_1 
[    7.910000]  (driver?)
[    7.910000] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)
[    7.910000] CPU: 0 PID: 1 Comm: swapper Not tainted 4.10.17-72b52ebab574eaf0bcd2256ae16a25976a37c407 #1
[    7.910000] Hardware name: ASpeed SoC
[    7.910000] [<80010080>] (unwind_backtrace) from [<8000d934>] (show_stack+0x20/0x24)
[    7.910000] [<8000d934>] (show_stack) from [<801dbf2c>] (dump_stack+0x20/0x28)
[    7.910000] [<801dbf2c>] (dump_stack) from [<800a4a40>] (panic+0xc8/0x264)
[    7.910000] [<800a4a40>] (panic) from [<805894f8>] (mount_block_root+0x214/0x300)
[    7.910000] [<805894f8>] (mount_block_root) from [<80589740>] (mount_root+0x60/0x7c)
[    7.910000] [<80589740>] (mount_root) from [<805898c8>] (prepare_namespace+0x16c/0x1d0)
[    7.910000] [<805898c8>] (prepare_namespace) from [<805890b0>] (kernel_init_freeable+0x184/0x1cc)
[    7.910000] [<805890b0>] (kernel_init_freeable) from [<803fe480>] (kernel_init+0x18/0x104)
[    7.910000] [<803fe480>] (kernel_init) from [<8000a5e8>] (ret_from_fork+0x14/0x2c)

Here's the env variables in the fail state:

mtdparts=mtdparts=bmc:384k(u-boot),128k(u-boot-env),-(obmc-ubi)
netmask=255.255.254.0
obmc_bootcmd=ubi part obmc-ubi; run do_rwreset; ubi read ${loadaddr} ${kernelname}; bootm ${loadaddr}
partition=nor0,0
pnor-7a9ef57c=1
pnor-8764baa3=0
root=/dev/ubiblock4_0
serverip=9.3.164.219
set_bootargs=setenv bootargs console=ttyS4,115200n8 ubi.mtd=obmc-ubi,0,0,0 ubi.mtd=alt-obmc-ubi,0,0,4 ro rootfstype=squashfs ubi.block=${ubiblock} root=${root} 
spi_dma=yes
stderr=serial
stdin=serial
stdout=serial
ubiblock=0,1
verify=yes

[mdmillerii]

Correction: You loaded the kernel just fine.

You just couldn't find the root file system from the kernel.

The env says root should be on alt, but the ubi block still says to make the block device on primary.

[gkeishin]

We hit this again with the Master new build 1173

[   14.990000] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)
[   14.990000] CPU: 0 PID: 1 Comm: swapper Not tainted 4.10.17-72b52ebab574eaf0bcd2256ae16a25976a37c407 #1
[   14.990000] Hardware name: ASpeed SoC
[   14.990000] [<80010080>] (unwind_backtrace) from [<8000d934>] (show_stack+0x20/0x24)
[   14.990000] [<8000d934>] (show_stack) from [<801dbf2c>] (dump_stack+0x20/0x28)
[   14.990000] [<801dbf2c>] (dump_stack) from [<800a4a40>] (panic+0xc8/0x264)
[   14.990000] [<800a4a40>] (panic) from [<805894f8>] (mount_block_root+0x214/0x300)
[   14.990000] [<805894f8>] (mount_block_root) from [<80589740>] (mount_root+0x60/0x7c)
[   14.990000] [<80589740>] (mount_root) from [<805898c8>] (prepare_namespace+0x16c/0x1d0)
[   14.990000] [<805898c8>] (prepare_namespace) from [<805890b0>] (kernel_init_freeable+0x184/0x1cc)
[   14.990000] [<805890b0>] (kernel_init_freeable) from [<803fe480>] (kernel_init+0x18/0x104)
[   14.990000] [<803fe480>] (kernel_init) from [<8000a5e8>] (ret_from_fork+0x14/0x2c)

bootargs=console=ttyS4,115200n8 ubi.mtd=obmc-ubi,0,0,0 ubi.mtd=alt-obmc-ubi,0,0,4 ro rootfstype=squashfs
bootcmd=run set_bootargs; run obmc_bootcmd
bootdelay=2
c27712c9=2
do_rwreset=if test "${rwreset}" = "true"; then ubi remove rwfs; ubi create rwfs 0x400000; fi
e1478d95=2
e2ff887d=2
e7379c07=2
e8ea3001=2
ethact=aspeednic#0
ethaddr=70:e2:84:14:28:76
f6590ce0=2
fba43456=2
fefaeaa1=2
kernelname=kernel-aeedf969
loadaddr=80800000
mtdids=nor0=bmc
mtdparts=mtdparts=bmc:384k(u-boot),128k(u-boot-env),-(obmc-ubi)
obmc_bootcmd=ubi part obmc-ubi; run do_rwreset; ubi read ${loadaddr} ${kernelname}; bootm ${loadaddr}
pnor-498bd90d=0
pnor-df4b8673=0
root=/dev/ubiblock0_0
set_bootargs=setenv bootargs console=ttyS4,115200n8 ubi.mtd=obmc-ubi,0,0,0 ubi.mtd=alt-obmc-ubi,0,0,4 ro rootfstype=squashfs ubi.block=${ubiblock} root=${root}
spi_dma=yes
stderr=serial
stdin=serial
stdout=serial
ubiblock=4,0
verify=yes

Environment size: 1307/65531 bytes
ast#

Was able to recover by updating the kernel env

ast# setenv ubiblock 4,0
ast# setenv root /dev/ubiblock4_0
ast# saveenv
Saving Environment to Flash...
Un-Protected 1 sectors
Un-Protected 1 sectors
Erasing Flash...
. done
Erased 1 sectors
Writing to Flash... done
Protected 1 sectors
Protected 1 sectors
ast# 

and boot

[geissonator]

Hit this again this evening, fixed with this:

setenv ubiblock 4,0
setenv root /dev/ubiblock4_0
saveenv
boot

Here's some data from the journal before the reboot:

Jan 17 01:15:03 witherspoon kernel: block ubiblock4_0: released
Jan 17 01:15:03 witherspoon kernel[996]: [ 1024.820000] block ubiblock4_0: released
Jan 17 01:16:09 witherspoon obmc-flash-bmc[3541]: Volume ID 0, size 257 LEBs (16809856 bytes, 16.0 MiB), LEB size 65408 bytes (63.9 KiB), static, name "rofs-8002b15e", alignment 1
Jan 17 01:17:10 witherspoon kernel: block ubiblock4_0: created from ubi4:0(rofs-8002b15e)
Jan 17 01:17:10 witherspoon kernel[996]: [ 1150.510000] block ubiblock4_0: created from ubi4:0(rofs-8002b15e)
Jan 17 01:17:21 witherspoon obmc-flash-bmc[3620]: Volume ID 0, size 65 LEBs (4251520 bytes, 4.1 MiB), LEB size 65408 bytes (63.9 KiB), static, name "kernel-8002b15e", alignment 1
Jan 17 01:17:28 witherspoon obmc-flash-bmc[3620]: Volume ID 3, size 65 LEBs (4251520 bytes, 4.1 MiB), LEB size 65408 bytes (63.9 KiB), static, name "kernel-8002b15e", alignment 1
Jan 17 01:17:38 witherspoon obmc-flash-bmc[3706]: [130B blob data]
Jan 17 01:17:39 witherspoon obmc-flash-bmc[3706]: [1.9K blob data]
Jan 17 01:17:39 witherspoon obmc-flash-bmc[3706]: [2.0K blob data]
Jan 17 01:17:39 witherspoon obmc-flash-bmc[3706]: [150B blob data]
Jan 17 01:17:39 witherspoon systemd[1]: Started Store read-only images 8002b15e to BMC storage.
Jan 17 01:17:39 witherspoon systemd[1]: Starting Set U-Boot environment variable...
Jan 17 01:17:39 witherspoon systemd[1]: Starting Set U-Boot environment variable...
Jan 17 01:17:39 witherspoon systemd[1]: Starting Set U-Boot environment variable...
Jan 17 01:17:40 witherspoon systemd[1]: Created slice system-obmc\x2dflash\x2dbmc\x2dupdateubootvars.slice.
Jan 17 01:17:40 witherspoon systemd[1]: Starting Updates the u-boot variable to point BMC version to 8002b15e...
Jan 17 01:17:40 witherspoon phosphor-image-updater[1159]: Error in Deleting image from image manager
Jan 17 01:17:43 witherspoon systemd[1]: Started Set U-Boot environment variable.
Jan 17 01:17:45 witherspoon systemd[1]: Started Set U-Boot environment variable.
Jan 17 01:17:45 witherspoon systemd[1]: Started Set U-Boot environment variable.
Jan 17 01:17:47 witherspoon dropbear[3533]: Exit (root): Terminated by signal
...
Jan 17 01:17:57 witherspoon systemd[1]: Stopped SSH Per-Connection Server (9.41.165.94:44998).
Jan 17 01:17:57 witherspoon systemd[1]: [email protected]: Main process exited, code=killed, status=15/TERM
Jan 17 01:17:57 witherspoon systemd[1]: Stopped Updates the u-boot variable to point BMC version to 8002b15e.
Jan 17 01:17:57 witherspoon systemd[1]: [email protected]: Unit entered failed state.
Jan 17 01:17:57 witherspoon systemd[1]: [email protected]: Failed with result 'signal'.
Jan 17 01:17:59 witherspoon systemd[1]: Removed slice system-obmc\x2dflash\x2dbmc\x2dupdateubootvars.slice.

[geissonator]

CI system hit this again over the weekend, similar traces:

Jan 21 10:15:25 witherspoon systemd[1]: Starting Set U-Boot environment variable...
Jan 21 10:15:25 witherspoon systemd[1]: Starting Set U-Boot environment variable...
Jan 21 10:15:25 witherspoon systemd[1]: Created slice system-obmc\x2dflash\x2dbmc\x2dupdateubootvars.slice.
Jan 21 10:15:25 witherspoon systemd[1]: Starting Updates the u-boot variable to point BMC version to f9753315...
Jan 21 10:15:28 witherspoon systemd[1]: Started Set U-Boot environment variable.
Jan 21 10:15:28 witherspoon systemd[1]: Started Set U-Boot environment variable.
Jan 21 10:15:30 witherspoon systemd[1]: Removed slice system-obmc\x2dsync\x2dinventory\x2ditem.slice.
Jan 21 10:15:30 witherspoon systemd[1]: Stopping Phosphor Hwmon Poller...
Jan 21 10:15:30 witherspoon systemd[1]: Stopping Phosphor Webserver...
Jan 21 10:15:30 witherspoon systemd[1]: Stopping Phosphor sysfs LED controller..
...
Jan 21 10:15:40 witherspoon systemd[1]: [email protected]: Main process exited, code=killed, status=15/TERM
Jan 21 10:15:41 witherspoon systemd[1]: Stopped Updates the u-boot variable to point BMC version to f9753315.
Jan 21 10:15:41 witherspoon systemd[1]: [email protected]: Unit entered failed state.
Jan 21 10:15:41 witherspoon systemd[1]: [email protected]: Failed with result 'signal'.
Jan 21 10:15:42 witherspoon systemd[1]: Removed slice system-obmc\x2dflash\x2dbmc\x2dupdateubootvars.slice.

[mdmillerii]

@geissonator please be sure to dump both primary and alternate u-boot environments when debugging this.

[gkeishin]

How do we do that dumping the alt u boot env @mdmillerii

[anoo1]

It appears that code update is not waiting for the "[email protected]" file, so the automation bucket can issue a reboot before it's done since the version would be marked as "Active".

[anoo1]

Fix for "witherspoon phosphor-image-updater[1159]: Error in Deleting image from image manager":
https://gerrit.openbmc-project.xyz/#/c/8628/

Fix for the repeated calls to "Starting Set U-Boot environment variable":
https://gerrit.openbmc-project.xyz/#/c/8630/

Wait for env var service:
https://gerrit.openbmc-project.xyz/#/c/8635/

[rfrandse]

https://gerrit.openbmc-project.xyz/8635 Wait for [email protected]
Resolves #2764 Unable to find root file system intermittently on System

[anoo1]

How do we do that dumping the alt u boot env @mdmillerii

fw_printenv -c /etc/alt_fw_env.config