Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reboot from USB stopped working on 3B+ now Pi 3B+ flashes 4 times after reboot #968

Closed
hoopsurfer opened this issue Apr 9, 2018 · 31 comments

Comments

@hoopsurfer
Copy link

Boot works fine always (both from SD and USB), reboot never works from USB, but works fine from SD.

Using fresh Raspian images with apt update/apt full-upgrade/rpi-update applied.
Current uname -a output:
Linux raspberrypi 4.14.32-v7+ #1107 SMP Fri Apr 6 16:36:46 BST 2018 armv71 GNU/Linux

On reboot system fails to reboot, the green LED blinks: "short short short long " over and over

Fails both with and without blank SD card installed
Fails on multiple power supplies, multiple USB devices, multiple Pi 3B+s
Full power-off/on always boots and same Pi 3B+ devices rebooted with original Pi-day bits

@pelwell
Copy link
Contributor

pelwell commented Apr 10, 2018

Your error code blink sequence looks odd - the known codes only have 0, 2 or 4 long flashes. Can you double check the pattern? Link to a short video if you aren't sure.

@hoopsurfer
Copy link
Author

hoopsurfer commented Apr 11, 2018

Interesting AFTER shutdown I see 10 flashes consistently. But here are more specifics.

I acquired another Pi 3B+ and it WAS able to reboot we'll need to see if it can maintain that ability. We'll call this the GoodPi. I have several Pi-Day Pi 3B+ that exhibit consistent reboot failure using the exact same USB devices of different types - we'll call those BadPi.

Both GoodPi and BadPi show repeated four rapid flashes when booting from USB without an SD where the flashes start at OS boot, but with an a blank SD card both do not flash. What are the constant 4 rapid flashes when booting from USB when the boot works fine?

Using only a clean 2018-03-13-raspbian-stretch image etched on a USB with no SD card, Both GoodPi and BadPi 3B+ reboot successfully the first time to expand storage, then once they fully boot subsequent reboots fail on the BadPI and it flashes the Green LED 4 times short-short-short-long (more regular flashes not the rapid flashes above). On the GoodPi reboot works as expected. What are the 4 regular flashes when reboot fails?

On shutdown both GoodPi and BadPi turn off the Red LED after shutdown then back on and then flash the Green LED 10 times. What are the 10 regular flashes after shutdown?

Booth GoodPi and BadPi boot just fine after a shutdown.

I haven't sampled enough devices to see if there are other BadPi and GoodPi in the wild.

@burtyb
Copy link

burtyb commented Apr 11, 2018

Not sure if this is exactly the same as I see 4 very fast flashes (https://www.youtube.com/watch?v=dqm8poGcTJw 4x slow motion) but I've seen occasional problems rebooting from USB whilst testing other things.

I setup the RPi3+ booting off USB with Raspbian lite to auto login and then reboot from bashrc. Sometimes I get a good run of over 1000 reboots before it fails but it can also be every reboot.

Good reboot (serial output)

[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 4.14.30-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1102 SMP Mon Mar 26 16:45:49 BST 2018
[ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] cma: Reserved 8 MiB at 0x3ac00000
[ 0.000000] random: fast init done
[ 0.000000] percpu: Embedded 17 pages/cpu @ba34a000 s38720 r8192 d22720 u69632
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 240555
[ 0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=4ea08631-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 940260K/970752K available (7168K kernel code, 550K rwdata, 2048K rodata, 1024K init, 706K bss, 22300K reserved, 8192K cma-reserved)
[ 0.000000] Virtual kernel memory layout:
[ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
[ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
[ 0.000000] vmalloc : 0xbb800000 - 0xff800000 (1088 MB)
[ 0.000000] lowmem : 0x80000000 - 0xbb400000 ( 948 MB)
[ 0.000000] modules : 0x7f000000 - 0x80000000 ( 16 MB)
[ 0.000000] .text : 0x80008000 - 0x80800000 (8160 kB)
[ 0.000000] .init : 0x80b00000 - 0x80c00000 (1024 kB)
[ 0.000000] .data : 0x80c00000 - 0x80c8986c ( 551 kB)
[ 0.000000] .bss : 0x80c90f40 - 0x80d417f4 ( 707 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] ftrace: allocating 24918 entries in 74 pages
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[ 0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000022] Switching to timer-based delay loop, resolution 52ns
[ 0.000276] Console: colour dummy device 80x30
[ 0.000819] console [tty1] enabled
[ 0.000861] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.000901] pid_max: default: 32768 minimum: 301
[ 0.001230] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.001263] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.002215] Disabling memory control group subsystem
[ 0.002314] CPU: Testing write buffer coherency: ok
[ 0.002726] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.003116] Setting up static identity map for 0x100000 - 0x10003c
[ 0.003248] Hierarchical SRCU implementation.
[ 0.003896] smp: Bringing up secondary CPUs ...
[ 0.004646] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.005446] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.006228] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.006332] smp: Brought up 1 node, 4 CPUs
[ 0.006402] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[ 0.006423] CPU: All CPU(s) started in HYP mode.
[ 0.006441] CPU: Virtualization extensions available.
[ 0.007309] devtmpfs: initialized
[ 0.017773] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[ 0.018022] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.018065] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 0.018642] pinctrl core: initialized pinctrl subsystem
[ 0.019401] NET: Registered protocol family 16
[ 0.022018] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.026798] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.026831] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.027053] Serial: AMBA PL011 UART driver
[ 0.028699] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[ 0.029181] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[ 0.060369] bcm2835-dma 3f007000.dma: DMA legacy API manager at bb813000, dmachans=0x1
[ 0.061812] SCSI subsystem initialized
[ 0.062052] usbcore: registered new interface driver usbfs
[ 0.062121] usbcore: registered new interface driver hub
[ 0.062222] usbcore: registered new device driver usb
[ 0.070074] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-03-23 16:31
[ 0.071382] clocksource: Switched to clocksource arch_sys_counter
[ 0.147218] VFS: Disk quotas dquot_6.6.0
[ 0.147331] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.147535] FS-Cache: Loaded
[ 0.147746] CacheFiles: Loaded
[ 0.156649] NET: Registered protocol family 2
[ 0.157388] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.157532] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.157735] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.157883] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.157944] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.158188] NET: Registered protocol family 1
[ 0.158657] RPC: Registered named UNIX socket transport module.
[ 0.158681] RPC: Registered udp transport module.
[ 0.158700] RPC: Registered tcp transport module.
[ 0.158719] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.160158] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[ 0.162936] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[ 0.170851] FS-Cache: Netfs 'nfs' registered for caching
[ 0.171502] NFS: Registering the id_resolver key type
[ 0.171551] Key type id_resolver registered
[ 0.171571] Key type id_legacy registered
[ 0.173466] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[ 0.173615] io scheduler noop registered
[ 0.173637] io scheduler deadline registered (default)
[ 0.173930] io scheduler cfq registered
[ 0.173951] io scheduler mq-deadline registered
[ 0.173971] io scheduler kyber registered
[ 0.176284] BCM2708FB: allocated DMA memory fad00000
[ 0.176329] BCM2708FB: allocated DMA channel 0 @ bb813000
[ 0.184873] Console: switching to colour frame buffer device 82x26
[ 0.192212] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[ 0.195716] bcm2835-rng 3f104000.rng: hwrng registered
[ 0.198129] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[ 0.203266] vc-sm: Videocore shared memory driver
[ 0.205847] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[ 0.220010] brd: module loaded
[ 0.230952] loop: module loaded
[ 0.233265] Loading iSCSI transport class v2.0-870.
[ 0.236208] libphy: Fixed MDIO Bus: probed
[ 0.238543] usbcore: registered new interface driver lan78xx
[ 0.240836] usbcore: registered new interface driver smsc95xx
[ 0.243065] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 0.470955] Core Release: 2.80a
[ 0.473223] Setting default values for core params
[ 0.475532] Finished setting default values for core params
[ 0.678133] Using Buffer DMA mode
[ 0.680454] Periodic Transfer Interrupt Enhancement - disabled
[ 0.682910] Multiprocessor Interrupt Enhancement - disabled
[ 0.685336] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 0.687715] Dedicated Tx FIFOs mode
[ 0.690365] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xbad14000 dma = 0xfad14000 len=9024
[ 0.695079] FIQ FSM acceleration enabled for :
[ 0.695079] Non-periodic Split Transactions
[ 0.695079] Periodic Split Transactions
[ 0.695079] High-Speed Isochronous Endpoints
[ 0.695079] Interrupt/Control Split Transaction hack enabled
[ 0.706207] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x805d2774
[ 0.708488] WARN::hcd_init_fiq:460: FIQ ASM at 0x805d2adc length 36
[ 0.710751] WARN::hcd_init_fiq:486: MPHI regs_base at 0xbb87e000
[ 0.713027] dwc_otg 3f980000.usb: DWC OTG Controller
[ 0.715345] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[ 0.717708] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[ 0.720031] Init: Port Power? op_state=1
[ 0.722315] Init: Power Port (0)
[ 0.724700] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 0.727016] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.729317] usb usb1: Product: DWC OTG Controller
[ 0.731583] usb usb1: Manufacturer: Linux 4.14.30-v7+ dwc_otg_hcd
[ 0.733861] usb usb1: SerialNumber: 3f980000.usb
[ 0.736704] hub 1-0:1.0: USB hub found
[ 0.738918] hub 1-0:1.0: 1 port detected
[ 0.741786] usbcore: registered new interface driver usb-storage
[ 0.744070] mousedev: PS/2 mouse device common for all mice
[ 0.746295] IR NEC protocol handler initialized
[ 0.748469] IR RC5(x/sz) protocol handler initialized
[ 0.750676] IR RC6 protocol handler initialized
[ 0.752881] IR JVC protocol handler initialized
[ 0.754965] IR Sony protocol handler initialized
[ 0.757056] IR SANYO protocol handler initialized
[ 0.759144] IR Sharp protocol handler initialized
[ 0.761135] IR MCE Keyboard/mouse protocol handler initialized
[ 0.763180] IR XMP protocol handler initialized
[ 0.765841] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[ 0.768191] bcm2835-cpufreq: min=600000 max=1400000
[ 0.770636] sdhci: Secure Digital Host Controller Interface driver
[ 0.772796] sdhci: Copyright(c) Pierre Ossman
[ 0.775244] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[ 0.777718] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[ 0.780007] sdhci-pltfm: SDHCI platform and OF driver helper
[ 0.783639] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.786033] hidraw: raw HID events driver (C) Jiri Kosina
[ 0.788510] usbcore: registered new interface driver usbhid
[ 0.790812] usbhid: USB HID core driver
[ 0.793681] vchiq: vchiq_init_state: slot_zero = bad80000, is_master = 0
[ 0.797374] [vc_sm_connected_init]: start
[ 0.805985] [vc_sm_connected_init]: end - returning 0
[ 0.808860] Initializing XFRM netlink socket
[ 0.811237] NET: Registered protocol family 17
[ 0.813711] Key type dns_resolver registered
[ 0.816473] Registering SWP/SWPB emulation handler
[ 0.819454] registered taskstats version 1
[ 0.827775] uart-pl011 3f201000.serial: cts_event_workaround enabled
[ 0.830344] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[ 0.836778] console [ttyS0] disabled
[ 0.839221] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 166, base_baud = 31250000) is a 16550
[ 0.961465] Indeed it is in host mode hprt0 = 00021501
[ 1.161423] usb 1-1: new high-speed USB device number 2 using dwc_otg
[ 1.161533] Indeed it is in host mode hprt0 = 00001101
[ 1.401636] usb 1-1: New USB device found, idVendor=0424, idProduct=2514
[ 1.401646] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1.405788] hub 1-1:1.0: USB hub found
[ 1.405869] hub 1-1:1.0: 4 ports detected
[ 1.721408] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 1.851626] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514
[ 1.851635] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1.856310] hub 1-1.1:1.0: USB hub found
[ 1.856384] hub 1-1.1:1.0: 3 ports detected
[ 1.945354] console [ttyS0] enabled
[ 1.952308] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[ 1.960704] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[ 2.011543] dwc_otg_handle_wakeup_detected_intr lxstate = 2
[ 2.022047] sdhost: log_buf @ bad13000 (fad13000)
[ 2.065455] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 2.074983] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 2.084424] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 2.094986] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 2.111409] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 2.120114] of_cfs_init
[ 2.124785] of_cfs_init: OK
[ 2.130131] Waiting for root device PARTUUID=4ea08631-02...
[ 2.194086] mmc1: new high speed SDIO card at address 0001
[ 2.581414] usb 1-1.1.1: new high-speed USB device number 4 using dwc_otg
[ 2.711797] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800
[ 2.721131] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 3.000318] libphy: lan78xx-mdiobus: probed
[ 3.101417] usb 1-1.1.3: new high-speed USB device number 5 using dwc_otg
[ 3.232228] usb 1-1.1.3: New USB device found, idVendor=0781, idProduct=5583
[ 3.241549] usb 1-1.1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 3.253325] usb 1-1.1.3: Product: Ultra Fit
[ 3.259690] usb 1-1.1.3: Manufacturer: SanDisk
[ 3.266286] usb 1-1.1.3: SerialNumber: 4C530001220114110455
[ 3.274637] usb-storage 1-1.1.3:1.0: USB Mass Storage device detected
[ 3.283848] scsi host0: usb-storage 1-1.1.3:1.0
[ 4.312304] scsi 0:0:0:0: Direct-Access SanDisk Ultra Fit 1.00 PQ: 0 ANSI: 6
[ 4.326090] sd 0:0:0:0: [sda] 240254976 512-byte logical blocks: (123 GB/115 GiB)
[ 4.339959] sd 0:0:0:0: [sda] Write Protect is off
[ 4.347788] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 4.374208] sda: sda1 sda2
[ 4.382645] sd 0:0:0:0: [sda] Attached SCSI removable disk
[ 4.409977] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
[ 4.422985] VFS: Mounted root (ext4 filesystem) readonly on device 8:2.
[ 4.438955] devtmpfs: mounted
[ 4.447907] Freeing unused kernel memory: 1024K
[ 4.786706] systemd[1]: System time before build time, advancing clock.
[ 4.882729] NET: Registered protocol family 10
[ 4.891212] Segment Routing with IPv6
[ 4.907040] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 4.936164] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[ 4.963536] systemd[1]: Detected architecture arm.
[ 4.987923] systemd[1]: Set hostname to .
[ 5.458582] systemd[1]: Listening on udev Kernel Socket.
[ 5.470903] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 5.489463] systemd[1]: Listening on Syslog Socket.
[ 5.500926] systemd[1]: Created slice User and Session Slice.
[ 5.513099] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 5.529816] systemd[1]: Reached target Swap.
[ 5.540380] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[ 5.795731] random: crng init done
etc...

Bad reboot

[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 4.14.30-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1102 SMP Mon Mar 26 16:45:49 BST 2018
[ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] cma: Reserved 8 MiB at 0x3ac00000
[ 0.000000] random: fast init done
[ 0.000000] percpu: Embedded 17 pages/cpu @ba34a000 s38720 r8192 d22720 u69632
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 240555
[ 0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=4ea08631-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 940260K/970752K available (7168K kernel code, 550K rwdata, 2048K rodata, 1024K init, 706K bss, 22300K reserved, 8192K cma-reserved)
[ 0.000000] Virtual kernel memory layout:
[ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
[ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
[ 0.000000] vmalloc : 0xbb800000 - 0xff800000 (1088 MB)
[ 0.000000] lowmem : 0x80000000 - 0xbb400000 ( 948 MB)
[ 0.000000] modules : 0x7f000000 - 0x80000000 ( 16 MB)
[ 0.000000] .text : 0x80008000 - 0x80800000 (8160 kB)
[ 0.000000] .init : 0x80b00000 - 0x80c00000 (1024 kB)
[ 0.000000] .data : 0x80c00000 - 0x80c8986c ( 551 kB)
[ 0.000000] .bss : 0x80c90f40 - 0x80d417f4 ( 707 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] ftrace: allocating 24918 entries in 74 pages
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[ 0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000022] Switching to timer-based delay loop, resolution 52ns
[ 0.000275] Console: colour dummy device 80x30
[ 0.000820] console [tty1] enabled
[ 0.000861] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.000902] pid_max: default: 32768 minimum: 301
[ 0.001229] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.001262] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.002213] Disabling memory control group subsystem
[ 0.002311] CPU: Testing write buffer coherency: ok
[ 0.002721] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.003116] Setting up static identity map for 0x100000 - 0x10003c
[ 0.003248] Hierarchical SRCU implementation.
[ 0.003898] smp: Bringing up secondary CPUs ...
[ 0.004655] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.005459] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.006239] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.006344] smp: Brought up 1 node, 4 CPUs
[ 0.006414] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[ 0.006435] CPU: All CPU(s) started in HYP mode.
[ 0.006453] CPU: Virtualization extensions available.
[ 0.007323] devtmpfs: initialized
[ 0.017784] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[ 0.018033] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.018076] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 0.018653] pinctrl core: initialized pinctrl subsystem
[ 0.019409] NET: Registered protocol family 16
[ 0.022017] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.026803] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.026836] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.027055] Serial: AMBA PL011 UART driver
[ 0.028701] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[ 0.029185] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[ 0.060347] bcm2835-dma 3f007000.dma: DMA legacy API manager at bb813000, dmachans=0x1
[ 0.061794] SCSI subsystem initialized
[ 0.062034] usbcore: registered new interface driver usbfs
[ 0.062104] usbcore: registered new interface driver hub
[ 0.062204] usbcore: registered new device driver usb
[ 0.070072] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-03-23 16:31
[ 0.071368] clocksource: Switched to clocksource arch_sys_counter
[ 0.147219] VFS: Disk quotas dquot_6.6.0
[ 0.147330] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.147534] FS-Cache: Loaded
[ 0.147744] CacheFiles: Loaded
[ 0.156662] NET: Registered protocol family 2
[ 0.157399] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.157528] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.157730] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.157876] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.157937] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.158184] NET: Registered protocol family 1
[ 0.158653] RPC: Registered named UNIX socket transport module.
[ 0.158677] RPC: Registered udp transport module.
[ 0.158696] RPC: Registered tcp transport module.
[ 0.158715] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.160149] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[ 0.162927] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[ 0.170839] FS-Cache: Netfs 'nfs' registered for caching
[ 0.171489] NFS: Registering the id_resolver key type
[ 0.171536] Key type id_resolver registered
[ 0.171556] Key type id_legacy registered
[ 0.173453] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[ 0.173599] io scheduler noop registered
[ 0.173621] io scheduler deadline registered (default)
[ 0.173913] io scheduler cfq registered
[ 0.173934] io scheduler mq-deadline registered
[ 0.173953] io scheduler kyber registered
[ 0.176256] BCM2708FB: allocated DMA memory fad00000
[ 0.176301] BCM2708FB: allocated DMA channel 0 @ bb813000
[ 0.184848] Console: switching to colour frame buffer device 82x26
[ 0.192194] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[ 0.195689] bcm2835-rng 3f104000.rng: hwrng registered
[ 0.198106] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[ 0.203240] vc-sm: Videocore shared memory driver
[ 0.205823] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[ 0.220020] brd: module loaded
[ 0.230913] loop: module loaded
[ 0.233227] Loading iSCSI transport class v2.0-870.
[ 0.236180] libphy: Fixed MDIO Bus: probed
[ 0.238519] usbcore: registered new interface driver lan78xx
[ 0.240815] usbcore: registered new interface driver smsc95xx
[ 0.243052] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 0.470937] Core Release: 2.80a
[ 0.473208] Setting default values for core params
[ 0.475523] Finished setting default values for core params
[ 0.678127] Using Buffer DMA mode
[ 0.680449] Periodic Transfer Interrupt Enhancement - disabled
[ 0.682908] Multiprocessor Interrupt Enhancement - disabled
[ 0.685336] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 0.687718] Dedicated Tx FIFOs mode
[ 0.690371] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xbad14000 dma = 0xfad14000 len=9024
[ 0.695093] FIQ FSM acceleration enabled for :
[ 0.695093] Non-periodic Split Transactions
[ 0.695093] Periodic Split Transactions
[ 0.695093] High-Speed Isochronous Endpoints
[ 0.695093] Interrupt/Control Split Transaction hack enabled
[ 0.706239] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x805d2774
[ 0.708524] WARN::hcd_init_fiq:460: FIQ ASM at 0x805d2adc length 36
[ 0.710789] WARN::hcd_init_fiq:486: MPHI regs_base at 0xbb87e000
[ 0.713067] dwc_otg 3f980000.usb: DWC OTG Controller
[ 0.715389] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[ 0.717757] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[ 0.720082] Init: Port Power? op_state=1
[ 0.722370] Init: Power Port (0)
[ 0.724758] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 0.727075] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.729377] usb usb1: Product: DWC OTG Controller
[ 0.731646] usb usb1: Manufacturer: Linux 4.14.30-v7+ dwc_otg_hcd
[ 0.733928] usb usb1: SerialNumber: 3f980000.usb
[ 0.736779] hub 1-0:1.0: USB hub found
[ 0.738991] hub 1-0:1.0: 1 port detected
[ 0.741851] usbcore: registered new interface driver usb-storage
[ 0.744141] mousedev: PS/2 mouse device common for all mice
[ 0.746361] IR NEC protocol handler initialized
[ 0.748530] IR RC5(x/sz) protocol handler initialized
[ 0.750729] IR RC6 protocol handler initialized
[ 0.752924] IR JVC protocol handler initialized
[ 0.755001] IR Sony protocol handler initialized
[ 0.757085] IR SANYO protocol handler initialized
[ 0.759169] IR Sharp protocol handler initialized
[ 0.761153] IR MCE Keyboard/mouse protocol handler initialized
[ 0.763189] IR XMP protocol handler initialized
[ 0.765858] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[ 0.768197] bcm2835-cpufreq: min=600000 max=1400000
[ 0.770653] sdhci: Secure Digital Host Controller Interface driver
[ 0.772803] sdhci: Copyright(c) Pierre Ossman
[ 0.775229] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[ 0.777690] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[ 0.779973] sdhci-pltfm: SDHCI platform and OF driver helper
[ 0.783600] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.785987] hidraw: raw HID events driver (C) Jiri Kosina
[ 0.788442] usbcore: registered new interface driver usbhid
[ 0.790742] usbhid: USB HID core driver
[ 0.793602] vchiq: vchiq_init_state: slot_zero = bad80000, is_master = 0
[ 0.797269] [vc_sm_connected_init]: start
[ 0.805959] [vc_sm_connected_init]: end - returning 0
[ 0.808802] Initializing XFRM netlink socket
[ 0.811173] NET: Registered protocol family 17
[ 0.813642] Key type dns_resolver registered
[ 0.816398] Registering SWP/SWPB emulation handler
[ 0.819424] registered taskstats version 1
[ 0.827771] uart-pl011 3f201000.serial: cts_event_workaround enabled
[ 0.830329] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[ 0.836862] console [ttyS0] disabled
[ 0.839302] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 166, base_baud = 31250000) is a 16550
[ 1.877274] console [ttyS0] enabled
[ 1.884158] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[ 1.892553] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[ 1.952021] sdhost: log_buf @ bad13000 (fad13000)
[ 1.991476] Indeed it is in host mode hprt0 = 00021501
[ 2.063140] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 2.072750] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 2.081401] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 2.090229] of_cfs_init
[ 2.095030] of_cfs_init: OK
[ 2.100494] Waiting for root device PARTUUID=4ea08631-02...
[ 2.109762] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 2.120459] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 2.191515] mmc1: new high speed SDIO card at address 0001
[ 2.221496] usb 1-1: new high-speed USB device number 2 using dwc_otg
[ 2.230383] Indeed it is in host mode hprt0 = 00001101
[ 2.471615] usb 1-1: New USB device found, idVendor=0424, idProduct=2514
[ 2.480631] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 2.510746] hub 1-1:1.0: USB hub found
[ 2.516785] hub 1-1:1.0: 4 ports detected
[ 2.841393] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 2.971609] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514
[ 2.980728] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 2.990830] hub 1-1.1:1.0: USB hub found
[ 2.997017] hub 1-1.1:1.0: 3 ports detected
[ 203.752220] random: crng init done

So it gets as far as fetching and booting the kernel from USB flash but then the USB flash isn't detected by the kernel. I tried removing and replugging the USB flash (before the "random: crng init done" shows up) but that didn't help.

@pelwell
Copy link
Contributor

pelwell commented Apr 11, 2018

Four fast flashes means "Start not found", as reported by bootcode.bin when the load fails for any reason.

The 10 flashes on shutdown is just a visual indication that shutdown has completed successfully.

Comparing the successful and unsuccessful boots, after removing the timestamps and a certain amount of reordering you get:

--- good.txt       2018-04-11 14:32:21.130087600 +0100
+++ bad.txt       2018-04-11 14:32:18.506254500 +0100
@@ -200,41 +200,4 @@
 usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
 hub 1-1.1:1.0: USB hub found
 hub 1-1.1:1.0: 3 ports detected
-dwc_otg_handle_wakeup_detected_intr lxstate = 2
-usb 1-1.1.1: new high-speed USB device number 4 using dwc_otg
-usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800
-usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
-libphy: lan78xx-mdiobus: probed
-usb 1-1.1.3: new high-speed USB device number 5 using dwc_otg
-usb 1-1.1.3: New USB device found, idVendor=0781, idProduct=5583
-usb 1-1.1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
-usb 1-1.1.3: Product: Ultra Fit
-usb 1-1.1.3: Manufacturer: SanDisk
-usb 1-1.1.3: SerialNumber: 4C530001220114110455
-usb-storage 1-1.1.3:1.0: USB Mass Storage device detected
-scsi host0: usb-storage 1-1.1.3:1.0
-scsi 0:0:0:0: Direct-Access SanDisk Ultra Fit 1.00 PQ: 0 ANSI: 6
-sd 0:0:0:0: [sda] 240254976 512-byte logical blocks: (123 GB/115 GiB)
-sd 0:0:0:0: [sda] Write Protect is off
-sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
-sda: sda1 sda2
-sd 0:0:0:0: [sda] Attached SCSI removable disk
-EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
-VFS: Mounted root (ext4 filesystem) readonly on device 8:2.
-devtmpfs: mounted
-Freeing unused kernel memory: 1024K
-systemd[1]: System time before build time, advancing clock.
-NET: Registered protocol family 10
-Segment Routing with IPv6
-ip_tables: (C) 2000-2006 Netfilter Core Team
-systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
-systemd[1]: Detected architecture arm.
-systemd[1]: Set hostname to .
-systemd[1]: Listening on udev Kernel Socket.
-systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
-systemd[1]: Listening on Syslog Socket.
-systemd[1]: Created slice User and Session Slice.
-systemd[1]: Started Forward Password Requests to Wall Directory Watch.
-systemd[1]: Reached target Swap.
-systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
 random: crng init done

In other words, the kernel just isn't seeing any USB devices, including the built-in Ethernet controller - just the hubs.

@JamesH65
Copy link
Contributor

Probably not related, but thought I would mention it, if I fail to update the modules to match the kernel when testing a new kernel, lack of USB is the major symptom. That would probably be indicated in the logs though.

@pelwell
Copy link
Contributor

pelwell commented Apr 11, 2018

Good point, but I don't think it's relevant in this case because in @burtyb's case the failure is intermittent and for @hoopsurfer it is board- (not model-) specific.

@hoopsurfer Try adding the following to config.txt:

sdram_freq=450
arm_freq=1200

@hoopsurfer
Copy link
Author

hoopsurfer commented Apr 12, 2018

Swapping out a GoodPi with a BadPi (everything attached/inserted is identical) fails to reboot with
sdram_freq=450
arm_freq=1200
it also fails with
sdram_freq=400
arm_freq=1000
I diffed logs (dmesg --notime) and they are identical with just a few minor ordering differences. At this point I'm thinking I send my BadPi back as defective and call it a day.

BTW, the four rapid flashes with no SD card are very rapid compared with the 4 flashes on reboot failures, still not clear what those mean since the happen on both GoodPi and BadPi and everything is working fine aside from the repeating flashes.

@Nilpo
Copy link

Nilpo commented Apr 12, 2018

I have 2 Pi 3 B+ that are exhibiting the exact same 4 flash behavior when using any firmware from 2018. When booting 2017 versions, I can boot successfully to the GPU test screen with a lightning bolt indicating outdated firmware. I can successfully boot into older releases of NOOBS and Raspbian, but again only those on 2017 firmware. I have returned and replaced both Pis already and they have all exhibited the exact same behavior. All of them were sourced from the same supplier.

@hoopsurfer
Copy link
Author

After sitting idle for the better part of 3 days, GoodPi failed an attempted reboot, after a power cycle it did boot and then reboot and seems to consistently reboot successfully again (tried 5 times). Something is not stable about 3B+ reboot behavior at least when booting from a USB device. I am using a tested 2.5A power adapter. Maybe if I let BadPi sit idle for 3 days it will start to reboot again. : )

@ghollingworth
Copy link
Contributor

@hoopsurfer Just looking into this a little, but starting by adding a whole tonne of changes to get some logging out...

To confirm your problems:

When you say failed to reboot, can you be more specific: How far does it get? Can you get a video of the Pi rebooting and failing showing both the LEDs and the HDMI output? Just want to make sure it is failing at the same point.

@hoopsurfer
Copy link
Author

hoopsurfer commented Apr 16, 2018

Fail to reboot from USB consistently on one of my 3B+ BadPi means:

  1. Issue "reboot" command in terminal
  2. The BadPi goes through shutdown/reboot process via systemd
  3. Red LED goes out briefly then turns back on
  4. The Green LED starts flashing 4 times over and over the 4th being a longer flash
    flash - flash - flash - longerflash - flash - flash - flash - longerflash . . .

Nothing shows on he screen.

I'll capture a video Monday.

@ghollingworth
Copy link
Contributor

I think this means it failed to find start.elf but the LED is inverted and therefore the dashes are actually the on and the flashes are the 'off'

I'm just not sure about whether we've correctly inverted the flash in bootcode.bin

Gordon

@hoopsurfer
Copy link
Author

When preping to create a video, it appears GoodPi has now become a BadPi much to my disappointment. Reboot fails with or without a blank SD now. IF we assume inverted LEDs causes the long flash. What is going to cause failure to find start.elf when it consistently IS found on boot from power-off?

@Nilpo
Copy link

Nilpo commented Apr 17, 2018

It's worth mentioning that USB booting is still officially considered an experimental feature, isn't it?

@Nilpo
Copy link

Nilpo commented Apr 17, 2018

Also, bad start.elf is short-short-short-short-long-long-long-long, is it not? Doesn't it do the same number of shorts and longs. It has in every instance for me.

@pelwell
Copy link
Contributor

pelwell commented Apr 17, 2018

It sounds like an intermittent (or environmentally sensitive) failure of the USB subsystem to reset properly during a reboot. We'll try to reproduce.

@pelwell
Copy link
Contributor

pelwell commented Apr 17, 2018

My comment above is possibly more to relevant to @burtyb. @ghollingworth is currently hard at work on bootcode.bin, so may have something to share later.

@hoopsurfer
Copy link
Author

After leaving that system off for the past day and restarting it, it now reboots consistently including multiple USB devices. Now we're back to GoodPi. I cannot explain the change.

@hoopsurfer
Copy link
Author

hoopsurfer commented Apr 19, 2018

@Nilpo we're talking Pi 3B+, which boots from USB by default, no wonky bit setting required. For me when reboot fails it is short short short long (repeating). When no SD card is present boot works but I see blink blink blink blink (repeating flashes). When shutdown it is short short short short short short short short short short (once). Same on multiple boards however I still have two BadPi (will not reboot) and one GoodPi (mostly reboots). I did reboot testing for some benchmarks and GoodPi did 30-40 in a row no problems (with and without SD cards and with multiple USB mSATA SSDs).

@rprr
Copy link

rprr commented May 2, 2018

I suppose that the reboot issues when netbooting could be related. I too get the repeated sequence of 4 flashes -- 3 short and 1 long. /var/log/sysconfig says that start.elf is not found.

@Nilpo
Copy link

Nilpo commented May 2, 2018

My issues turned out to be related to HDMI.

popcornmix added a commit that referenced this issue May 18, 2018
kernel: firmware/raspberrypi: Notify firmware of a reboot
See: #968

kernel: config: Add CONFIG_DM_CACHE
See: raspberrypi/linux#2553

kernel: Cleanup of bcm2708_fb file to kernel coding standards

kernel: Add ability to export the pin used by the gpio-poweroff driver
See: raspberrypi/linux#2552

kernel: Revert: Sets the BCDC priority to constant 0

firmware: vc_image: vc_image_fill_yuv_uv sometimes overfilled the first column
See: raspberrypi/userland#465

firmware: arm_loader: Add SET_NOTIFY_REBOOT message
See: #968

firmware: gencmd: Report temperature with read_ring_osc values
popcornmix added a commit to Hexxeh/rpi-firmware that referenced this issue May 18, 2018
kernel: firmware/raspberrypi: Notify firmware of a reboot
See: raspberrypi/firmware#968

kernel: config: Add CONFIG_DM_CACHE
See: raspberrypi/linux#2553

kernel: Cleanup of bcm2708_fb file to kernel coding standards

kernel: Add ability to export the pin used by the gpio-poweroff driver
See: raspberrypi/linux#2552

kernel: Revert: Sets the BCDC priority to constant 0

firmware: vc_image: vc_image_fill_yuv_uv sometimes overfilled the first column
See: raspberrypi/userland#465

firmware: arm_loader: Add SET_NOTIFY_REBOOT message
See: raspberrypi/firmware#968

firmware: gencmd: Report temperature with read_ring_osc values
@hoopsurfer
Copy link
Author

I have now spent some more time looking at the reboot issue using two 3B+ devices. From hours of reboot testing I would say that with a USB mSATA attached I get random results when rebooting - sometimes it works sometimes it fails, once it works it seems to work for a while, once it fails it fails for a while. I cannot predict when it will work or fail or find any series of steps that causes a consistent result.

In my case both 3B+ devices ALWAYS boot correctly (from power off), but often reboot can fail with the four flashing LEDs. Reboot failure means the system effectively hangs, power needs to be cycled to reboot. Forcing fsck doesn't generally make a difference, running with or without a blank SD card seems to make no difference.

I need help debugging reboot failures.

@burtyb
Copy link

burtyb commented Jun 22, 2018

I saw there had been a couple of commits referencing this issue so I just tested with the latest rpi-update kernel to see if there had been any improvements in reboots on USB devices but things are now worse (doesn't reboot at all) - not sure if it's this known/expected atm?

Using a fresh Raspbian Lite 2018-04-18 on an 16GB Sandisk Ultra Fit in a Pi3+

Adding "uart_enable=1" to config.txt.

It boots OK on 4.14.34-v7+ and does the normal resize and reboot.

sudo apt-get update && sudo apt-get -y dist-upgrade

sudo reboot

Boots into new 4.14.34-v7+ kernel.

sudo reboot

Again boots into 4.14.34-v7+ kernel OK.

sudo rpi-update

It updates to "fe525d2be041c1a9b924824e430b5d51214315c4", "4.14.50-v7+ #1122 SMP Tue Jun 19 12:26:26 BST 2018"

sudo reboot

Boots into new 4.14.50-v7+ kernel.

sudo reboot

I see the following on the serial console as it restarts.

...
[ OK ] Reached target Unmount All Filesystems.
[ OK ] Stopped File System Check on /dev/disk/by-partuuid/00291d5e-01.
[ OK ] Removed slice system-systemd\x2dfsck.slice.
[ OK ] Stopped target Local File Systems (Pre).
[ OK ] Stopped Create Static Device Nodes in /dev.
[ OK ] Stopped Remount Root and Kernel File Systems.
[ OK ] Reached target Shutdown.
[ 33.161393] reboot: Restarting system

And then both the PWR and ACT LED go OFF and never come back on. There's no sign of the boot process starting on the serial and the USB device is never powered back on either (I can measure 5.1919v / 3.2982v on the gpio header so power looks OK).

After cycling the power it boots up OK but again doesn't come back when rebooted.

Repeating the above steps with a"Crucial Gizmo! USB Device 8GB" it also fails. But on an SD card it works OK.

@ghollingworth
Copy link
Contributor

I think we need to look back into the gpio expander driver again, I don't think it is properly resetting the LAN9515 at boot time, which it should do via the LAN_RUN_BOOT pin. But this requires that the LAN_RUN pin on the gpio_expander is tri-stated.

@ghollingworth
Copy link
Contributor

Oops... Didn't mean to close!

@pelwell
Copy link
Contributor

pelwell commented Jun 23, 2018

I was looking at this before leaving yesterday, and I think the problem must be that the VPU code to restore the internal LAN_RUN GPIO (LAN_RUN_BOOT) is clearing the (default) pull down setting, causing it to float. Sometimes this works, and sometimes it doesn't.

I'll build and link to a modified start.elf for testing.

@pelwell
Copy link
Contributor

pelwell commented Jun 26, 2018

The change I mentioned above didn't work, so I didn't bother uploading it. We're puzzled, but actively investigating the possible differences between a first-time boot and a reboot.

popcornmix added a commit that referenced this issue Jun 29, 2018
See: #968

firmware: Allow selection of DSI port for LCD
popcornmix added a commit to Hexxeh/rpi-firmware that referenced this issue Jun 29, 2018
@ghollingworth
Copy link
Contributor

Fixed on latest build

@hoopsurfer
Copy link
Author

Reconfirmed the original failure on current public firmware from 2018-06-07 15:30 running Linux 4.14.50-v7+ 1122 SMP Tue Jun 19 12:26:26 BST 2018.

Tested after rpi-update to latest build firmware from 2018-06-29 13:12 running Linux 4.14.52-v7+ 1123 SMP Wed Jun 27 17:35:49 BST 2018 for 4 hours of continuous reboots with 100% success.

I am no longer able to reproduce the reboot failure - consider #968 tested fixed. Thanks!

@polishcode
Copy link

Hi all,

Although 3 years have passed I am currently experiencing the same issue.
My setup:

  • pi 3b+
  • all latest updates installed (pi os)
  • sd card with (latest) bootcode.bin + timeout empty file
  • 1 * usb bootable pendrive with pi os
  • 3 * usb 2.0<->sata adapters each connected to 1 TB drive creating raid array (1 logical disk)
  • external power supply powering all: pi + disks
  • ethernet cable connected to router
  • wifi + bt disabled in config files

Cold boot always succeeds.
Restart is unreliable: sometimes succeeds, sometimes fails. When it fails there is no HDMI output, green LED flashes 4 short + 1 long (if I count correctly). Power off/on fixes issue. However, I need that in a remote location, so no easy way to do cold reboot when it fails.

Setup utilized as a low-power backup NAS in secondary location.

Any help or debugging guidance appreciated.

image

@polishcode
Copy link

Also, in case reboot fails:

  • power LED in pendrive stays off
  • data LEDs (blue) in usb<->sata adapters are off
    It looks as if during such a reboot USB subsystem failed to somehow initialize.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

8 participants