Re: Unclean shutdown for r273852 -> r273899 transition

From: O. Hartmann <ohartman_at_zedat.fu-berlin.de>
Date: Fri, 31 Oct 2014 20:30:17 +0100
Am Fri, 31 Oct 2014 06:59:12 -0700
David Wolfskill <david_at_catwhisker.org> schrieb:

> I thought it a bit odd when I rebooted after the "make installworld"
> completed and found that fsck(8) was checking teh file systems on my
> laptop.
> 
> When it also happened for my build machine, I suspected it might not
> merely be a one-off oddity... and I was able to make use of the serial
> console on the build machine.
> 
> THe laptop started out running:
> 
> FreeBSD g1-252.catwhisker.org 11.0-CURRENT FreeBSD 11.0-CURRENT #1412
> r273852M/273852:1100040: Thu Oct 30 05:25:51 PDT 2014
> root_at_g1-252.catwhisker.org:/common/S4/obj/usr/src/sys/CANARY  i386
> 
> this morning; I performed an in-place source upgrade to:
> 
> FreeBSD g1-252.catwhisker.org 11.0-CURRENT FreeBSD 11.0-CURRENT #1413
> r273899M/273900:1100041: Fri Oct 31 06:01:13 PDT 2014
> root_at_g1-252.catwhisker.org:/common/S4/obj/usr/src/sys/CANARY  i386
> 
> 
> Here's what things looked like on the cosnole for the build machine (which
> had been built from sources at the same revisions):
> 
> Oct 31 06:40:09 freebeast shutdown: reboot by david: 
> Stopping cron.
> Waiting for PIDS: 723.
> Stopping sshd.
> Waiting for PIDS: 713.
> Stopping rsyncd.
> Waiting for PIDS: 686.
> Stopping powerd.
> Waiting for PIDS: 671.
> Stopping ntpd.
> Waiting for PIDS: 668.
> Stopping lpd.
> Waiting for PIDS: 647.
> Stopping lockd.
> Waiting for PIDS: 630.
> Stopping statd.
> Waiting for PIDS: 627.
> Stopping nfsd.
> Waiting for PIDS: 623 624.
> Stopping mountd.
> Waiting for PIDS: 617.
> Stopping casperd.
> Waiting for PIDS: 595.
> Stopping amd.
> Waiting for PIDS: 587.
> Stopping ypbind.
> Waiting for PIDS: 582.
> Stopping rpcbind.
> Waiting for PIDS: 491.
> Stopping devd.
> Waiting for PIDS: 407.
> Writing entropy file:.
> .
> TermiOct 31 06:40:14 freebeast syslogd: exiting on signal 15
> Waiting (max 60 seconds) for system process `vnlru' to stop...done
> Waiting (max 60 seconds) for system process `syncer' to stop...
> Syncing disks, vnodes remaining...5 6 6 6 6 4 4 4 4 4 3 1 1 1 1 1 1 1 1 0 0 0 0 0 0 done
> Waiting (max 60 seconds) for system process `bufdaemon' to stop...done
> All buffers synced.
> lock order reversal:
>  1st 0xc7925388 ufs (ufs) _at_ /usr/src/sys/kern/vfs_mount.c:1223
>  2nd 0xc7a7a7f8 devfs (devfs) _at_ /usr/src/sys/ufs/ffs/ffs_vfsops.c:1375
> KDB: stack backtrace:
> db_trace_self_wrapper(c11ac524,c6da28c8,c156af90,c156afa4,e1fb9890,...) at
> db_trace_self_wrapper+0x2d/frame 0xe1fb9828
> kdb_backtrace(c11b00a9,c7a7a7f8,c11a2e94,c6daa3e0,c11e2149,...) at
> kdb_backtrace+0x30/frame 0xe1fb9890 witness_checkorder(c7a7a7f8,9,c11e2149,55f,0,...)
> at witness_checkorder+0xd0c/frame 0xe1fb98e0
> __lockmgr_args(c7a7a7f8,80400,c7a7a818,0,0,0,c11e2149,55f) at
> __lockmgr_args+0x8f3/frame 0xe1fb99bc
> vop_stdlock(e1fb9a30,c11e2149,63d,1244,c7a7a838,...) at vop_stdlock+0x4d/frame
> 0xe1fb99ec VOP_LOCK1_APV(c140ddac,e1fb9a30,0,0,c145ac60,...) at
> VOP_LOCK1_APV+0x10a/frame 0  ______               ____   _____ _____ |
> ____|             |  _ \ / ____|  __ \ | |___ _ __ ___  ___ | |_) | (___ | |  | | |
> ___| '__/ _ \/ _ \|  _ < \___ \| |  | | | |   | | |  __/  __/| |_) |____) | |__| | |
> |   | | |    |    ||     |      |      | |_|   |_|  \___|\___||____/|_____/|_____/
> ```                        ` s` `.....---.......--.```   -/ ... 
> 
> (The stack bactrace is obviously truncated.)
> 
> ...
> Booting...
> GDB: no debug ports present
> KDB: debugger backends: ddb
> KDB: current backend: ddb
> Copyright (c) 1992-2014 The FreeBSD Project.
> Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
>         The Regents of the University of California. All rights reserved.
> FreeBSD is a registered trademark of The FreeBSD Foundation.
> FreeBSD 11.0-CURRENT #1651  r273899M/273900:1100041: Fri Oct 31 06:31:31 PDT 2014
>     root_at_freebeast.catwhisker.org:/common/S4/obj/usr/src/sys/GENERIC i386
> FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
> WARNING: WITNESS option enabled, expect reduced performance.
> CPU: Intel(R) Xeon(TM) CPU 3.60GHz (3600.20-MHz 686-class CPU)
>   Origin="GenuineIntel"  Id=0xf41  Family=0xf  Model=0x4  Stepping=1
>   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>
>   Features2=0x659d<SSE3,DTES64,MON,DS_CPL,EST,TM2,CNXT-ID,CX16,xTPR>
>   AMD Features=0x20100000<NX,LM>
>   TSC: P-state invariant
> real memory  = 2147483648 (2048 MB)
> avail memory = 2077032448 (1980 MB)
> Event timer "LAPIC" quality 400
> ACPI APIC Table: <PTLTD          APIC  >
> FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
> FreeBSD/SMP: 2 package(s) x 1 core(s)
>  cpu0 (BSP): APIC ID:  0
>  cpu1 (AP): APIC ID:  6
> random device not loaded/active; using insecure pseudo-random number generator
> ioapic0 <Version 2.0> irqs 0-23 on motherboard
> ioapic1 <Version 2.0> irqs 24-47 on motherboard
> ioapic2 <Version 2.0> irqs 48-71 on motherboard
> random: entropy device infrastructure driver
> random: selecting highest priority adaptor <Dummy>
> kbd1 at kbdmux0
> random: SOFT: yarrow init()
> random: selecting highest priority adaptor <Yarrow>
> ...
> SMP: AP CPU #1 Launched!
> Timecounter "TSC-low" frequency 1800099747 Hz quality 1000
> WARNING: WITNESS option enabled, expect reduced performance.
> Trying to mount root from ufs:/dev/aacd0s4a [rw]...
> Setting hostuuid: 80f1e964-dc63-0010-89d5-0030482d326a.
> Setting hostid: 0xc74551dd.
> cp: /var/log/utx.lastlogin: No such file or directory
> chmod: /var/log/utx.lastlogin: No such file or directory
> cp: /var/log/utx.log: No such file or directory
> chmod: /var/log/utx.log: No such file or directory
> Starting file system checks:
> /dev/aacd0s4a: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd0s4a: clean, 234181 free (1941 frags, 29030 blocks, 0.5% fragmentation)
> /dev/aacd0s1a: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd0s1a: clean, 144421 free (1565 frags, 17857 blocks, 0.4% fragmentation)
> /dev/aacd1s1e: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd1s1e: clean, 2589387 free (211371 frags, 297252 blocks, 1.6% fragmentation)
> /dev/aacd0s1d: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd0s1d: clean, 275828 free (3876 frags, 33994 blocks, 0.4% fragmentation)
> /dev/aacd0s2a: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd0s2a: clean, 149425 free (97 frags, 18666 blocks, 0.0% fragmentation)
> /dev/aacd0s2d: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd0s2d: clean, 311378 free (218 frags, 38895 blocks, 0.0% fragmentation)
> /dev/aacd0s3a: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd0s3a: clean, 144465 free (1473 frags, 17874 blocks, 0.4% fragmentation)
> /dev/aacd0s3d: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd0s3d: clean, 279024 free (41032 frags, 29749 blocks, 4.6% fragmentation)
> /dev/aacd0s4d: NO WRITE ACCESS
> /dev/aacd0s4d: UNEXPECTED INCONSISTENCY; RUN fsck MANUALLY.
> /dev/aacd0s4f: FILE SYSTEM CLEAN; SKIPPING CHECKS
> /dev/aacd0s4f: clean, 2090552 free (592 frags, 261245 blocks, 0.0% fragmentation)
> THE FOLLOWING FILE SYSTEM HAD AN UNEXPECTED INCONSISTENCY:
>         ufs: /dev/aacd0s4d (/usr)
> File system preen failed, trying fsck -y 
> ** /dev/aacd0s4a
> ** Last Mounted on /
> ** Root file system
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 4306 files, 137698 used, 234181 free (1941 frags, 29030 blocks, 0.5% fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> ** /dev/aacd0s1a
> ** Last Mounted on /S1
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 10354 files, 227458 used, 144421 free (1565 frags, 17857 blocks, 0.4% fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> ** /dev/aacd0s1d
> ** Last Mounted on /S1/usr
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 146169 files, 619244 used, 275828 free (3876 frags, 33994 blocks, 0.4% fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> ** /dev/aacd0s2a
> ** Last Mounted on /S2
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 10313 files, 222454 used, 149425 free (97 frags, 18666 blocks, 0.0% fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> ** /dev/aacd0s2d
> ** Last Mounted on /S2/usr
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 134366 files, 583702 used, 311378 free (218 frags, 38895 blocks, 0.0% fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> ** /dev/aacd0s3a
> ** Last Mounted on /S3
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 10352 files, 227414 used, 144465 free (1473 frags, 17874 blocks, 0.4% fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> ** /dev/aacd0s3d
> ** Last Mounted on /S3/usr
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> random: unblocking device.
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 145515 files, 616056 used, 279024 free (41032 frags, 29749 blocks, 4.6% fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> ** /dev/aacd0s4d (NO WRITE)
> ** Last Mounted on /usr
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 143274 files, 563503 used, 331464 free (18320 frags, 39143 blocks, 2.0% fragmentation)
> ** /dev/aacd1s1e
> ** Last Mounted on /common
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 620322 files, 10780289 used, 2589387 free (211371 frags, 297252 blocks, 1.6%
> fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> ** /dev/aacd0s4f
> ** Last Mounted on /var
> ** Phase 1 - Check Blocks and Sizes
> ** Phase 2 - Check Pathnames
> ** Phase 3 - Check Connectivity
> ** Phase 4 - Check Reference Counts
> ** Phase 5 - Check Cyl groups
> 575 files, 25776 used, 2090552 free (592 frags, 261245 blocks, 0.0% fragmentation)
> 
> ***** FILE SYSTEM IS CLEAN *****
> lock order reversal:
>  1st 0xc79085c0 ufs (ufs) _at_ /usr/src/sys/kern/vfs_mount.c:1223
>  2nd 0xc7995c68 devfs (devfs) _at_ /usr/src/sys/ufs/ffs/ffs_vfsops.c:1375
> KDB: stack backtrace:
> db_trace_self_wrapper(c11aca2c,c6d9f8c8,c1574418,c157441c,f4cbb860,...) at
> db_trace_self_wrapper+0x2d/frame 0xf4cbb7f8
> kdb_backtrace(c11b05b1,c7995c68,c11a339c,c6da7448,c11e2649,...) at
> kdb_backtrace+0x30/frame 0xf4cbb860 witness_checkorder(c7995c68,9,c11e2649,55f,0,...)
> at witness_checkorder+0xd0c/frame 0xf4cbb8b0
> __lockmgr_args(c7995c68,80400,c7995c88,0,0,0,c11e2649,55f) at
> __lockmgr_args+0x8f3/frame 0xf4cbb98c
> vop_stdlock(f4cbba00,c7937310,c79a32a0,0,c79a32a0,...) at vop_stdlock+0x4d/frame
> 0xf4cbb9bc VOP_LOCK1_APV(c140d5a0,f4cbba00,0,0,c145a460,...) at
> VOP_LOCK1_APV+0x10a/frame 0xf4cbb9e8 _vn_lock(c7995c34,80400,c11e2649,55f,c1574418,...)
> at _vn_lock+0xa6/frame 0xf4cbba28 ffs_flushfiles(c79a32a0,8,c7937310,1,c7995c34,...) at
> ffs_flushfiles+0x142/frame 0xf4cbba74 softdep_flushfiles(c79a32a0,0,c7937310,0,0,...)
> at softdep_flushfiles+0x74/frame 0xf4cbbac8
> ffs_unmount(c79a32a0,8000000,c11b92d4,50a,c141db80,...) at ffs_unmount+0x7b/frame
> 0xf4cbbb10 dounmount(c79a32a0,8000000,c7937310,48c,0,...) at dounmount+0x4de/frame
> 0xf4cbbb70 sys_unmount(c7937310,f4cbbcc8,8,c11a894c,db,...) at sys_unmount+0x2ca/frame
> 0xf4cbbc40 syscall(f4cbbd08) at syscall+0x30c/frame 0xf4cbbcfc Xint0x80_syscall() at
> Xint0x80_syscall+0x21/frame 0xf4cbbcfc --- syscall (22, FreeBSD ELF32, sys_unmount),
> eip = 0x280cc63b, esp = 0xbfbfe464, ebp = 0xbfbfe530 --- Mounting local file systems:.
> Writing entropy file:. Setting hostname: freebeast.catwhisker.org. ....
> 
> 
> After the "smoke test" on head, I rebooted the laptop to today's
> stable/10 (FreeBSD 10.1-PRERELEASE #1374  r273898M/273900:1001501: Fri
> Oct 31 04:12:05 PDT 2014); the build machine was powered off (until just
> before midnight).
> 
> I'm not sure exactly how much of a problem this is, but it seems
> anomalous, at best.
> 
> Peace,
> david

I see this on ALL of our CURRENT systems as of yesterday and today. The filesystem is
left unclean and whatever I do with fsck, the system starts compalining about
inconsistencies after a full reboot.

At the moment I'm on two boxes at home at 
FreeBSD 11.0-CURRENT #1 r273914: Fri Oct 31 19:40:04 CET 2014 amd64
with this symptomes.

The result is that several services do not start anymore, slapd, nslcd, postgres, hal,
dbus, to name some. 

I think this is serious.

oh


Received on Fri Oct 31 2014 - 18:30:20 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:53 UTC