1 Reply Latest reply: Oct 19, 2012 6:05 PM by Blaidd Drwg
nnegi Level 1 Level 1 (0 points)

Our SAN file-system suddenly went down. Looking into the cvlogs, it is pointing related to space problem, though the system has around 230GB free at the point of failure. CAn someone provide some pointer here what has cause the SAN voulme unmounted from clients as I am bit confused if it is problem related to free inodes or free space or some hard-disk issue. I have checked the Storage Event viewer, but did got anything suspected at h/w level.

 

 

[[1010 11:07:56.711992] 0xa013d720 (Debug) FOUsurpCheck: read ARB info (pass 1): host (172.22.225.30:49201) conns 0 age 1349863676.00 secs his delta 338923.00 secs my delta 338923.00 secs.

[1010 11:07:56.712000] 0xa013d720 (Debug) FOUsurpCheck: peer found idle (pass 1): his conns 0 my votes 3 arb usurpee ::.

[1010 11:07:57] 0xa013d720 (Info) Branding Arbitration Block (attempt 1) votes 3.

[1010 11:07:59.101398] 0xa013d720 (Debug) Cannot find fail over script [/Library/Filesystems/Xsan/bin/cvfail.dir1] - looking for generic script.

[1010 11:07:59] 0xa013d720 (Info) Launching fail over script ["/Library/Filesystems/Xsan/bin/cvfail" dir1 49177 SAN]

[1010 11:07:59.123274] 0xa013d720 (Debug) Starting journal log recovery.

[1010 11:08:00.339234] 0xa013d720 (Debug) Completed journal log recovery.

[1010 11:08:00.339545] 0xa013d720 (Debug) Inode_init_post_activation: FsStatus 0xd27, Brl_ResyncState 1

[1010 11:08:00] 0xb8e2f000 (Info) FSM Alloc:  Loading Stripe Group "MetadataAndJournal". 418.15 GB.

[1010 11:08:00] 0xb8eb1000 (Info) FSM Alloc:  Loading Stripe Group "Data". 4.90 TB.

[1010 11:08:00] 0xb8e2f000 (Info) FSM Alloc:  Stripe Group "MetadataAndJournal" active.

[1010 11:08:01] 0xb8eb1000 (Warning) FSM Alloc: Stripe Group "Data" 15033784 free blocks in 218142 fragments inserted.

[1010 11:08:01] 0xb8eb1000 (Warning) FSM Alloc: Stripe Group "Data" 1039159 free blocks in 86351 fragments ignored.

[1010 11:08:01] 0xb8eb1000 (Info) FSM Alloc:  free blocks 15033784 with 0 blocks currently  reserved for client delayed buffers.Reserved blocks may change with client activity.

[1010 11:08:01] 0xb8eb1000 (Info) FSM Alloc:  Stripe Group "Data" active.

[1010 11:08:01] 0xa013d720 (Warning) Windows Security has been turned off in config file but clients have been requested to enforce ACLs.  Windows Security remains in effect.

[1010 11:08:01] 0xa013d720 (Info) File system 'SAN' requires UTF8-NFC file names

[1010 11:08:01] 0xa013d720 (Info) File System Service 'SAN[1]' now active on host 'dir1:49177'.

[1010 11:08:01] 0xb8fb5000 (Info) Inode_fl_scan: starting scan

[1010 11:08:01.128255] 0xa013d720 (Debug) Node [1] [172.22.22.5:64426] connected.

[1010 11:08:01.128543] 0xa013d720 (Debug) Node [2] [172.22.22.1:62725] connected.

[1010 11:08:01.128761] 0xa013d720 (Debug) Node [3] [172.22.22.2:58817] connected.

[1010 11:08:01.128974] 0xa013d720 (Debug) Node [4] [172.22.22.6:56186] connected.

[1010 11:08:01.129116] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.5:64425.

[1010 11:08:01.129223] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.2:58816.

[1010 11:08:01.129281] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.6:56185.

[1010 11:08:01.129428] 0xa013d720 (Debug) Node [5] [172.22.22.4:53913] connected.

[1010 11:08:01.129677] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.1:62724.

[1010 11:08:01.129834] 0xa013d720 (Debug) Node [6] [172.22.22.3:59970] connected.

[1010 11:08:01.129996] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.3:59969.

[1010 11:08:01.130159] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.4:53912.

[1010 11:08:01.130255] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.6:56183.

[1010 11:08:01.130367] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.2:58814.

[1010 11:08:01] 0xb4717000 (Info) Node [6] [172.22.22.3:59970] Client Login (active 1).

[1010 11:08:01] 0xb481b000 (Info) Node [2] [172.22.22.1:62725] Client Login (active 2).

[1010 11:08:01] 0xb4799000 (Info) Node [1] [172.22.22.5:64426] Client Login (active 3).

[1010 11:08:01] 0xb489d000 (Info) Node [3] [172.22.22.2:58817] Client Login (active 4).

[1010 11:08:01] 0xb491f000 (Info) Node [4] [172.22.22.6:56186] Client Login (active 5).

[1010 11:08:01] 0xb49a1000 (Info) Node [5] [172.22.22.4:53913] Client Login (active 6).

[1010 11:08:01] 0xb7241000 (Info) XsanSpotlightGetSearchLevel: Unable to copy store attributes -> No index

[1010 11:08:01] 0xb7241000 (Info) XsanSpotlightRpc_ChannelCreate: Spotlight is disabled, rejecting request

[1010 11:08:03] 0xb503b000 (**Critical**) No Space! [alloc.c:2627] [0x1 0x20].

[1010 11:08:03.853420] 0xb503b000 (Debug) Alloc max us latency 2660 inode 0x58000084ff6f0 byte hint 0xa4000 actual 0xa4000

[1010 11:08:03.883006] 0xb80fb000 (Debug) Alloc max us latency 32277 inode 0x28000084ff6ee byte hint 0x1ec000 actual 0x1ec000

[1010 11:08:04] 0xb8fb5000 (**Error**) add_to_free_list: inode 0x7f800000bd39ca failed lookup

[1010 11:08:04] 0xb8fb5000 (Info) Inode_fl_scan: scan aborted

[1010 11:08:04] 0xb8fb5000 (Info) Inode_fl_scan final tally: 76233 inodes scanned, 0 pending added, 0 free added.

[1010 11:08:05.175704] 0xb6797000 (Debug) Alloc max us latency 746377 inode 0x58000084ff6f0 byte hint 0x400000 actual 0x400000

[1010 11:08:05] 0xb8303000 (**Critical**) No Space! [alloc.c:2627] [0x18 0x20].

[1010 11:08:05] 0xb8dad000 (**FATAL**) PANIC: /Library/Filesystems/Xsan/bin/fsm "free_pending_inode_thread: Cannot lookup extended inode [0xa9ed7e8] -No such file or directory

[1010 11:08:05.474961] 0xa013d720 (Debug) Listener_thread: flushing journal.

[1010 11:08:05.474971] 0xa013d720 (Debug) Listener_thread: journal flush complete.

[1010 11:08:05.475006] 0xa013d720 (Debug) FSM memory SUMMARY resident size 204MB.

[1010 11:08:05.475013] 0xa013d720 (Debug) FSM I/O SUMMARY writes total/324.

[1010 11:08:05.475017] 0xa013d720 (Debug) FSM I/O SUMMARY writes journal/36 sb/0 buf/49 abm/4.

[1010 11:08:05.475026] 0xa013d720 (Debug) FSM I/O SUMMARY writes inode/40 ganged/51 (3.98%).

[1010 11:08:05.475030] 0xa013d720 (Debug) FSM wait SUMMARY inode pool expand waits/0.

[1010 11:08:05.475034] 0xa013d720 (Debug) FSM wait SUMMARY journal waits/0.

[1010 11:08:05.475048] 0xa013d720 (Debug) FSM wait SUMMARY journal bytes used avg/538322 max/2968576.

[1010 11:08:05.475051] 0xa013d720 (Debug) FSM wait SUMMARY free buffer waits/0.

[1010 11:08:05.475054] 0xa013d720 (Debug) FSM wait SUMMARY free inode waits/0.

[1010 11:08:05.475057] 0xa013d720 (Debug) FSM wait SUMMARY revokes/0 avg/0 min/0 max/0.

[1010 11:08:05.475061] 0xa013d720 (Debug) FSM threads SUMMARY max busy hi-prio/14 lo-prio/6.

[1010 11:08:05.475064] 0xa013d720 (Debug) FSM threads SUMMARY max busy dmig/0 events/0.

[1010 11:08:05.475067] 0xa013d720 (Debug) FSM msg queue SUMMARY hi-prio now/0 min/0 max/6.

[1010 11:08:05.475070] 0xa013d720 (Debug) FSM msg queue SUMMARY lo-prio now/0 min/0 max/4.

[1010 11:08:05.475073] 0xa013d720 (Debug) FSM msg queue SUMMARY dmig now/0 min/0 max/0.

[1010 11:08:05.475076] 0xa013d720 (Debug) FSM msg queue SUMMARY events now/0 min/0 max/0.

[1010 11:08:05.475079] 0xa013d720 (Debug) FSM cache SUMMARY inode lookups/1791 misses/571 hits/68.12%.

[1010 11:08:05.475083] 0xa013d720 (Debug) FSM cache SUMMARY free incore inodes now/32728 min/32720 max/32768.

[1010 11:08:05.475165] 0xa013d720 (Debug) FSM cache SUMMARY buffer lookups/916 misses/375 hits/59.06%.

[1010 11:08:05.475185] 0xa013d720 (Debug) FSM cache SUMMARY free buffers now/8188 min/1 max/8192.

[1010 11:08:05.475189] 0xa013d720 (Debug) FSM cache SUMMARY attrs now/421 min/1 max/421.

[1010 11:08:05.475293] 0xa013d720 (Debug) FSM extent SUMMARY extent lookups/335 misses/6 hits/98.21%.

[1010 11:08:05.475298] 0xa013d720 (Debug) FSM extent SUMMARY hint tries/10 misses/7 hits/30.00%.

[1010 11:08:05.475312] 0xa013d720 (Debug) VOP SUMMARY Setattr cnt/154 avg/4839 min/23 max/130340.

[1010 11:08:05.475319] 0xa013d720 (Debug) VOP SUMMARY Open cnt/488 avg/13037 min/11 max/217683.

[1010 11:08:05.475329] 0xa013d720 (Debug) VOP SUMMARY Close cnt/101 avg/40 min/16 max/654.

[1010 11:08:05.475334] 0xa013d720 (Debug) VOP SUMMARY Getquota cnt/5 avg/145054 min/85 max/362506.

[1010 11:08:05.475338] 0xa013d720 (Debug) VOP SUMMARY VopLookupV4 cnt/130 avg/91969 min/21 max/603580.

[1010 11:08:05.475342] 0xa013d720 (Debug) VOP SUMMARY VopCapNegotiate cnt/6 avg/17 min/10 max/24.

[1010 11:08:05.475346] 0xa013d720 (Debug) VOP SUMMARY VopReaddir2 cnt/2 avg/64 min/47 max/81.

[1010 11:08:05.475350] 0xa013d720 (Debug) VOP SUMMARY VopClientId cnt/6 avg/20 min/14 max/25.

[1010 11:08:05.475353] 0xa013d720 (Debug) VOP SUMMARY GetResyncAttr cnt/116 avg/5479 min/11 max/176697.

[1010 11:08:05.475358] 0xa013d720 (Debug) TKN SUMMARY TokenRequestV2 cnt/12 avg/31 min/19 max/58.

[1010 11:08:05.475362] 0xa013d720 (Debug) TKN SUMMARY TokenRequestV3 cnt/5 avg/377693 min/22 max/1888251.

[1010 11:08:05.475367] 0xa013d720 (Debug) TKN SUMMARY OpenChange cnt/2 avg/27 min/10 max/45.

[1010 11:08:05.475371] 0xa013d720 (Debug) TKN SUMMARY TokenChangeV4 cnt/161 avg/1715 min/3 max/116624.

[1010 11:08:05.475374] 0xa013d720 (Debug) TKN SUMMARY TokenReqAlloc cnt/7 avg/111901 min/65 max/746407.

[1010 11:08:05.475382] 0xa013d720 (Debug) BRL SUMMARY ClearLock cnt/15 avg/28 min/8 max/72.

[1010 11:08:05.475386] 0xa013d720 (Debug) BRL SUMMARY ReconDone cnt/6 avg/29 min/12 max/36.

[1010 11:08:05.475390] 0xa013d720 (Debug) BRL SUMMARY RestoreLock cnt/304 avg/29 min/11 max/52.

[1010 11:08:05.475396] 0xa013d720 (Debug) SG SUMMARY MetadataAndJournal space total/418.15 GB free/415.25 GB (99.31%)

[1010 11:08:05.475402] 0xa013d720 (Debug) SG SUMMARY MetadataAndJournal space minfree/415.25 GB (99.31%) maxfree/415.25 GB (99.31%)

[1010 11:08:05.475406] 0xa013d720 (Debug) SG SUMMARY MetadataAndJournal alloc extent cnt/0 avgsize/0.00 B.

[1010 11:08:05.475409] 0xa013d720 (Debug) SG SUMMARY 153 btree free space fragments 304 splay tree fragments

[1010 11:08:05.475414] 0xa013d720 (Debug) SG SUMMARY Data space total/4.90 TB free/229.39 GB (4.57%)

[1010 11:08:05.475419] 0xa013d720 (Debug) SG SUMMARY Data space minfree/229.38 GB (4.57%) maxfree/229.40 GB (4.57%)

[1010 11:08:05.475423] 0xa013d720 (Debug) SG SUMMARY Data alloc extent cnt/5 avgsize/2.93 MB.

[1010 11:08:05.475426] 0xa013d720 (Debug) SG SUMMARY 218156 btree free space fragments 436242 splay tree fragments

[1010 11:08:05.475438] 0xa013d720 (Debug) PIO HiPriWr SUMMARY META-DATA cnt/36 maxq/0.

[1010 11:08:05.475442] 0xa013d720 (Debug) PIO HiPriWr SUMMARY META-DATA avg/28868 min/217 max/885843.

[1010 11:08:05.475447] 0xa013d720 (Debug) PIO HiPriWr SUMMARY META-DATA sysavg/28866 sysmin/216 sysmax/885842.

[1010 11:08:05.475451] 0xa013d720 (Debug) PIO HiPriWr SUMMARY META-DATA avglen/3598 minlen/512 maxlen/32256.

[1010 11:08:05.475454] 0xa013d720 (Debug) PIO Read SUMMARY META-DATA cnt/742 maxq/15.

[1010 11:08:05.475458] 0xa013d720 (Debug) PIO Read SUMMARY META-DATA avg/35831 min/159 max/217679.

[1010 11:08:05.475462] 0xa013d720 (Debug) PIO Read SUMMARY META-DATA sysavg/7538 sysmin/147 sysmax/94276.

[1010 11:08:05.475466] 0xa013d720 (Debug) PIO Read SUMMARY META-DATA avglen/160671 minlen/512 maxlen/4194304.

[1010 11:08:05.475469] 0xa013d720 (Debug) PIO Write SUMMARY META-DATA cnt/288 maxq/15.

[1010 11:08:05.475473] 0xa013d720 (Debug) PIO Write SUMMARY META-DATA avg/6373 min/181 max/123669.

[1010 11:08:05.475477] 0xa013d720 (Debug) PIO Write SUMMARY META-DATA sysavg/537 sysmin/149 sysmax/19922.

[1010 11:08:05.475480] 0xa013d720 (Debug) PIO Write SUMMARY META-DATA avglen/15667 minlen/512 maxlen/16384.

[1010 11:08:05.475491] 0xa013d720 (Debug) Cache SUMMARY [172.22.22.5] attrs now/11 min/1 max/11.

[1010 11:08:05.475497] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.5] Setattr cnt/13 avg/9872 min/65 max/123828.

[1010 11:08:05.475501] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.5] Open cnt/11 avg/18787 min/19 max/68015.

[1010 11:08:05.475505] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.5] Getquota cnt/5 avg/145054 min/85 max/362506.

[1010 11:08:05.475510] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.5] VopCapNegotiate cnt/1 avg/10 min/10 max/10.

[1010 11:08:05.475514] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.5] VopClientId cnt/1 avg/20 min/20 max/20.

[1010 11:08:05.475518] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.5] GetResyncAttr cnt/8 avg/49 min/28 max/85.

[1010 11:08:05.475521] 0xa013d720 (Debug) Cache SUMMARY [172.22.22.1] attrs now/114 min/1 max/114.

[1010 11:08:05.475526] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.1] Setattr cnt/58 avg/1074 min/28 max/58930.

[1010 11:08:05.475530] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.1] Open cnt/133 avg/24032 min/11 max/198396.

[1010 11:08:05.475534] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.1] Close cnt/37 avg/52 min/22 max/654.

[1010 11:08:05.475538] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.1] VopLookupV4 cnt/46 avg/29865 min/21 max/198636.

[1010 11:08:05.475542] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.1] VopCapNegotiate cnt/1 avg/19 min/19 max/19.

[1010 11:08:05.475546] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.1] VopReaddir2 cnt/1 avg/47 min/47 max/47.

[1010 11:08:05.475550] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.1] VopClientId cnt/1 avg/25 min/25 max/25.

[1010 11:08:05.475554] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.1] GetResyncAttr cnt/34 avg/8671 min/11 max/115262.

[1010 11:08:05.475557] 0xa013d720 (Debug) Cache SUMMARY [172.22.22.2] attrs now/59 min/1 max/59.

[1010 11:08:05.475562] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.2] Setattr cnt/70 avg/3893 min/23 max/116839.

[1010 11:08:05.475566] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.2] Open cnt/114 avg/4943 min/17 max/121316.

[1010 11:08:05.475570] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.2] Close cnt/63 avg/33 min/16 max/76.

[1010 11:08:05.475575] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.2] VopLookupV4 cnt/72 avg/137767 min/42 max/603580.

[1010 11:08:05.475579] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.2] VopCapNegotiate cnt/1 avg/17 min/17 max/17.

[1010 11:08:05.475582] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.2] VopReaddir2 cnt/1 avg/81 min/81 max/81.

[1010 11:08:05.475586] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.2] VopClientId cnt/1 avg/16 min/16 max/16.

[1010 11:08:05.475590] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.2] GetResyncAttr cnt/53 avg/5528 min/15 max/176697.

[1010 11:08:05.475594] 0xa013d720 (Debug) Cache SUMMARY [172.22.22.6] attrs now/223 min/1 max/223.

[1010 11:08:05.475603] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.6] Setattr cnt/11 avg/13793 min/36 max/120293.

[1010 11:08:05.475612] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.6] Open cnt/223 avg/10740 min/24 max/217683.

[1010 11:08:05.475617] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.6] VopCapNegotiate cnt/1 avg/12 min/12 max/12.

[1010 11:08:05.475620] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.6] VopClientId cnt/1 avg/22 min/22 max/22.

[1010 11:08:05.475624] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.6] GetResyncAttr cnt/7 avg/32 min/16 max/57.

[1010 11:08:05.475628] 0xa013d720 (Debug) Cache SUMMARY [172.22.22.4] attrs now/6 min/1 max/6.

[1010 11:08:05.475633] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.4] Setattr cnt/2 avg/65216 min/92 max/130340.

[1010 11:08:05.475639] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.4] Open cnt/6 avg/52 min/30 max/119.

[1010 11:08:05.475643] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.4] Close cnt/1 avg/75 min/75 max/75.

[1010 11:08:05.475647] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.4] VopLookupV4 cnt/5 avg/35735 min/48 max/126036.

[1010 11:08:05.475651] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.4] VopCapNegotiate cnt/1 avg/20 min/20 max/20.

[1010 11:08:05.475655] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.4] VopClientId cnt/1 avg/24 min/24 max/24.

[1010 11:08:05.475659] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.4] GetResyncAttr cnt/6 avg/7786 min/29 max/46514.

[1010 11:08:05.475662] 0xa013d720 (Debug) Cache SUMMARY [172.22.22.3] attrs now/8 min/1 max/8.

[1010 11:08:05.475667] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.3] Open cnt/1 avg/38 min/38 max/38.

[1010 11:08:05.475672] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.3] VopLookupV4 cnt/7 avg/69189 min/51 max/133390.

[1010 11:08:05.475676] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.3] VopCapNegotiate cnt/1 avg/24 min/24 max/24.

[1010 11:08:05.475679] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.3] VopClientId cnt/1 avg/14 min/14 max/14.

[1010 11:08:05.475683] 0xa013d720 (Debug) VOP SUMMARY [172.22.22.3] GetResyncAttr cnt/8 avg/48 min/21 max/114.

[1010 11:08:05.475688] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.5] TokenRequestV2 cnt/2 avg/28 min/25 max/32.

[1010 11:08:05.475692] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.5] TokenRequestV3 cnt/3 avg/629441 min/22 max/1888251.

[1010 11:08:05.475697] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.5] TokenChangeV4 cnt/13 avg/10 min/5 max/21.

[1010 11:08:05.475701] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.1] TokenRequestV2 cnt/2 avg/44 min/30 max/58.

[1010 11:08:05.475705] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.1] TokenChangeV4 cnt/58 avg/1025 min/4 max/58807.

[1010 11:08:05.475710] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.2] TokenRequestV2 cnt/2 avg/25 min/19 max/32.

[1010 11:08:05.475714] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.2] OpenChange cnt/2 avg/27 min/10 max/45.

[1010 11:08:05.475718] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.2] TokenChangeV4 cnt/70 avg/3088 min/3 max/116624.

[1010 11:08:05.475723] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.6] TokenRequestV2 cnt/2 avg/30 min/26 max/35.

[1010 11:08:05.475727] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.6] TokenRequestV3 cnt/1 avg/86 min/86 max/86.

[1010 11:08:05.475730] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.6] TokenChangeV4 cnt/18 avg/20 min/4 max/170.

[1010 11:08:05.475736] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.6] TokenReqAlloc cnt/7 avg/111901 min/65 max/746407.

[1010 11:08:05.475742] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.4] TokenRequestV2 cnt/2 avg/32 min/31 max/33.

[1010 11:08:05.475746] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.4] TokenChangeV4 cnt/2 avg/8 min/8 max/8.

[1010 11:08:05.475750] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.3] TokenRequestV2 cnt/2 avg/29 min/23 max/35.

[1010 11:08:05.475754] 0xa013d720 (Debug) TKN SUMMARY [172.22.22.3] TokenRequestV3 cnt/1 avg/56 min/56 max/56.

[1010 11:08:05.475772] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.5] ReconDone cnt/1 avg/30 min/30 max/30.

[1010 11:08:05.475777] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.5] RestoreLock cnt/6 avg/32 min/21 max/51.

[1010 11:08:05.475786] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.1] ClearLock cnt/11 avg/28 min/8 max/72.

[1010 11:08:05.475790] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.1] ReconDone cnt/1 avg/31 min/31 max/31.

[1010 11:08:05.475794] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.1] RestoreLock cnt/80 avg/31 min/11 max/52.

[1010 11:08:05.475798] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.2] ClearLock cnt/4 avg/27 min/22 max/32.

[1010 11:08:05.475801] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.2] ReconDone cnt/1 avg/12 min/12 max/12.

[1010 11:08:05.475805] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.2] RestoreLock cnt/2 avg/27 min/24 max/30.

[1010 11:08:05.475813] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.6] ReconDone cnt/1 avg/32 min/32 max/32.

[1010 11:08:05.475817] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.6] RestoreLock cnt/216 avg/29 min/13 max/52.

[1010 11:08:05.475822] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.4] ReconDone cnt/1 avg/34 min/34 max/34.

[1010 11:08:05.475875] 0xa013d720 (Debug) BRL SUMMARY [172.22.22.3] ReconDone cnt/1 avg/36 min/36 max/36.

[1010 11:08:05] 0xb8dad000 (**FATAL**) PANIC: aborting threads now.

[1010 11:08:27] 0xa013d720 (Info) Server Revision 3.1.0 Build 2 (339.12)

[1010 11:08:27] 0xa013d720 (Info) Built for Darwin 9.0 ppc

[1010 11:08:27] 0xa013d720 (Info) Created on Tue Feb 19 17:29:50 PST 2008

[1010 11:08:27] 0xa013d720 (Info) Built in /SourceCache/XsanFS/XsanFS-339.12

[1010 11:08:27] 0xa013d720 (Info)

[1010 11:08:27] 0xa013d720 (Info) Self (dir1) IP address is 172.22.225.29.

[1010 11:08:27.161609] 0xa013d720 (Debug) No fsports file - port range enforcement disabled.

[1010 11:08:27] 0xa013d720 (Info) Listening on TCP socket dir1:60018

[1010 11:08:27] 0xa013d720 (Info) Node [0] [dir1:60018] File System Manager Login.

[1010 11:08:27] 0xa013d720 (Info) Service standing by on host 'dir1:60018'.

[1010 11:08:30.520792] 0xa013d720 (Debug) Standby service - NSS ping from 172.22.22.6:56227.

[1010 11:08:30.520918] 0xa013d720 (Debug) Standby service - NSS ping from 172.22.22.5:64465.

[1010 11:08:30.521019] 0xa013d720 (Debug) Standby service - NSS ping from 172.22.22.2:58870.

[1010 11:08:30.521116] 0xa013d720 (Debug) Standby service - NSS ping from 172.22.22.1:62777.

[1010 11:08:30.522880] 0xa013d720 (Debug) FOUsurpCheck: read ARB info (pass 1): host (172.22.225.29:49177) conns 0 age 1349863686.00 secs his delta 0.00 secs my delta 3.00 secs.

[1010 11:08:30.522889] 0xa013d720 (Debug) FOUsurpCheck: ARB is already mine.

[1010 11:08:30] 0xa013d720 (Info) Branding Arbitration Block (attempt 1) votes 3.

[1010 11:08:32.525870] 0xa013d720 (Debug) Cannot find fail over script [/Library/Filesystems/Xsan/bin/cvfail.dir1] - looking for generic script.

[1010 11:08:32] 0xa013d720 (Info) Launching fail over script ["/Library/Filesystems/Xsan/bin/cvfail" dir1 60018 SAN]

[1010 11:08:32.534331] 0xa013d720 (Debug) Starting journal log recovery.

[1010 11:08:32.656098] 0xa013d720 (Debug) Completed journal log recovery.

[1010 11:08:32.656439] 0xa013d720 (Debug) Inode_init_post_activation: FsStatus 0xd27, Brl_ResyncState 1

[1010 11:08:32] 0xb8eb1000 (Info) FSM Alloc:  Loading Stripe Group "MetadataAndJournal". 418.15 GB.

[1010 11:08:32] 0xb8f33000 (Info) FSM Alloc:  Loading Stripe Group "Data". 4.90 TB.

[1010 11:08:32] 0xb8eb1000 (Info) FSM Alloc:  Stripe Group "MetadataAndJournal" active.

[1010 11:08:33] 0xb8f33000 (Warning) FSM Alloc: Stripe Group "Data" 15032983 free blocks in 218141 fragments inserted.

[1010 11:08:33] 0xb8f33000 (Warning) FSM Alloc: Stripe Group "Data" 1039194 free blocks in 86357 fragments ignored.

[1010 11:08:33] 0xb8f33000 (Info) FSM Alloc:  free blocks 15032983 with 0 blocks currently  reserved for client delayed buffers.Reserved blocks may change with client activity.

[1010 11:08:33] 0xb8f33000 (Info) FSM Alloc:  Stripe Group "Data" active.

[1010 11:08:33] 0xa013d720 (Warning) Windows Security has been turned off in config file but clients have been requested to enforce ACLs.  Windows Security remains in effect.

[1010 11:08:33] 0xa013d720 (Info) File system 'SAN' requires UTF8-NFC file names

[1010 11:08:33] 0xa013d720 (Info) File System Service 'SAN[1]' now active on host 'dir1:60018'.

[1010 11:08:33] 0xb9037000 (Info) Inode_fl_scan: starting scan

[1010 11:08:33.294726] 0xa013d720 (Debug) Node [1] [172.22.22.4:53966] connected.

[1010 11:08:33.294924] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.4:53965.

[1010 11:08:33.295063] 0xa013d720 (Debug) Node [2] [172.22.22.2:58872] connected.

[1010 11:08:33.295281] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.2:58871.

[1010 11:08:33.295545] 0xa013d720 (Debug) Node [3] [172.22.22.1:62779] connected.

[1010 11:08:33.295778] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.1:62778.

[1010 11:08:33.295923] 0xa013d720 (Debug) Node [4] [172.22.22.5:64467] connected.

[1010 11:08:33.296096] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.5:64466.

[1010 11:08:33.296266] 0xa013d720 (Debug) Node [5] [172.22.22.6:56229] connected.

[1010 11:08:33.296440] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.6:56228.

[1010 11:08:33.296571] 0xa013d720 (Debug) Node [6] [172.22.22.3:60024] connected.

[1010 11:08:33.296731] 0xa013d720 (Debug) Active service - NSS ping from 172.22.22.3:60023.

[1010 11:08:33] 0xb4695000 (Info) Node [1] [172.22.22.4:53966] Client Login (active 1).

[1010 11:08:33] 0xb4717000 (Info) Node [6] [172.22.22.3:60024] Client Login (active 2).

[1010 11:08:33] 0xb481b000 (Info) Node [3] [172.22.22.1:62779] Client Login (active 3).

[1010 11:08:33] 0xb4799000 (Info) Node [2] [172.22.22.2:58872] Client Login (active 4).

[1010 11:08:33] 0xb491f000 (Info) Node [5] [172.22.22.6:56229] Client Login (active 5).

[1010 11:08:33] 0xb489d000 (Info) Node [4] [172.22.22.5:64467] Client Login (active 6).

[1010 11:08:33] 0xb607b000 (Info) XsanSpotlightGetSearchLevel: Unable to copy store attributes -> No index

[1010 11:08:33] 0xb607b000 (Info) XsanSpotlightRpc_ChannelCreate: Spotlight is disabled, rejecting request

[1010 11:08:34] 0xb9037000 (**Error**) add_to_free_list: inode 0x7f800000bd39ca failed lookup

[1010 11:08:34] 0xb9037000 (Info) Inode_fl_scan: scan aborted

[1010 11:08:34] 0xb9037000 (Info) Inode_fl_scan final tally: 76233 inodes scanned, 0 pending added, 0 free added.

[1010 11:08:34] 0xb5df1000 (**Critical**) No Space! [alloc.c:2627] [0x8 0x20].

[1010 11:08:34.328118] 0xb7ae3000 (Debug) Alloc max us latency 22813 inode 0x58000084ff6f0 byte hint 0x2c0000 actual 0x2c0000

[1010 11:08:34.354556] 0xb5df1000 (Debug) Alloc max us latency 49069 inode 0x28000084ff6f1 byte hint 0x240000 actual 0x240000

[1010 11:08:34.591766] 0xb5ff9000 (Debug) Alloc max us latency 205743 inode 0x28000084ff6ee byte hint 0xc000 actual 0xc000

[1010 11:08:34] 0xb8e2f000 (**FATAL**) PANIC: /Library/Filesystems/Xsan/bin/fsm "free_pending_inode_thread: Cannot lookup extended inode [0xa9ed7e8] -No such file or directory


Mac OS X (10.5.6)
  • Blaidd Drwg Level 1 Level 1 (70 points)

     

    [1010 11:08:27] 0xa013d720 (Info) Server Revision 3.1.0 Build 2 (339.12)

    [1010 11:08:27] 0xa013d720 (Info) Built for Darwin 9.0 ppc

    [1010 11:08:27] 0xa013d720 (Info) Created on Tue Feb 19 17:29:50 PST 2008

     

     

    That's Xsan 2.0. That's really old version. Upgrade to Xsan 2.1.1, which is the highest version you can upgrade to on a PowerPC Mac. If problems persist, run cvfsck per http://support.apple.com/kb/HT1081.

     

    You may need the -C option to create a new free inode list. That's not in HT1081, but you can see it documented in the man page. See "man cvfsck".