occasional eject, unmount issues

Moderators: jhartley, MSR734, nola

occasional eject, unmount issues

Post by grahamperrin » Sun Sep 23, 2012 10:20 pm

Think of this as a companion topic to both of:


> an eject dialogue for a volume long after the volume was truly ejected

Image

The twenty-two minute screen recording, from which that frame is taken, is rainy day viewing for October or November. Issues seen within the movie are, to me, not a priority; I work around them. No narration, but to a trained eye most of the movie should be self-explanatory (notifications from HardwareGrowler indicate disconnections, connections; and so on).

Link: the movie and other files.

Concerning mds, which features for a while in relation to a child file system: unfortunately the results of mddiagnose were naturally removed when the computer restarted. (For the future: I have asked Apple to store diagnoses in less volatile areas.)

Environment

MacBookPro5,2 with 8 GB memory and OS X 10.8.2.
grahamperrin Offline

User avatar
 
Posts: 1596
Joined: Fri Sep 14, 2012 10:21 pm
Location: Brighton and Hove, United Kingdom

cross reference

Post by grahamperrin » Mon Sep 24, 2012 7:30 pm

Reading this topic alongside Spotlight not working any more ? …

My first installation of ZEVO Community Edition 1.1 was over a Ten's Complement beta – not to a clean OS. Some disks were used with prior betas and prior public releases of ZEVO.

That first installation, over the beta, was logged as an install (not as an upgrade) – 
2012-09-15 around 06:20, and to an unreleased build of the OS.

A subsequent installation of ZEVO Community Edition 1.1 to the same build of the OS was logged as an upgrade – 
2012-09-19 around 23:12.

App Store offered the minor update to released Build 12C54 of OS X 10.8.2. I recall taking that option and as expected, I found the machine still with outdated Build 12A269 of Recovery OS 10.8 … so I took the opportunity to perform a full installation (for the build of Recovery OS to match the build of OS X). The current install.log.0.bz2 shows, filtered for 12C54:

Code: Select all
Sep 20 15:16:09 macbookpro08-centrim.home OSInstaller[325]: Running OS Build: Mac OS X 10.8.2 (12C54)
Sep 20 21:16:49 macbookpro08-centrim.home OSInstaller[325]: Installed "OS X" (10.8.2 (12C54))


– but I can't be sure about those (when I last checked, a few weeks or months ago, the times logged during full installation of an OS differed from local times by a few hours).

Focusing on ZEVO, on mds and on Spotlight

For what it's worth, I sensed a period of settling in. Maybe three or four days.

After those few days, passed: the eject/unmount behaviours outlined in this topic are, to me, subtly different from the behaviours when previous builds of ZEVO were combined with previous builds of the OS. Generally better. Just slightly unpredictable.

mds behaviours in builds of Mountain Lion do seem generally less disruptive, and less overt, than in Lion. If Spotlight now is more self-healing than in the past, I reckon that its healing is quiet. In particular:

  • I do not expect a visual indication of indexing (in the main Spotlight menu) during all periods of indexing for the file system
  • I never expect an indication in the main Spotlight menu during the periods when indexing for Mail is outdated.
grahamperrin Offline

User avatar
 
Posts: 1596
Joined: Fri Sep 14, 2012 10:21 pm
Location: Brighton and Hove, United Kingdom

Re: occasional eject, unmount issues

Post by grahamperrin » Sat Oct 06, 2012 3:29 am

Now, for maybe the first time ever, I can't eject any ZFS volume.

At least one (the first that I wanted to eject, some hours ago) has files in use by nothing other than mds so I gathered a little information, ran mddiagnose, moved the result away from /private/tmp

… currently running
sudo sysdiagnose mds
and I guess that the result will be for the lowest number PID for mds.

Terminal output and other mush appearing soon at http://www.wuala.com/grahamperrin/publi ... de=gallery

I'll leave the laptop in this state (unable to eject volumes of external disks) for as long as possible, just in case there's anything else that should be gathered.

(Don, anything else?)
grahamperrin Offline

User avatar
 
Posts: 1596
Joined: Fri Sep 14, 2012 10:21 pm
Location: Brighton and Hove, United Kingdom

Re: occasional eject, unmount issues

Post by grahamperrin » Sat Oct 06, 2012 3:35 pm

If it helps: at the time of writing, for some of the affected devices I do not get
GPTE… paths at
/dev/dsk/

The output below is copied from today's collection on Wuala, from file
2012-10-06 21-04 Terminal output.txt
– focus on disk8:

Code: Select all
macbookpro08-centrim:~ gjp22$ sudo su
sh-3.2# date
Sat  6 Oct 2012 21:04:34 BST
sh-3.2# uptime
21:04  up 1 day,  2:18, 3 users, load averages: 1.92 1.26 1.17
sh-3.2# ls /dev/disk4* | xargs -n 1 -t zdb -l | grep GPTE_
zdb -l /dev/disk4
zdb -l /dev/disk4s1
zdb -l /dev/disk4s2
        path: '/dev/dsk/GPTE_1928482A-7FE4-482D-B692-3EC6B03159BA'
        path: '/dev/dsk/GPTE_1928482A-7FE4-482D-B692-3EC6B03159BA'
        path: '/dev/dsk/GPTE_1928482A-7FE4-482D-B692-3EC6B03159BA'
        path: '/dev/dsk/GPTE_1928482A-7FE4-482D-B692-3EC6B03159BA'
sh-3.2# ls /dev/disk5* | xargs -n 1 -t zdb -l | grep GPTE_
zdb -l /dev/disk5
        path: '/dev/dsk/GPTE_1928482A-7FE4-482D-B692-3EC6B03159BA'
        path: '/dev/dsk/GPTE_1928482A-7FE4-482D-B692-3EC6B03159BA'
zdb -l /dev/disk5s1
        path: '/dev/dsk/GPTE_1928482A-7FE4-482D-B692-3EC6B03159BA'
        path: '/dev/dsk/GPTE_1928482A-7FE4-482D-B692-3EC6B03159BA'
sh-3.2# ls /dev/disk6* | xargs -n 1 -t zdb -l | grep GPTE_
ls: /dev/disk6*: No such file or directory
sh-3.2# ls /dev/disk7* | xargs -n 1 -t zdb -l | grep GPTE_
zdb -l /dev/disk7
zdb -l /dev/disk7s1
zdb -l /dev/disk7s2
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
sh-3.2# ls /dev/disk8* | xargs -n 1 -t zdb -l | grep GPTE_
zdb -l /dev/disk8
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
zdb -l /dev/disk8s1
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
zdb -l /dev/disk8s1s1
zdb -l /dev/disk8s1s1s1
zdb -l /dev/disk8s1s1s2
zdb -l /dev/disk8s1s2
zdb -l /dev/disk8s1s3
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
zdb -l /dev/disk8s1s4
zdb -l /dev/disk8s1s4s1
sh-3.2# clear





sh-3.2# diskutil list | grep zfs
   0:             zfs_pool_proxy gjp22                  *614.2 GB   disk3
   0:             zfs_pool_proxy zhandy                 *635.7 GB   disk5
   1:       zfs_filesystem_proxy Pocket Time Machine     85.1 GB    disk5s1
   0:             zfs_pool_proxy tall                   *2.0 TB     disk8
   1:       zfs_filesystem_proxy backups                 62.4 GB    disk8s1
   2:       zfs_filesystem_proxy LaCie d2 Extreme        50.7 GB    disk8s1s1
   3:       zfs_filesystem_proxy 11G                     50.7 GB    disk8s1s1s1
   4:       zfs_filesystem_proxy 12A                     50.7 GB    disk8s1s1s2
   5:       zfs_filesystem_proxy blocky                  54.2 GB    disk8s1s2
   6:       zfs_filesystem_proxy gjp22                   376.0 GB   disk8s1s3
   7:       zfs_filesystem_proxy zhandy                  478.3 GB   disk8s1s4
   8:       zfs_filesystem_proxy Pocket Time Machine     107.4 GB   disk8s1s4s1
sh-3.2# zfs list
NAME                                       USED   AVAIL   REFER  MOUNTPOINT
gjp22                                     341Gi   222Gi   307Gi  /Volumes/gjp22
tall                                     1.75Ti  43.2Gi   440Gi  /Volumes/tall
tall/backups                              872Gi  43.2Gi  10.9Gi  /Volumes/tall/backups
tall/backups/LaCie d2 Extreme            2.00Mi  43.2Gi   572Ki  /Volumes/tall/backups/LaCie d2 Extreme
tall/backups/LaCie d2 Extreme/11G         740Ki  43.2Gi   740Ki  /Volumes/tall/backups/LaCie d2 Extreme/11G
tall/backups/LaCie d2 Extreme/12A         732Ki  43.2Gi   732Ki  /Volumes/tall/backups/LaCie d2 Extreme/12A
tall/backups/blocky                      3.31Gi  43.2Gi  3.31Gi  /Volumes/tall/backups/blocky
tall/backups/gjp22                        386Gi  43.2Gi   307Gi  /Volumes/tall/backups/gjp22
tall/backups/zhandy                       472Gi  43.2Gi   398Gi  /Volumes/tall/backups/zhandy
tall/backups/zhandy/Pocket Time Machine  52.8Gi  43.2Gi  52.8Gi  /Volumes/tall/backups/zhandy/Pocket Time Machine
zhandy                                    554Gi  28.3Gi   411Gi  /Volumes/zhandy
zhandy/Pocket Time Machine               50.2Gi  28.3Gi  50.2Gi  /Volumes/zhandy/Pocket Time Machine
sh-3.2# zpool status -xv -T d
Sat  6 Oct 21:05:53 2012
all pools are healthy
sh-3.2# clear





sh-3.2# mount
/dev/disk1 on / (hfs, local, journaled)
devfs on /dev (devfs, local, nobrowse)
/dev/disk0s2 on /Volumes/swap (hfs, local, journaled)
/dev/disk0s4 on /Volumes/spare (hfs, local, journaled)
map -hosts on /net (autofs, nosuid, automounted, nobrowse)
map auto_home on /home (autofs, automounted, nobrowse)
AFS on /afs (afs)
/dev/disk3 on /Volumes/gjp22 (zfs, local, journaled, noatime)
/dev/disk5 on /Volumes/zhandy (zfs, local, journaled, noatime)
/dev/disk5s1 on /Volumes/zhandy/Pocket Time Machine (zfs, local, journaled, noatime)
/dev/disk8 on /Volumes/tall (zfs, local, journaled, noatime)
/dev/disk8s1 on /Volumes/tall/backups (zfs, local, journaled, noatime)
/dev/disk8s1s1 on /Volumes/tall/backups/LaCie d2 Extreme (zfs, local, journaled, noatime)
/dev/disk8s1s1s1 on /Volumes/tall/backups/LaCie d2 Extreme/11G (zfs, local, journaled, noatime)
/dev/disk8s1s1s2 on /Volumes/tall/backups/LaCie d2 Extreme/12A (zfs, local, journaled, noatime)
/dev/disk8s1s2 on /Volumes/tall/backups/blocky (zfs, local, read-only, journaled, noatime)
/dev/disk8s1s4 on /Volumes/tall/backups/zhandy (zfs, local, read-only, journaled, noatime)
/dev/disk8s1s4s1 on /Volumes/tall/backups/zhandy/Pocket Time Machine (zfs, local, read-only, journaled, noatime)
Wuala on /Volumes/WualaDrive (osxfusefs, local, nodev, nosuid, synchronous, mounted by gjp22)
sh-3.2# exit
exit
macbookpro08-centrim:~ gjp22$


Without the grep, for disk8* alone:

Code: Select all
macbookpro08-centrim:~ gjp22$ ls /dev/disk8* | sudo xargs -n 1 -t zdb -l
Password:
zdb -l /dev/disk8
--------------------------------------------
LABEL 0
--------------------------------------------
    version: 28
    name: 'tall'
    state: 0
    txg: 1121043
    pool_guid: 11005033736436061818
    hostname: 'macbookpro08-centrim.home@1B4C77AE-B80A-59F9-B5CB-7A86B7437D40'
    top_guid: 3631269066261115103
    guid: 3631269066261115103
    vdev_children: 1
    vdev_tree:
        type: 'disk'
        id: 0
        guid: 3631269066261115103
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        whole_disk: 0
        metaslab_array: 31
        metaslab_shift: 31
        ashift: 12
        asize: 2000050192384
        is_log: 0
        DTL: 350
        create_txg: 4
--------------------------------------------
LABEL 1
--------------------------------------------
    version: 28
    name: 'tall'
    state: 0
    txg: 1121043
    pool_guid: 11005033736436061818
    hostname: 'macbookpro08-centrim.home@1B4C77AE-B80A-59F9-B5CB-7A86B7437D40'
    top_guid: 3631269066261115103
    guid: 3631269066261115103
    vdev_children: 1
    vdev_tree:
        type: 'disk'
        id: 0
        guid: 3631269066261115103
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        whole_disk: 0
        metaslab_array: 31
        metaslab_shift: 31
        ashift: 12
        asize: 2000050192384
        is_log: 0
        DTL: 350
        create_txg: 4
--------------------------------------------
LABEL 2
--------------------------------------------
failed to unpack label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to unpack label 3
zdb -l /dev/disk8s1
--------------------------------------------
LABEL 0
--------------------------------------------
    version: 28
    name: 'tall'
    state: 0
    txg: 1121043
    pool_guid: 11005033736436061818
    hostname: 'macbookpro08-centrim.home@1B4C77AE-B80A-59F9-B5CB-7A86B7437D40'
    top_guid: 3631269066261115103
    guid: 3631269066261115103
    vdev_children: 1
    vdev_tree:
        type: 'disk'
        id: 0
        guid: 3631269066261115103
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        whole_disk: 0
        metaslab_array: 31
        metaslab_shift: 31
        ashift: 12
        asize: 2000050192384
        is_log: 0
        DTL: 350
        create_txg: 4
--------------------------------------------
LABEL 1
--------------------------------------------
    version: 28
    name: 'tall'
    state: 0
    txg: 1121043
    pool_guid: 11005033736436061818
    hostname: 'macbookpro08-centrim.home@1B4C77AE-B80A-59F9-B5CB-7A86B7437D40'
    top_guid: 3631269066261115103
    guid: 3631269066261115103
    vdev_children: 1
    vdev_tree:
        type: 'disk'
        id: 0
        guid: 3631269066261115103
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        whole_disk: 0
        metaslab_array: 31
        metaslab_shift: 31
        ashift: 12
        asize: 2000050192384
        is_log: 0
        DTL: 350
        create_txg: 4
--------------------------------------------
LABEL 2
--------------------------------------------
failed to unpack label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to unpack label 3
zdb -l /dev/disk8s1s1
--------------------------------------------
LABEL 0
--------------------------------------------
failed to read label 0
--------------------------------------------
LABEL 1
--------------------------------------------
failed to read label 1
--------------------------------------------
LABEL 2
--------------------------------------------
failed to read label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to read label 3
zdb -l /dev/disk8s1s1s1
--------------------------------------------
LABEL 0
--------------------------------------------
failed to read label 0
--------------------------------------------
LABEL 1
--------------------------------------------
failed to read label 1
--------------------------------------------
LABEL 2
--------------------------------------------
failed to read label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to read label 3
zdb -l /dev/disk8s1s1s2
--------------------------------------------
LABEL 0
--------------------------------------------
failed to read label 0
--------------------------------------------
LABEL 1
--------------------------------------------
failed to read label 1
--------------------------------------------
LABEL 2
--------------------------------------------
failed to read label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to read label 3
zdb -l /dev/disk8s1s2
--------------------------------------------
LABEL 0
--------------------------------------------
failed to read label 0
--------------------------------------------
LABEL 1
--------------------------------------------
failed to read label 1
--------------------------------------------
LABEL 2
--------------------------------------------
failed to read label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to read label 3
zdb -l /dev/disk8s1s3
--------------------------------------------
LABEL 0
--------------------------------------------
    version: 28
    name: 'tall'
    state: 0
    txg: 1121043
    pool_guid: 11005033736436061818
    hostname: 'macbookpro08-centrim.home@1B4C77AE-B80A-59F9-B5CB-7A86B7437D40'
    top_guid: 3631269066261115103
    guid: 3631269066261115103
    vdev_children: 1
    vdev_tree:
        type: 'disk'
        id: 0
        guid: 3631269066261115103
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        whole_disk: 0
        metaslab_array: 31
        metaslab_shift: 31
        ashift: 12
        asize: 2000050192384
        is_log: 0
        DTL: 350
        create_txg: 4
--------------------------------------------
LABEL 1
--------------------------------------------
    version: 28
    name: 'tall'
    state: 0
    txg: 1121043
    pool_guid: 11005033736436061818
    hostname: 'macbookpro08-centrim.home@1B4C77AE-B80A-59F9-B5CB-7A86B7437D40'
    top_guid: 3631269066261115103
    guid: 3631269066261115103
    vdev_children: 1
    vdev_tree:
        type: 'disk'
        id: 0
        guid: 3631269066261115103
        path: '/dev/dsk/GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C'
        whole_disk: 0
        metaslab_array: 31
        metaslab_shift: 31
        ashift: 12
        asize: 2000050192384
        is_log: 0
        DTL: 350
        create_txg: 4
--------------------------------------------
LABEL 2
--------------------------------------------
failed to read label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to read label 3
zdb -l /dev/disk8s1s4
--------------------------------------------
LABEL 0
--------------------------------------------
failed to read label 0
--------------------------------------------
LABEL 1
--------------------------------------------
failed to read label 1
--------------------------------------------
LABEL 2
--------------------------------------------
failed to read label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to read label 3
zdb -l /dev/disk8s1s4s1
--------------------------------------------
LABEL 0
--------------------------------------------
failed to read label 0
--------------------------------------------
LABEL 1
--------------------------------------------
failed to read label 1
--------------------------------------------
LABEL 2
--------------------------------------------
failed to read label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to read label 3
macbookpro08-centrim:~ gjp22$


Postscript

Rewind a few hours, to probably the first volume that I tried to eject/unmount – 
/dev/disk8s1s4s1 on /Volumes/tall/backups/zhandy/Pocket Time Machine
(I routinely eject that one to avoid the issue pictured here).

Now for that volume in particular:

Code: Select all
macbookpro08-centrim:~ gjp22$ date
Sat  6 Oct 2012 21:38:52 BST
macbookpro08-centrim:~ gjp22$ uptime
21:38  up 1 day,  2:53, 2 users, load averages: 0.45 0.92 1.02
macbookpro08-centrim:~ gjp22$ sudo zdb -l /dev/disk8s1s4s1
--------------------------------------------
LABEL 0
--------------------------------------------
failed to read label 0
--------------------------------------------
LABEL 1
--------------------------------------------
failed to read label 1
--------------------------------------------
LABEL 2
--------------------------------------------
failed to read label 2
--------------------------------------------
LABEL 3
--------------------------------------------
failed to read label 3
macbookpro08-centrim:~ gjp22$
grahamperrin Offline

User avatar
 
Posts: 1596
Joined: Fri Sep 14, 2012 10:21 pm
Location: Brighton and Hove, United Kingdom

Re: occasional eject, unmount issues

Post by grahamperrin » Sat Oct 06, 2012 4:10 pm

The two drives currently affected are on USB, separate buses:

2012-10-06 22-08-18 screenshot.png
2012-10-06 22-08-18 screenshot.png (96.13 KiB) Viewed 65 times


Whilst those two on USB are affected, I can connect a different drive (with a ZEVO volume) to the FireWire bus, eject and disconnect from FireWire without difficulty.

The more I think about today's incident, the more I suspect that it differs from what's described in the opening post. I normally find that after a waiting period, volumes can be unmounted. Today, no such luck.
grahamperrin Offline

User avatar
 
Posts: 1596
Joined: Fri Sep 14, 2012 10:21 pm
Location: Brighton and Hove, United Kingdom

Re: occasional eject, unmount issues

Post by grahamperrin » Sun Oct 07, 2012 8:59 am

grahamperrin wrote:Now, for maybe the first time ever, I can't eject any ZFS volume. … 


Mid-morning on Saturday, that was a misperception.

Now, Sunday afternoon, looking more closely, there is just one ZFS volume that does mount and umount:

  • the backup (/Volumes/tall/backups/gjp22) of my ZFS home (/Volumes/gjp22).

Since boot on the evening of Friday 2012-10-05, no other volume has been backed up. Backup began around five past midnight on the morning of the 6th:

Code: Select all
2012-10-06 00:04:58.667 sudo[57666]:    gjp22 : TTY=ttys000 ; PWD=/Volumes/gjp22/Documents/com/github/jollyjinx/ZFS-TimeMachine/jollyjinx-ZFS-TimeMachine-874d417 ; USER=root ; COMMAND=./zfstimemachinebackup.perl --sourcepool=gjp22 --destinationpool=tall/backups/gjp22 --snapshotstokeeponsource=100 --createsnapshotonsource


… probably the first volume that I tried to eject/unmount –
/dev/disk8s1s4s1 on /Volumes/tall/backups/zhandy/Pocket Time Machine


I can't recall whether that attempt was before or after five past, but certainly at eight minutes past (during the send and receive to a different dataset in the pool) I wondered why Pocket Time Machine would not eject:

Code: Select all
2012-10-06 00:08:05.447 sudo[57744]:    gjp22 : TTY=ttys001 ; PWD=/Volumes/gjp22 ; USER=root ; COMMAND=/usr/sbin/lsof /Volumes/tall/backups/zhandy/Pocket Time Machine


Lines from a system log query:

Code: Select all
2012-10-05 18:46:20.000 kernel[0]: mbinit: done [64 MB total pool size, (42/21) split]
2012-10-05 18:46:20.000 kernel[0]: CoreStorage: fsck_cs has finished for group "039C0D47-F3CF-44D3-A825-B48F01FCF334" with status 0x00
2012-10-05 18:46:20.000 kernel[0]: CoreStorage: fsck_cs has finished for group "902434C9-0131-4E3A-AE15-2B8B938087AD" with status 0x00
2012-10-05 18:46:20.000 kernel[0]: CoreStorageFamily::unlockVEKs() failed to unwrap the vek, status = e00002bc
2012-10-05 18:46:20.000 kernel[0]: Got boot device = IOService:/AppleACPIPlatformExpert/PCI0@0/AppleACPIPCI/SATA@B/AppleMCP79AHCI/PRT0@0/IOAHCIDevice@0/AppleAHCIDiskDriver/IOAHCIBlockStorageDevice/IOBlockStorageDriver/ST750LX003-1AC154 Media/IOGUIDPartitionScheme/OS@5/CoreStoragePhysical/CoreStorageGroup/OS
2012-10-05 18:46:35.147 corestoraged[98]: 0x7fff71c01180 unlockLVF: LVF=FFCE2FAF-BE8E-4FEF-9F3E-E221C6CBCA11, "AES-XTS", status = "Locked"
2012-10-05 18:46:36.290 corestoraged[98]: 0x7fff71c01180 unlockLVF: LVF=7AA96B8E-0E41-4C3F-9589-5FAE0C956372, "AES-XTS", status = "Unlocked"
2012-10-05 18:46:42.883 corestoraged[98]: 0x7fff71c01180 unlockLVF: LVF=FFCE2FAF-BE8E-4FEF-9F3E-E221C6CBCA11, "AES-XTS", status = "Locked"
2012-10-05 18:46:44.000 kernel[0]: maximum znodes: 99072
2012-10-05 18:46:44.000 kernel[0]: ZFSLabelScheme:probe: label 'gjp22', vdev 18001602949135038910
2012-10-05 18:46:44.000 kernel[0]: ZFSLabelScheme:start: 'gjp22' critical mass with 1 vdev(s) (importing)
2012-10-05 18:46:45.000 kernel[0]: zfsx_sysctl: hide children 1 --> 0
2012-10-05 18:46:46.000 kernel[0]: zfsx_kev_importpool:'gjp22' (13173756898033222216)
2012-10-05 18:46:49.000 kernel[0]: zfsx_vdm_open: 'gjp22' disk2s2
2012-10-05 18:46:54.000 kernel[0]: zfsx_mount: '/Volumes/gjp22'
2012-10-05 18:47:27.569 corestoraged[98]: 0x7fff71c01180 unlockLVF: LVF=FFCE2FAF-BE8E-4FEF-9F3E-E221C6CBCA11, "AES-XTS", status = "Unlocked"
2012-10-05 20:31:58.000 kernel[0]: ZFSLabelScheme:probe: label 'zhandy', vdev 10616857169251329946
2012-10-05 20:31:58.000 kernel[0]: ZFSLabelScheme:start: 'zhandy' critical mass with 1 vdev(s) (importing)
2012-10-05 20:31:58.000 kernel[0]: zfsx_kev_importpool:'zhandy' (4688397874579579662)
2012-10-05 20:31:59.000 kernel[0]: zfsx_vdm_open: 'zhandy' disk4s2
2012-10-05 20:32:01.000 kernel[0]: zfsx_mount: '/Volumes/zhandy'
2012-10-05 20:32:02.000 kernel[0]: zfsx_mount: '/Volumes/zhandy/Pocket Time Machine'
2012-10-05 22:34:42.000 kernel[0]: zfsx_unmount: '/Volumes/zhandy/Pocket Time Machine' (umount)
2012-10-05 22:34:43.000 kernel[0]: zfsvfs_teardown: '/Volumes/zhandy/Pocket Time Machine' (txg_wait_synced in 322 ms)
2012-10-05 22:34:45.000 kernel[0]: zfsx_unmount: '/Volumes/zhandy' (umount)
2012-10-05 22:34:45.000 kernel[0]: zfsvfs_teardown: '/Volumes/zhandy' (txg_wait_synced in 353 ms)
2012-10-05 22:34:46.000 kernel[0]: zfsx_vdm_close: 'disk4s2'
2012-10-05 22:34:51.000 kernel[0]: ZFSLabelScheme:willTerminate: this 0xffffff8029c07900 provider 0xffffff802d863100 'zfs vdev for 'zhandy''
2012-10-05 22:34:51.000 kernel[0]: ZFSLabelScheme:stop: 0xffffff8029c07900 goodbye 'zfs vdev for 'zhandy''
2012-10-05 23:27:16.000 kernel[0]: ZFSLabelScheme:probe: label 'zhandy', vdev 10616857169251329946
2012-10-05 23:27:16.000 kernel[0]: ZFSLabelScheme:start: 'zhandy' critical mass with 1 vdev(s) (importing)
2012-10-05 23:27:16.000 kernel[0]: zfsx_kev_importpool:'zhandy' (4688397874579579662)
2012-10-05 23:27:18.000 kernel[0]: zfsx_vdm_open: 'zhandy' disk4s2
2012-10-05 23:27:19.000 kernel[0]: zfsx_mount: '/Volumes/zhandy'
2012-10-05 23:27:20.000 kernel[0]: zfsx_mount: '/Volumes/zhandy/Pocket Time Machine'
2012-10-05 23:27:35.000 kernel[0]: ZFSLabelScheme:probe: label 'tall', vdev 3631269066261115103
2012-10-05 23:27:35.000 kernel[0]: ZFSLabelScheme:start: 'tall' critical mass with 1 vdev(s) (importing)
2012-10-05 23:27:35.000 kernel[0]: zfsx_kev_importpool:'tall' (11005033736436061818)
2012-10-05 23:27:38.000 kernel[0]: zfsx_vdm_open: 'tall' disk7s2
2012-10-05 23:27:42.000 kernel[0]: zfsx_mount: '/Volumes/tall'
2012-10-05 23:27:43.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups'
2012-10-05 23:27:44.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups/LaCie d2 Extreme'
2012-10-05 23:27:44.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups/LaCie d2 Extreme/11G'
2012-10-05 23:27:45.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups/LaCie d2 Extreme/12A'
2012-10-05 23:27:45.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups/blocky'
2012-10-05 23:27:46.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups/gjp22'
2012-10-05 23:27:47.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups/zhandy'
2012-10-05 23:27:48.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups/zhandy/Pocket Time Machine'
2012-10-06 00:05:23.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:06:16.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:07:03.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:07:28.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:08:13.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:08:42.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:09:18.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:09:41.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:10:07.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:10:32.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:10:52.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:11:09.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:11:32.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:12:32.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:13:26.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:14:10.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:15:30.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:17:29.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 00:19:11.000 kernel[0]: zfsvfs_teardown: online recv of /Volumes/tall/backups/gjp22
2012-10-06 09:18:41.000 kernel[0]: zfsx_unmount: '/Volumes/tall/backups/gjp22' (umount)
2012-10-06 09:46:01.000 kernel[0]: ZFSLabelScheme:probe: label 'flakylaciebde', vdev 8886612543563761462
2012-10-06 09:46:01.000 kernel[0]: ZFSLabelScheme:start: 'flakylaciebde' critical mass with 1 vdev(s) (importing)
2012-10-06 09:46:01.000 kernel[0]: zfsx_kev_importpool:'flakylaciebde' (9774159268332657427)
2012-10-06 09:46:02.000 kernel[0]: zfsx_vdm_open: 'flakylaciebde' disk9s2
2012-10-06 09:46:03.000 kernel[0]: zfsx_mount: '/Volumes/flakylaciebde'
2012-10-06 09:46:04.353 corestoraged[98]: 0x7fff71c01180 unlockLVF: LVF=EC0A0823-749D-4706-8F1D-2032ED1ADD7F, "AES-XTS", status = "Locked"
2012-10-06 09:46:04.000 kernel[0]: CoreStorage: fsck_cs has finished for group "9B249BC0-A6D0-4721-B581-FC3B20CDA81B" with status 0x00
2012-10-06 09:46:04.000 kernel[0]: CoreStorageFamily::unlockVEKs() failed to unwrap the vek, status = e00002bc
2012-10-06 13:32:00.000 kernel[0]: zfsx_unmount: '/Volumes/flakylaciebde' (umount)
2012-10-06 13:32:00.000 kernel[0]: zfsvfs_teardown: '/Volumes/flakylaciebde' (txg_wait_synced in 201 ms)
2012-10-06 13:32:01.000 kernel[0]: zfsx_vdm_close: 'disk9s2'
2012-10-06 16:23:44.000 kernel[0]: ZFSLabelScheme:willTerminate: this 0xffffff8025939f00 provider 0xffffff8028726100 'zfs vdev for 'flakylaciebde''
2012-10-06 16:23:44.000 kernel[0]: ZFSLabelScheme:stop: 0xffffff8025939f00 goodbye 'zfs vdev for 'flakylaciebde''
2012-10-06 16:23:44.000 kernel[0]: CoreStorage::recover() PV E9490EF3-7104-42A1-A755-98362C5CA3CC from group "LaCie Little Big Disk 2" (9B249BC0-A6D0-4721-B581-FC3B20CDA81B) has been marked missing.
2012-10-06 16:23:44.000 kernel[0]: CoreStorage: terminating group "LaCie Little Big Disk 2" (9B249BC0-A6D0-4721-B581-FC3B20CDA81B).
2012-10-06 23:29:34.000 kernel[0]: ZFSLabelScheme:probe: label 'flakylaciebde', vdev 8886612543563761462
2012-10-06 23:29:34.000 kernel[0]: ZFSLabelScheme:start: 'flakylaciebde' critical mass with 1 vdev(s) (importing)
2012-10-06 23:29:34.000 kernel[0]: zfsx_kev_importpool:'flakylaciebde' (9774159268332657427)
2012-10-06 23:29:35.000 kernel[0]: zfsx_vdm_open: 'flakylaciebde' disk10s2
2012-10-06 23:29:36.000 kernel[0]: zfsx_mount: '/Volumes/flakylaciebde'
2012-10-07 07:27:41.000 kernel[0]: still waiting on znode 13637453 (0xffffff8139f94c80) REG ZIL
2012-10-07 07:27:41.000 kernel[0]: still waiting on znode 13637453 (0xffffff8139f94c80) REG ZIL
2012-10-07 09:02:04.000 kernel[0]: zfsx_pageout: reentrant, znode 26811599 'compatibility.ini', off 0, len 4096
2012-10-07 09:11:38.000 kernel[0]: zfsx_unmount: '/Volumes/flakylaciebde' (umount)
2012-10-07 09:11:38.000 kernel[0]: zfsvfs_teardown: '/Volumes/flakylaciebde' (txg_wait_synced in 70 ms)
2012-10-07 09:11:39.000 kernel[0]: zfsx_vdm_close: 'disk10s2'
2012-10-07 09:11:52.000 kernel[0]: ZFSLabelScheme:willTerminate: this 0xffffff80319bbb00 provider 0xffffff80331ea900 'zfs vdev for 'flakylaciebde''
2012-10-07 09:11:52.000 kernel[0]: ZFSLabelScheme:stop: 0xffffff80319bbb00 goodbye 'zfs vdev for 'flakylaciebde''
2012-10-07 09:13:22.000 kernel[0]: zfsx_mount: '/Volumes/tall/backups/gjp22'
2012-10-07 14:11:14.000 kernel[0]: zfsx_unmount: '/Volumes/tall/backups/gjp22' (umount)


Recent verbose history for the tall pool:

Code: Select all
2012-10-05.23:27:41 [internal pool import txg:1121043] pool spa 28; zfs spa 28; zpl 5; uts macbookpro08-centrim.home@1B4C77AE-B80A-59F9-B5CB-7A86B7437D40 12.2.0 Darwin Kernel Version 12.2.0: Sat Aug 25 00:48:52 PDT 2012; root:xnu-2050.18.24~1/RELEASE_X86_64 MacBookPro5,2
2012-10-06.00:05:17 [internal replay_inc_sync txg:1121496] dataset = 16388
2012-10-06.00:05:23 [internal snapshot txg:1121503] dataset = 16609
2012-10-06.00:05:24 [internal destroy_begin_sync txg:1121504] dataset = 16388
2012-10-06.00:05:24 [internal destroy txg:1121509] dataset = 16388
2012-10-06.00:05:24 [internal property set txg:1121509] reservation=0 dataset = 16388
2012-10-06.00:05:24 [internal reservation set txg:1121509] 0 dataset = 0
2012-10-06.00:05:25 zfs receive -v -F tall/backups/gjp22
2012-10-06.00:05:25 [internal replay_inc_sync txg:1121510] dataset = 16831
2012-10-06.00:06:17 [internal snapshot txg:1121531] dataset = 16974
2012-10-06.00:06:17 [internal destroy_begin_sync txg:1121532] dataset = 16831
2012-10-06.00:06:17 [internal destroy txg:1121537] dataset = 16831
2012-10-06.00:06:17 [internal property set txg:1121537] reservation=0 dataset = 16831
2012-10-06.00:06:17 [internal reservation set txg:1121537] 0 dataset = 0
2012-10-06.00:06:17 [internal replay_inc_sync txg:1121538] dataset = 17126
2012-10-06.00:07:03 [internal snapshot txg:1121553] dataset = 17270
2012-10-06.00:07:04 [internal destroy_begin_sync txg:1121554] dataset = 17126
2012-10-06.00:07:04 [internal destroy txg:1121559] dataset = 17126
2012-10-06.00:07:04 [internal property set txg:1121559] reservation=0 dataset = 17126
2012-10-06.00:07:04 [internal reservation set txg:1121559] 0 dataset = 0
2012-10-06.00:07:05 [internal replay_inc_sync txg:1121560] dataset = 17420
2012-10-06.00:07:29 [internal snapshot txg:1121571] dataset = 17566
2012-10-06.00:07:29 [internal destroy_begin_sync txg:1121572] dataset = 17420
2012-10-06.00:07:30 [internal destroy txg:1121577] dataset = 17420
2012-10-06.00:07:30 [internal property set txg:1121577] reservation=0 dataset = 17420
2012-10-06.00:07:30 [internal reservation set txg:1121577] 0 dataset = 0
2012-10-06.00:07:30 [internal replay_inc_sync txg:1121578] dataset = 17712
2012-10-06.00:08:13 [internal snapshot txg:1121593] dataset = 17858
2012-10-06.00:08:14 [internal destroy_begin_sync txg:1121594] dataset = 17712
2012-10-06.00:08:14 [internal destroy txg:1121599] dataset = 17712
2012-10-06.00:08:14 [internal property set txg:1121599] reservation=0 dataset = 17712
2012-10-06.00:08:14 [internal reservation set txg:1121599] 0 dataset = 0
2012-10-06.00:08:14 [internal replay_inc_sync txg:1121600] dataset = 18103
2012-10-06.00:08:42 [internal snapshot txg:1121612] dataset = 18264
2012-10-06.00:08:42 [internal destroy_begin_sync txg:1121613] dataset = 18103
2012-10-06.00:08:43 [internal destroy txg:1121618] dataset = 18103
2012-10-06.00:08:43 [internal property set txg:1121618] reservation=0 dataset = 18103
2012-10-06.00:08:43 [internal reservation set txg:1121618] 0 dataset = 0
2012-10-06.00:08:44 [internal replay_inc_sync txg:1121619] dataset = 18442
2012-10-06.00:09:18 [internal snapshot txg:1121634] dataset = 18651
2012-10-06.00:09:19 [internal destroy_begin_sync txg:1121635] dataset = 18442
2012-10-06.00:09:19 [internal destroy txg:1121640] dataset = 18442
2012-10-06.00:09:19 [internal property set txg:1121640] reservation=0 dataset = 18442
2012-10-06.00:09:19 [internal reservation set txg:1121640] 0 dataset = 0
2012-10-06.00:09:20 [internal replay_inc_sync txg:1121641] dataset = 18803
2012-10-06.00:09:42 [internal snapshot txg:1121652] dataset = 18962
2012-10-06.00:09:42 [internal destroy_begin_sync txg:1121653] dataset = 18803
2012-10-06.00:09:44 [internal destroy txg:1121658] dataset = 18803
2012-10-06.00:09:44 [internal property set txg:1121658] reservation=0 dataset = 18803
2012-10-06.00:09:44 [internal reservation set txg:1121658] 0 dataset = 0
2012-10-06.00:09:44 [internal replay_inc_sync txg:1121659] dataset = 19123
2012-10-06.00:10:09 [internal snapshot txg:1121670] dataset = 19277
2012-10-06.00:10:09 [internal destroy_begin_sync txg:1121671] dataset = 19123
2012-10-06.00:10:10 [internal destroy txg:1121676] dataset = 19123
2012-10-06.00:10:10 [internal property set txg:1121676] reservation=0 dataset = 19123
2012-10-06.00:10:10 [internal reservation set txg:1121676] 0 dataset = 0
2012-10-06.00:10:10 [internal replay_inc_sync txg:1121677] dataset = 19449
2012-10-06.00:10:32 [internal snapshot txg:1121687] dataset = 19614
2012-10-06.00:10:32 [internal destroy_begin_sync txg:1121688] dataset = 19449
2012-10-06.00:10:34 [internal destroy txg:1121693] dataset = 19449
2012-10-06.00:10:34 [internal property set txg:1121693] reservation=0 dataset = 19449
2012-10-06.00:10:34 [internal reservation set txg:1121693] 0 dataset = 0
2012-10-06.00:10:34 [internal replay_inc_sync txg:1121694] dataset = 19767
2012-10-06.00:10:53 [internal snapshot txg:1121704] dataset = 19934
2012-10-06.00:10:53 [internal destroy_begin_sync txg:1121705] dataset = 19767
2012-10-06.00:10:54 [internal destroy txg:1121710] dataset = 19767
2012-10-06.00:10:54 [internal property set txg:1121710] reservation=0 dataset = 19767
2012-10-06.00:10:54 [internal reservation set txg:1121710] 0 dataset = 0
2012-10-06.00:10:54 [internal replay_inc_sync txg:1121711] dataset = 20091
2012-10-06.00:11:10 [internal snapshot txg:1121720] dataset = 20251
2012-10-06.00:11:10 [internal destroy_begin_sync txg:1121721] dataset = 20091
2012-10-06.00:11:11 [internal destroy txg:1121726] dataset = 20091
2012-10-06.00:11:11 [internal property set txg:1121726] reservation=0 dataset = 20091
2012-10-06.00:11:11 [internal reservation set txg:1121726] 0 dataset = 0
2012-10-06.00:11:12 [internal replay_inc_sync txg:1121727] dataset = 20419
2012-10-06.00:11:33 [internal snapshot txg:1121737] dataset = 20576
2012-10-06.00:11:33 [internal destroy_begin_sync txg:1121738] dataset = 20419
2012-10-06.00:11:34 [internal destroy txg:1121743] dataset = 20419
2012-10-06.00:11:34 [internal property set txg:1121743] reservation=0 dataset = 20419
2012-10-06.00:11:34 [internal reservation set txg:1121743] 0 dataset = 0
2012-10-06.00:11:34 [internal replay_inc_sync txg:1121744] dataset = 20741
2012-10-06.00:12:33 [internal snapshot txg:1121762] dataset = 20912
2012-10-06.00:12:33 [internal destroy_begin_sync txg:1121763] dataset = 20741
2012-10-06.00:12:34 [internal destroy txg:1121768] dataset = 20741
2012-10-06.00:12:34 [internal property set txg:1121768] reservation=0 dataset = 20741
2012-10-06.00:12:34 [internal reservation set txg:1121768] 0 dataset = 0
2012-10-06.00:12:35 [internal replay_inc_sync txg:1121769] dataset = 21077
2012-10-06.00:13:29 [internal snapshot txg:1121787] dataset = 21255
2012-10-06.00:13:30 [internal destroy_begin_sync txg:1121788] dataset = 21077
2012-10-06.00:13:31 [internal destroy txg:1121793] dataset = 21077
2012-10-06.00:13:31 [internal property set txg:1121793] reservation=0 dataset = 21077
2012-10-06.00:13:31 [internal reservation set txg:1121793] 0 dataset = 0
2012-10-06.00:13:31 [internal replay_inc_sync txg:1121794] dataset = 21421
2012-10-06.00:14:12 [internal snapshot txg:1121809] dataset = 21598
2012-10-06.00:14:12 [internal destroy_begin_sync txg:1121810] dataset = 21421
2012-10-06.00:14:13 [internal destroy txg:1121815] dataset = 21421
2012-10-06.00:14:13 [internal property set txg:1121815] reservation=0 dataset = 21421
2012-10-06.00:14:13 [internal reservation set txg:1121815] 0 dataset = 0
2012-10-06.00:14:13 [internal replay_inc_sync txg:1121816] dataset = 21783
2012-10-06.00:15:32 [internal snapshot txg:1121852] dataset = 21940
2012-10-06.00:15:32 [internal destroy_begin_sync txg:1121853] dataset = 21783
2012-10-06.00:15:34 [internal destroy txg:1121858] dataset = 21783
2012-10-06.00:15:34 [internal property set txg:1121858] reservation=0 dataset = 21783
2012-10-06.00:15:34 [internal reservation set txg:1121858] 0 dataset = 0
2012-10-06.00:15:34 [internal replay_inc_sync txg:1121859] dataset = 22106
2012-10-06.00:17:31 [internal snapshot txg:1121941] dataset = 22269
2012-10-06.00:17:31 [internal destroy_begin_sync txg:1121942] dataset = 22106
2012-10-06.00:17:32 [internal destroy txg:1121947] dataset = 22106
2012-10-06.00:17:32 [internal property set txg:1121947] reservation=0 dataset = 22106
2012-10-06.00:17:32 [internal reservation set txg:1121947] 0 dataset = 0
2012-10-06.00:17:32 [internal replay_inc_sync txg:1121948] dataset = 22444
2012-10-06.00:19:12 [internal snapshot txg:1122023] dataset = 22611
2012-10-06.00:19:13 [internal destroy_begin_sync txg:1122024] dataset = 22444
2012-10-06.00:19:15 [internal destroy txg:1122029] dataset = 22444
2012-10-06.00:19:15 [internal property set txg:1122029] reservation=0 dataset = 22444
2012-10-06.00:19:15 [internal reservation set txg:1122029] 0 dataset = 0
2012-10-06.00:19:32 [internal destroy txg:1122033] dataset = 56733
2012-10-06.00:19:33 zfs destroy tall/backups/gjp22@2012-10-03-134004
2012-10-06.00:19:33 [internal destroy txg:1122034] dataset = 28544
2012-10-06.00:19:34 zfs destroy tall/backups/gjp22@2012-09-28-231457
2012-10-06.00:19:34 [internal destroy txg:1122035] dataset = 28257
2012-10-06.00:19:35 zfs destroy tall/backups/gjp22@2012-09-28-221312
2012-10-06.00:19:35 [internal destroy txg:1122036] dataset = 27972
2012-10-06.00:19:36 zfs destroy tall/backups/gjp22@2012-09-28-211312
2012-10-06.00:19:36 [internal destroy txg:1122037] dataset = 27689
2012-10-06.00:19:37 zfs destroy tall/backups/gjp22@2012-09-28-190732
2012-10-06.00:19:37 [internal destroy txg:1122038] dataset = 27408
2012-10-06.00:19:38 zfs destroy tall/backups/gjp22@2012-09-28-180731
2012-10-06.00:19:38 [internal destroy txg:1122039] dataset = 27129
2012-10-06.00:19:38 zfs destroy tall/backups/gjp22@2012-09-28-170731
2012-10-06.00:19:38 [internal destroy txg:1122040] dataset = 26852
2012-10-06.00:19:39 zfs destroy tall/backups/gjp22@2012-09-28-160731
2012-10-06.00:19:39 [internal destroy txg:1122041] dataset = 26577
2012-10-06.00:19:40 zfs destroy tall/backups/gjp22@2012-09-28-150731
2012-10-06.00:19:40 [internal destroy txg:1122042] dataset = 26304
2012-10-06.00:19:41 zfs destroy tall/backups/gjp22@2012-09-28-140732
2012-10-06.00:19:41 [internal destroy txg:1122043] dataset = 26033
2012-10-06.00:19:42 zfs destroy tall/backups/gjp22@2012-09-28-130732
2012-10-06.00:19:42 [internal destroy txg:1122044] dataset = 25764
2012-10-06.00:19:42 zfs destroy tall/backups/gjp22@2012-09-28-120732
2012-10-06.00:19:42 [internal destroy txg:1122045] dataset = 25497
2012-10-06.00:19:44 zfs destroy tall/backups/gjp22@2012-09-28-110732
2012-10-06.00:19:44 [internal destroy txg:1122046] dataset = 25232
2012-10-06.00:19:45 zfs destroy tall/backups/gjp22@2012-09-28-092714
2012-10-06.00:19:45 [internal destroy txg:1122047] dataset = 24652
2012-10-06.00:19:46 zfs destroy tall/backups/gjp22@2012-09-28-082713
2012-10-06.00:19:46 [internal destroy txg:1122048] dataset = 24355
2012-10-06.00:19:47 zfs destroy tall/backups/gjp22@2012-09-28-072713
2012-10-06.00:19:47 [internal destroy txg:1122049] dataset = 24060
2012-10-06.00:19:48 zfs destroy tall/backups/gjp22@2012-09-28-062714
2012-10-06.00:19:48 [internal destroy txg:1122050] dataset = 23767
2012-10-06.00:19:49 zfs destroy tall/backups/gjp22@2012-09-28-052714
2012-10-06.00:19:49 [internal destroy txg:1122051] dataset = 23476
2012-10-06.00:19:50 zfs destroy tall/backups/gjp22@2012-09-28-042714
2012-10-06.00:19:50 [internal destroy txg:1122052] dataset = 23187
2012-10-06.00:19:57 zfs destroy tall/backups/gjp22@2012-09-28-032715
grahamperrin Offline

User avatar
 
Posts: 1596
Joined: Fri Sep 14, 2012 10:21 pm
Location: Brighton and Hove, United Kingdom

shut down to work around root mds use of files on ZEVO volum

Post by grahamperrin » Mon Oct 08, 2012 2:42 am

For the issue that began late Friday (or after midnight), a Monday morning 2012-10-08 log out from the OS did not work around; when I next logged in as gjp22, still I could not eject ZFS volumes.

It was necessary to shut down the computer.

Below, selected mds-related lines from
/private/var/log/com.apple.launchd/launchd-shutdown.system.log

Code: Select all
31660    com.apple.launchd                1        com.apple.metadata.mds.spindump 0         Closing receive right for com.apple.metadata.mds.spindump
31666    com.apple.launchd                1        com.apple.metadata.mds.spindump 0         Mach service deleted: com.apple.metadata.mds.spindump
31671    com.apple.launchd                1        com.apple.metadata.mds.spindump 0         Removed
31674    com.apple.launchd                1        com.apple.metadata.mds.scan 0         Closing receive right for com.apple.metadata.mds.scan
31679    com.apple.launchd                1        com.apple.metadata.mds.scan 0         Mach service deleted: com.apple.metadata.mds.scan
31684    com.apple.launchd                1        com.apple.metadata.mds.scan 0         Removed
31688    com.apple.launchd                1        com.apple.metadata.mds   85        Job is active: PID is still valid
31695    com.apple.launchd                1        com.apple.metadata.mds   85        Stopping job...
31731    com.apple.launchd                1        com.apple.metadata.mds   85        Sent job SIGTERM.
31734    com.apple.launchd                1        com.apple.metadata.mds   85        Job was sent SIGTERM.
631270   com.apple.launchd                1        com.apple.metadata.mds   85        Job is active: PID is still valid
631273   com.apple.launchd                1        com.apple.metadata.mds   85        Job was sent SIGTERM.


… 

Code: Select all
4027784  com.apple.launchd                1        com.apple.metadata.mds   85        Job is active: PID is still valid
4027786  com.apple.launchd                1        com.apple.metadata.mds   85        Job was sent SIGTERM.
4305869  com.apple.launchd                1        com.apple.launchd        1         System: Receive right returned to us: com.apple.metadata.mds
4305885  com.apple.launchd                1        com.apple.metadata.mds   85        Tried to dispatch an already active job: PID is still valid.
4305915  com.apple.launchd                1        com.apple.metadata.mds   85        Job is active: PID is still valid
4305919  com.apple.launchd                1        com.apple.metadata.mds   85        Job was sent SIGTERM.
4305975  com.apple.launchd                1        com.apple.launchd        1         System: Receive right returned to us: com.apple.metadata.mds.xpcs
4305982  com.apple.launchd                1        com.apple.metadata.mds   85        Tried to dispatch an already active job: PID is still valid.
4306053  com.apple.launchd                1        com.apple.metadata.mds   85        Job is active: PID is still valid
4306057  com.apple.launchd                1        com.apple.metadata.mds   85        Job was sent SIGTERM.
4306104  com.apple.launchd                1        com.apple.launchd        1         System: Receive right returned to us: com.apple.metadata.mds.xpc
4306112  com.apple.launchd                1        com.apple.metadata.mds   85        Tried to dispatch an already active job: PID is still valid.
4306139  com.apple.launchd                1        com.apple.metadata.mds   85        Job is active: PID is still valid
4306142  com.apple.launchd                1        com.apple.metadata.mds   85        Job was sent SIGTERM.
4307749  com.apple.launchd                1        com.apple.metadata.mds   85        Job is active: PID is still valid
4307752  com.apple.launchd                1        com.apple.metadata.mds   85        Job was sent SIGTERM.
4560944  com.apple.launchd                1        com.apple.metadata.mds   85        Dispatching kevent callback.
4560947  com.apple.launchd                1        com.apple.metadata.mds   85        EVFILT_PROC event for job.
4560951  com.apple.launchd                1        com.apple.metadata.mds   85        Reaping
4560979  com.apple.launchd                1        com.apple.metadata.mds   85        Exited 4.529226 seconds after the first signal was sent
4560987  com.apple.launchd                1        com.apple.metadata.mds   0         Exited while shutdown in progress. Processes remaining: 7/5
4560990  com.apple.launchd                1        com.apple.metadata.mds   0         Job is useless. Removing.
4560996  com.apple.launchd                1        com.apple.metadata.mds   0         Closing receive right for com.apple.metadata.mds
4561004  com.apple.launchd                1        com.apple.metadata.mds   0         Mach service deleted: com.apple.metadata.mds
4561007  com.apple.launchd                1        com.apple.metadata.mds   0         Closing receive right for com.apple.metadata.mds.xpcs
4561012  com.apple.launchd                1        com.apple.metadata.mds   0         Mach service deleted: com.apple.metadata.mds.xpcs
4561015  com.apple.launchd                1        com.apple.metadata.mds   0         Closing receive right for com.apple.metadata.mds.xpc
4561020  com.apple.launchd                1        com.apple.metadata.mds   0         Mach service deleted: com.apple.metadata.mds.xpc
4561026  com.apple.launchd                1        com.apple.metadata.mds   0         Removed


The last few lines, for convenience:

Code: Select all
4560979  com.apple.launchd                1        com.apple.metadata.mds   85        Exited 4.529226 seconds after the first signal was sent
4560987  com.apple.launchd                1        com.apple.metadata.mds   0         Exited while shutdown in progress. Processes remaining: 7/5
4560990  com.apple.launchd                1        com.apple.metadata.mds   0         Job is useless. Removing.
4560996  com.apple.launchd                1        com.apple.metadata.mds   0         Closing receive right for com.apple.metadata.mds
4561004  com.apple.launchd                1        com.apple.metadata.mds   0         Mach service deleted: com.apple.metadata.mds
4561007  com.apple.launchd                1        com.apple.metadata.mds   0         Closing receive right for com.apple.metadata.mds.xpcs
4561012  com.apple.launchd                1        com.apple.metadata.mds   0         Mach service deleted: com.apple.metadata.mds.xpcs
4561015  com.apple.launchd                1        com.apple.metadata.mds   0         Closing receive right for com.apple.metadata.mds.xpc
4561020  com.apple.launchd                1        com.apple.metadata.mds   0         Mach service deleted: com.apple.metadata.mds.xpc
4561026  com.apple.launchd                1        com.apple.metadata.mds   0         Removed


The log in its entirety is at http://www.wuala.com/grahamperrin/public/2012/10/05/a/
grahamperrin Offline

User avatar
 
Posts: 1596
Joined: Fri Sep 14, 2012 10:21 pm
Location: Brighton and Hove, United Kingdom


Return to General Discussion

Who is online

Users browsing this forum: ilovezfs and 1 guest

cron