"shutdown -r now" hangs after "freebsd-update upgrade -r 10.3-RELEASE"

Today I've upgraded one of my machines from 10.2-RELEASE to 10.3-RELEASE as per https://www.freebsd.org/releases/10.3R/installation.html#upgrade-binary and then I did shutdown -r now
After couple of minutes I realized the machine is not going to "show up" and I headed to the physical location of the machine, it was hanging on the reboot, here are the related lines:
Code:
Apr 19 08:52:15 daemon shutdown: reboot by booster:
Apr 19 08:52:16 daemon kernel: No such file or directory
Apr 19 08:52:16 daemon kernel: Stopping jails:
Apr 19 08:52:16 daemon kernel: games
Apr 19 08:52:17 daemon kernel: mail
Apr 19 08:52:18 daemon kernel: www
Apr 19 08:52:28 daemon kernel: jail: www: /sbin/umount -t nullfs /usr/jails/www/basejail: failed
Apr 19 08:52:28 daemon kernel: .
Apr 19 08:52:31 daemon ntpd[671]: ntpd exiting on signal 15 (Terminated)
Apr 19 08:52:32 daemon kernel: , 671.
Apr 19 08:52:32 daemon syslogd: exiting on signal 15
Apr 19 09:31:46 daemon syslogd: kernel boot file is /boot/kernel/kernel
Apr 19 09:31:46 daemon kernel: Waiting (max 60 seconds) for system process `vnlru' to stop...done
Apr 19 09:31:46 daemon kernel: Waiting (max 60 seconds) for system process `bufdaemon' to stop...done
Apr 19 09:31:46 daemon kernel: Waiting (max 60 seconds) for system process `syncer' to stop...
Apr 19 09:31:46 daemon kernel: Syncing disks, vnodes remaining...0 0 0 0 done
Apr 19 09:31:46 daemon kernel: All buffers synced.
Apr 19 09:31:46 daemon kernel: Copyright (c) 1992-2016 The FreeBSD Project.
Apr 19 09:31:46 daemon kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
Apr 19 09:31:46 daemon kernel: The Regents of the University of California. All rights reserved.
Apr 19 09:31:46 daemon kernel: FreeBSD is a registered trademark of The FreeBSD Foundation.
Apr 19 09:31:46 daemon kernel: FreeBSD 10.3-RELEASE #0 r297264: Fri Mar 25 02:10:02 UTC 2016
Apr 19 09:31:46 daemon kernel: root@releng1.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC amd64
Apr 19 09:31:46 daemon kernel: FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
Apr 19 09:31:46 daemon kernel: CPU: Intel(R) Core(TM)2 Quad CPU  Q6600  @ 2.40GHz (2400.14-MHz K8-class CPU)
Apr 19 09:31:46 daemon kernel: Origin="GenuineIntel"  Id=0x6fb  Family=0x6  Model=0xf  Stepping=11
Apr 19 09:31:46 daemon kernel: Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
Apr 19 09:31:46 daemon kernel: Features2=0xe3bd<SSE3,DTES64,MON,DS_CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM>
Apr 19 09:31:46 daemon kernel: AMD Features=0x20100800<SYSCALL,NX,LM>
Apr 19 09:31:46 daemon kernel: AMD Features2=0x1<LAHF>
Apr 19 09:31:46 daemon kernel: VT-x: HLT,PAUSE
Apr 19 09:31:46 daemon kernel: TSC: P-state invariant, performance statistics
Apr 19 09:31:46 daemon kernel: real memory  = 4294967296 (4096 MB)
Apr 19 09:31:46 daemon kernel: avail memory = 4109955072 (3919 MB)
Apr 19 09:31:46 daemon kernel: Event timer "LAPIC" quality 400
Apr 19 09:31:46 daemon kernel: ACPI APIC Table: <INTEL  S3000AH>
Apr 19 09:31:46 daemon kernel: FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
Apr 19 09:31:46 daemon kernel: FreeBSD/SMP: 1 package(s) x 4 core(s)
Apr 19 09:31:46 daemon kernel: cpu0 (BSP): APIC ID:  0
Apr 19 09:31:46 daemon kernel: cpu1 (AP): APIC ID:  1
Apr 19 09:31:46 daemon kernel: cpu2 (AP): APIC ID:  2
Apr 19 09:31:46 daemon kernel: cpu3 (AP): APIC ID:  3
Apr 19 09:31:46 daemon kernel: random: <Software, Yarrow> initialized
Apr 19 09:31:46 daemon kernel: ACPI BIOS Warning (bug): 32/64X length mismatch in FADT/Pm1aEventBlock: 32/16 (20150515/tbfadt-644)
Apr 19 09:31:46 daemon kernel: ACPI BIOS Warning (bug): 32/64X length mismatch in FADT/PmTimerBlock: 32/24 (20150515/tbfadt-644)
Apr 19 09:31:46 daemon kernel: ACPI BIOS Warning (bug): Invalid length for FADT/Pm1aEventBlock: 16, using default 32 (20150515/tbfadt-725)
Apr 19 09:31:46 daemon kernel: ACPI BIOS Warning (bug): Invalid length for FADT/PmTimerBlock: 24, using default 32 (20150515/tbfadt-725)
Apr 19 09:31:46 daemon kernel: ioapic0: Changing APIC ID to 5
Apr 19 09:31:46 daemon kernel: ioapic0 <Version 2.0> irqs 0-23 on motherboard
Apr 19 09:31:46 daemon kernel: kbd1 at kbdmux0
Apr 19 09:31:46 daemon kernel: acpi0: <INTEL S3000AH> on motherboard
Apr 19 09:31:46 daemon kernel: acpi0: Power Button (fixed)
Apr 19 09:31:46 daemon kernel: cpu0: <ACPI CPU> on acpi0
Apr 19 09:31:46 daemon kernel: cpu1: <ACPI CPU> on acpi0
Apr 19 09:31:46 daemon kernel: cpu2: <ACPI CPU> on acpi0
Apr 19 09:31:46 daemon kernel: cpu3: <ACPI CPU> on acpi0
Apr 19 09:31:46 daemon kernel: atrtc0: <AT realtime clock> port 0x70-0x71,0x74-0x77 irq 8 on acpi0
Apr 19 09:31:46 daemon kernel: Event timer "RTC" frequency 32768 Hz quality 0
Apr 19 09:31:46 daemon kernel: attimer0: <AT timer> port 0x40-0x43,0x50-0x53 irq 0 on acpi0
Apr 19 09:31:46 daemon kernel: Timecounter "i8254" frequency 1193182 Hz quality 0
Apr 19 09:31:46 daemon kernel: Event timer "i8254" frequency 1193182 Hz quality 100
Apr 19 09:31:46 daemon kernel: hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on acpi0
Apr 19 09:31:46 daemon kernel: Timecounter "HPET" frequency 14318180 Hz quality 950
Apr 19 09:31:46 daemon kernel: Event timer "HPET" frequency 14318180 Hz quality 450
Apr 19 09:31:46 daemon kernel: Event timer "HPET1" frequency 14318180 Hz quality 440
Apr 19 09:31:46 daemon kernel: Event timer "HPET2" frequency 14318180 Hz quality 440
Apr 19 09:31:46 daemon kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
Apr 19 09:31:46 daemon kernel: acpi_timer0: <24-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
Apr 19 09:31:46 daemon kernel: acpi_button0: <Sleep Button> on acpi0
Apr 19 09:31:46 daemon kernel: pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
Apr 19 09:31:46 daemon kernel: pcib0: Length mismatch for 3 range: 6c00000 vs 6bfffff
Apr 19 09:31:46 daemon kernel: pcib0: Length mismatch for 3 range: 10000001 vs 10000000
Apr 19 09:31:46 daemon kernel: pci0: <ACPI PCI bus> on pcib0
Apr 19 09:31:46 daemon kernel: pcib1: <ACPI PCI-PCI bridge> at device 28.0 on pci0
Apr 19 09:31:46 daemon kernel: pci1: <ACPI PCI bus> on pcib1
Apr 19 09:31:46 daemon kernel: pcib2: <ACPI PCI-PCI bridge> at device 28.4 on pci0
Apr 19 09:31:46 daemon kernel: pci2: <ACPI PCI bus> on pcib2
Apr 19 09:31:46 daemon kernel: pcib3: <ACPI PCI-PCI bridge> at device 28.5 on pci0
Apr 19 09:31:46 daemon kernel: pci3: <ACPI PCI bus> on pcib3
Apr 19 09:31:46 daemon kernel: em0: <Intel(R) PRO/1000 Network Connection 7.6.1-k> port 0x2000-0x201f mem 0xe8180000-0xe819ffff,0xe8100000-0xe817ffff irq 17 at device 0.0 on pci3
Apr 19 09:31:46 daemon kernel: em0: Using an MSI interrupt
Apr 19 09:31:46 daemon kernel: em0: Ethernet address: 00:15:17:50:1c:8f
Apr 19 09:31:46 daemon kernel: pci3: <simple comms, UART> at device 0.3 (no driver attached)
Apr 19 09:31:46 daemon kernel: pci3: <serial bus> at device 0.4 (no driver attached)
Apr 19 09:31:46 daemon kernel: uhci0: <Intel 82801G (ICH7) USB controller USB-A> port 0x3080-0x309f irq 23 at device 29.0 on pci0
Apr 19 09:31:46 daemon kernel: uhci0: LegSup = 0x2f00
Apr 19 09:31:46 daemon kernel: usbus0 on uhci0
Apr 19 09:31:46 daemon kernel: uhci1: <Intel 82801G (ICH7) USB controller USB-B> port 0x3060-0x307f irq 19 at device 29.1 on pci0
Apr 19 09:31:46 daemon kernel: uhci1: LegSup = 0x2f00
Apr 19 09:31:46 daemon kernel: usbus1 on uhci1
Apr 19 09:31:46 daemon kernel: uhci2: <Intel 82801G (ICH7) USB controller USB-C> port 0x3040-0x305f irq 18 at device 29.2 on pci0
Apr 19 09:31:46 daemon kernel: uhci2: LegSup = 0x2f00
Apr 19 09:31:46 daemon kernel: usbus2 on uhci2
Apr 19 09:31:46 daemon kernel: uhci3: <Intel 82801G (ICH7) USB controller USB-D> port 0x3020-0x303f irq 16 at device 29.3 on pci0
Apr 19 09:31:46 daemon kernel: uhci3: LegSup = 0x2f00
Apr 19 09:31:46 daemon kernel: usbus3 on uhci3
Apr 19 09:31:46 daemon kernel: ehci0: <Intel 82801GB/R (ICH7) USB 2.0 controller> mem 0xe8200400-0xe82007ff irq 23 at device 29.7 on pci0
Apr 19 09:31:46 daemon kernel: usbus4: waiting for BIOS to give up control
Apr 19 09:31:46 daemon kernel: usbus4: timed out waiting for BIOS
Apr 19 09:31:46 daemon kernel: usbus4: EHCI version 1.0
Apr 19 09:31:46 daemon kernel: usbus4 on ehci0
Apr 19 09:31:46 daemon kernel: pcib4: <ACPI PCI-PCI bridge> at device 30.0 on pci0
Apr 19 09:31:46 daemon kernel: pci4: <ACPI PCI bus> on pcib4
Apr 19 09:31:46 daemon kernel: vgapci0: <VGA-compatible display> port 0x1000-0x10ff mem 0xe0000000-0xe7ffffff,0xe8040000-0xe804ffff irq 18 at device 4.0 on pci4
Apr 19 09:31:46 daemon kernel: vgapci0: Boot video device
Apr 19 09:31:46 daemon kernel: em1: <Intel(R) PRO/1000 Legacy Network Connection 1.1.0> port 0x1100-0x113f mem 0xe8020000-0xe803ffff,0xe8000000-0xe801ffff irq 17 at device 5.0 on pci4
Apr 19 09:31:46 daemon kernel: em1: Ethernet address: 00:15:17:50:1c:90
Apr 19 09:31:46 daemon kernel: isab0: <PCI-ISA bridge> at device 31.0 on pci0
Apr 19 09:31:46 daemon kernel: isa0: <ISA bus> on isab0
Apr 19 09:31:46 daemon kernel: atapci0: <Intel ICH7 SATA300 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x30a0-0x30af mem 0xe8200000-0xe82003ff irq 19 at device 31.2 on pci0
Apr 19 09:31:46 daemon kernel: ata0: <ATA channel> at channel 0 on atapci0
Apr 19 09:31:46 daemon kernel: ata1: <ATA channel> at channel 1 on atapci0
Apr 19 09:31:46 daemon kernel: fdc0: <floppy drive controller> port 0x3f0-0x3f5,0x3f0 irq 6 drq 2 on acpi0
Apr 19 09:31:46 daemon kernel: orm0: <ISA Option ROM> at iomem 0xc0000-0xc8fff on isa0
Apr 19 09:31:46 daemon kernel: sc0: <System console> at flags 0x100 on isa0
Apr 19 09:31:46 daemon kernel: sc0: VGA <16 virtual consoles, flags=0x300>
Apr 19 09:31:46 daemon kernel: vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
Apr 19 09:31:46 daemon kernel: atkbdc0: <Keyboard controller (i8042)> at port 0x60,0x64 on isa0
Apr 19 09:31:46 daemon kernel: atkbd0: <AT Keyboard> irq 1 on atkbdc0
Apr 19 09:31:46 daemon kernel: kbd0 at atkbd0
Apr 19 09:31:46 daemon kernel: atkbd0: [GIANT-LOCKED]
Apr 19 09:31:46 daemon kernel: ppc0: cannot reserve I/O port range
Apr 19 09:31:46 daemon kernel: est0: <Enhanced SpeedStep Frequency Control> on cpu0
Apr 19 09:31:46 daemon kernel: est1: <Enhanced SpeedStep Frequency Control> on cpu1
Apr 19 09:31:46 daemon kernel: est2: <Enhanced SpeedStep Frequency Control> on cpu2
Apr 19 09:31:46 daemon kernel: est3: <Enhanced SpeedStep Frequency Control> on cpu3
Apr 19 09:31:46 daemon kernel: ZFS NOTICE: Prefetch is disabled by default if less than 4GB of RAM is present;
Apr 19 09:31:46 daemon kernel: to enable, add "vfs.zfs.prefetch_disable=0" to /boot/loader.conf.
Apr 19 09:31:46 daemon kernel: ZFS filesystem version: 5
Apr 19 09:31:46 daemon kernel: ZFS storage pool version: features support (5000)
Apr 19 09:31:46 daemon kernel: Timecounters tick every 1.000 msec
Apr 19 09:31:46 daemon kernel: random: unblocking device.
Apr 19 09:31:46 daemon kernel: usbus0: 12Mbps Full Speed USB v1.0
Apr 19 09:31:46 daemon kernel: usbus1: 12Mbps Full Speed USB v1.0
Apr 19 09:31:46 daemon kernel: usbus2: 12Mbps Full Speed USB v1.0
Apr 19 09:31:46 daemon kernel: usbus3: 12Mbps Full Speed USB v1.0
Apr 19 09:31:46 daemon kernel: usbus4: 480Mbps High Speed USB v2.0
Apr 19 09:31:46 daemon kernel: ugen0.1: <Intel> at usbus0
Apr 19 09:31:46 daemon kernel: uhub0: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0
Apr 19 09:31:46 daemon kernel: ugen3.1: <Intel> at usbus3
Apr 19 09:31:46 daemon kernel: uhub1: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus3
Apr 19 09:31:46 daemon kernel: ugen2.1: <Intel> at usbus2
Apr 19 09:31:46 daemon kernel: uhub2: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus2
Apr 19 09:31:46 daemon kernel: ugen1.1: <Intel> at usbus1
Apr 19 09:31:46 daemon kernel: uhub3: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus1
Apr 19 09:31:46 daemon kernel: ugen4.1: <Intel> at usbus4
Apr 19 09:31:46 daemon kernel: uhub4: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus4
Apr 19 09:31:46 daemon kernel: uhub0: 2 ports with 2 removable, self powered
Apr 19 09:31:46 daemon kernel: uhub1: 2 ports with 2 removable, self powered
Apr 19 09:31:46 daemon kernel: uhub2: 2 ports with 2 removable, self powered
Apr 19 09:31:46 daemon kernel: uhub3: 2 ports with 2 removable, self powered
Apr 19 09:31:46 daemon kernel: ada0 at ata0 bus 0 scbus0 target 0 lun 0
Apr 19 09:31:46 daemon kernel: ada0: <ST3250620AS 3.AAK> ATA-7 SATA 2.x device
Apr 19 09:31:46 daemon kernel: ada0: Serial Number 6QF3EHAF
Apr 19 09:31:46 daemon kernel: ada0: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)
Apr 19 09:31:46 daemon kernel: ada0: 238475MB (488397168 512 byte sectors)
Apr 19 09:31:46 daemon kernel: ada0: Previously was known as ad0
Apr 19 09:31:46 daemon kernel: ada1 at ata1 bus 0 scbus1 target 0 lun 0
Apr 19 09:31:46 daemon kernel: ada1: <ST3250620AS 3.AAK> ATA-7 SATA 2.x device
Apr 19 09:31:46 daemon kernel: ada1: Serial Number 6QF3EJRM
Apr 19 09:31:46 daemon kernel: ada1: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)
Apr 19 09:31:46 daemon kernel: ada1: 238475MB (488397168 512 byte sectors)
Apr 19 09:31:46 daemon kernel: ada1: Previously was known as ad2
Apr 19 09:31:46 daemon kernel: SMP: AP CPU #2 Launched!
Apr 19 09:31:46 daemon kernel: SMP: AP CPU #1 Launched!
Apr 19 09:31:46 daemon kernel: SMP: AP CPU #3 Launched!
Apr 19 09:31:46 daemon kernel: Timecounter "TSC-low" frequency 1200068235 Hz quality 1000
Apr 19 09:31:46 daemon kernel: Root mount waiting for: usbus4
Apr 19 09:31:46 daemon kernel: Root mount waiting for: usbus4
Apr 19 09:31:46 daemon kernel: uhub4: 8 ports with 8 removable, self powered
Apr 19 09:31:46 daemon kernel: Trying to mount root from zfs:zroot/ROOT/default []...
Apr 19 09:31:46 daemon kernel: ugen2.2: <USB> at usbus2
Apr 19 09:31:46 daemon kernel: ukbd0: <USB USB Keykoard, class 0/0, rev 1.10/1.10, addr 2> on usbus2
Apr 19 09:31:46 daemon kernel: kbd2 at ukbd0
Apr 19 09:31:46 daemon kernel: uhid0: <USB USB Keykoard, class 0/0, rev 1.10/1.10, addr 2> on usbus2
Apr 19 09:31:46 daemon kernel: em0: link state changed to UP
Apr 19 09:31:47 daemon ntpd[676]: ntpd 4.2.8p6-a (1): Starting
Apr 19 09:31:50 daemon kernel: Starting jails:
Apr 19 09:31:58 daemon kernel: www
Apr 19 09:32:11 daemon kernel: mail
Apr 19 09:32:11 daemon root: /etc/rc.d/jail: WARNING: Per-jail configuration via jail_* variables  is obsolete.  Please consider to migrate to /etc/jail.conf.
Apr 19 09:32:11 daemon kernel: games.
Apr 19 09:32:52 daemon login: ROOT LOGIN (root) ON ttyv0
It's strange (because of the timestamps) that when I saw the screen once I got there about 40min after the reboot attempt it was showing "All buffers synced." at the bottom of the console and has hanging there, physically reseting the machine solved the problem and the rest of the upgrade process went fine.
So does anyone has an idea how to avoid this in future? Is it something I can do or it's just "not my fault"? For example I think next time I upgrade a machine I'll use reboot vs shutdown -r now.​
 
I see, thanks for the link. Still this is really annoying since I wasn't prepared for it and I was lucky to be around the machine (same town), it was going to be very bad if it was on another continent with nobody around to press the reset button... It's also strange to see this happen on 1 machine and not on another, I had upgraded my local router few days earlier and I didn't had that problem. If not fixed at least I think it may not be a bad idea to have some sort of warning here https://www.freebsd.org/releases/10.3R/installation.html#upgrade-binary so one can prepare for such scenario.
 
Before the next casual reboot, let's cp init oinit; rm init; cp oinit init. Will it correspond to the hang?

Juha

10.1-p10, simple diskwide GPT UFS, softupdates, no journaling, md swapfile, no hang from lingering init binary.
 
Is this happening only for users with jails running? I've done at least a dozen shutdown -r now, and no hangs yet. I've got other machines I can upgrade to test if someone wants. Does this happen only during the upgrade process, or does it continue on after the upgrade process is done?
 
Are there any USB drives attached? My home server hangs from time to time on the same thing. But only if the external USB drive is attached.
 
No USB devices attached to that machine, not even keyboard, just power and LAN cables attached
 
No USB devices attached to that machine, not even keyboard, just power and LAN cables attached
Have you tried putting in
Code:
hw.usb.no_shutdown_wait=1
(see posts above) anyway? I had similar (intermittent) issue that seemed to be fixed with that change.
 
I don't have a machine to upgrade anymore, but I've putted that anyway, it's not going to hurt in my case.
 
Back
Top