Pro/Forums - View Single Post

rpmurray · 12-10-2008, 07:16 AM

Day 8. Ta Da. Completed.

We're back up and running in degraded mode.

These are the final log entries:

12/10/2008 2:44:57 37 D SYS | DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2D90 sts=19
12/10/2008 2:45:02 37 D SYS | DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2D90 sts=19
12/10/2008 2:45:03 37 D SYS | DISK: req=0xDB37C0 dev=0x80000 fn=1 blk=0xFAB2D90 sts=19
12/10/2008 2:45:09 37 D SYS | DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2DA0 sts=20
12/10/2008 2:45:13 37 D SYS | DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2DA0 sts=19
12/10/2008 2:45:13 37 D SYS | DISK: req=0xDB37C0 dev=0x80000 fn=1 blk=0xFAB2DA0 sts=19
12/10/2008 2:45:18 37 D SYS | DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2DB0 sts=20
12/10/2008 2:45:22 37 D SYS | DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2DB0 sts=19
12/10/2008 2:45:23 37 D SYS | DISK: req=0xDB37C0 dev=0x80000 fn=1 blk=0xFAB2DB0 sts=19
12/10/2008 2:45:43 37 D SYS | DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB6DC0 sts=7
12/10/2008 2:45:44 37 D SYS | DISK: req=0x111E328 dev=0xC0000 fn=3 blk=0x1 sts=12
12/10/2008 2:45:45 37 D SYS | DISK: req=0x111E328 dev=0xC0000 fn=3 blk=0x1 sts=12
12/10/2008 2:45:45 37 E L01 | File System : Unrecoverable error on logical device 60000. Member 10000 failing
12/10/2008 2:45:45 37 W L01 | File System : Disk I/O error on RAID-5 device 60000
12/10/2008 2:45:45 37 W D[80060000] | File System : Logical device 80060000: no spares found to perform hot replacement
12/10/2008 2:45:45 37 D SYS | DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB6DC0 sts=1
12/10/2008 2:45:45 37 D SYS | DISK: req=0xDB37C0 dev=0x80000 fn=1 blk=0xFAB6DC0 sts=1
12/10/2008 2:45:45 37 E L01 | File System : RAID-5 device 60000 operating in degraded mode
12/10/2008 2:46:26 37 I L01 | File System Check : ** Phase 1b - Rescan for more duplicate blocks
12/10/2008 2:46:26 37 I L01 | File System Check : ** Phase 2 - Check pathnames
12/10/2008 5:28:14 37 I L01 | File System Check : ** Phase 3 - Check connectivity
12/10/2008 5:29:26 37 I L01 | File System Check : ** Phase 4 - Check reference counts
12/10/2008 5:31:13 37 I L01 | File System Check : ** Phase 4b - Check backlinks
12/10/2008 5:35:08 37 I L01 | File System Check : ** Phase 5 - Check cylinder groups
12/10/2008 5:35:08 37 W L01 | File System Check : Blk(s) missing in bit maps (Salvaged)
12/10/2008 5:35:08 37 W L01 | File System Check : Summary information bad (Salvaged)
12/10/2008 5:44:17 37 W L01 | File System Check : Free blk count(s) wrong in superblk (Salvaged)
12/10/2008 5:44:17 37 W L01 | File System Check : Modified flag set in superblock (Fixed)
12/10/2008 5:44:17 37 W L01 | File System Check : Clean flag not set in superblock (Fixed)
12/10/2008 5:44:17 37 D SYS | 21938076 bytes used during fsck()
12/10/2008 5:44:17 37 I L01 | File System Check : 4333803 files, 44214049 used, 5142887 free (0 frags, 5142887 blocks, 0.0%% fragmentation)
12/10/2008 5:44:17 37 I L01 | File System Check : ***** File system was modified *****
12/10/2008 5:44:17 37 D SYS | Elapsed time: 581400 s.
12/10/2008 5:44:17 37 D SYS | Fsck cache statistics:
12/10/2008 5:44:17 37 D SYS | total memory used for cache: 12674412 bytes
12/10/2008 5:44:17 37 D SYS | total number of directories: 194962
12/10/2008 5:44:17 37 D SYS | maximum depth of recursion in sorting: 6
12/10/2008 5:44:17 37 D SYS | number of swaps in sorting phase: 2175356
12/10/2008 5:44:17 37 D SYS | ----- generic i-node cache -----
12/10/2008 5:44:17 37 D SYS | cache entries: 2580
12/10/2008 5:44:17 37 D SYS | cache hits: 266087710 (99%)
12/10/2008 5:44:17 37 D SYS | cache misses: 2442895 (0%)
12/10/2008 5:44:17 37 D SYS | reused cache entries: 2440960
12/10/2008 5:44:17 37 D SYS | total reads from swap device: 2296288
12/10/2008 5:44:17 37 D SYS | total writes to swap device: 1014858
12/10/2008 5:44:17 37 D SYS | total writes skipped (clean blocks): 1426102
12/10/2008 5:44:17 37 D SYS | average successful cache lookup: 1.00 iterations
12/10/2008 5:44:17 37 D SYS | maximum successful cache lookup: 1 iterations
12/10/2008 5:44:17 37 D SYS | average unsuccessful cache lookup: 1.00 iterations
12/10/2008 5:44:17 37 D SYS | maximum unsuccessful cache lookup: 1 iterations
12/10/2008 5:44:17 37 D SYS | ----- directory i-node cache -----
12/10/2008 5:44:17 37 D SYS | cache entries: 1290
12/10/2008 5:44:17 37 D SYS | cache hits: 8054465 (99%)
12/10/2008 5:44:17 37 D SYS | cache misses: 45759 (0%)
12/10/2008 5:44:17 37 D SYS | reused cache entries: 46906
12/10/2008 5:44:17 37 D SYS | total reads from swap device: 45759
12/10/2008 5:44:17 37 D SYS | total writes to swap device: 26980
12/10/2008 5:44:17 37 D SYS | total writes skipped (clean blocks): 19926
12/10/2008 5:44:17 37 D SYS | average successful cache lookup: 1.00 iterations
12/10/2008 5:44:17 37 D SYS | maximum successful cache lookup: 1 iterations
12/10/2008 5:44:17 37 D SYS | average unsuccessful cache lookup: 1.00 iterations
12/10/2008 5:44:17 37 D SYS | maximum unsuccessful cache lookup: 1 iterations
12/10/2008 5:44:17 37 I L01 | File System Check : Cleanup completed...
12/10/2008 5:44:17 37 D SYS | Update FDB 0x60000...
12/10/2008 5:44:17 37 I L01 | File System : Opened FDB for device 0x60000
12/10/2008 5:44:17 37 D SYS | Scheduled ACL Set and Propagate at /0/os_private for FDB_ID_0
12/10/2008 5:44:17 37 D SYS | NFS: The hash table has been initialized.
12/10/2008 5:44:17 37 D SYS | NFS: the NFSID <--->FDBID cache has been initialised.
12/10/2008 5:44:17 37 D SYS | NFS Server Disabled.
12/10/2008 5:44:17 37 D SYS | suspend_factor = E3A12
12/10/2008 5:44:17 37 D SYS | DISK: Additional ARBs: 3548 (Mem: 581872) Total Arbs: 4356 (Mem: 714384)
12/10/2008 5:44:17 37 I SYS | System Initialization : Initialization Complete! Memory to be released: 29462592 bytes.
12/10/2008 5:44:17 37 D SYS | Restarted process timing
12/10/2008 5:44:17 37 D SYS | Propagate on /0/os_private: Success - 15 files, 0 dirs; Errors - 0 files, 0 dirs
12/10/2008 5:44:17 37 I L01 | File System : Logical set synchronization done on device 60000

Disk Status says:

RAID5 - Large data protection disk
Data protection disabled. One RAID 5 member has failed. Operating in degraded mode.

Disk 1 has an amber LED.

I'm backing up a few files I'd like to keep. I originally bought six drives for this when I was setting it up; two were as spares for just such a contingency. I'll see what happens when I change out the drive. It'll either accept the drive and rebuild, or it'll give me the same problem I had with the other Snap where it wouldn't bring a spare back into the RAID no matter what I did.

So now we can add to the database that I could take up to 168 hours to do a disk check on a Snap 4100 480GB when a drive encounters a bad block.

12-10-2008, 07:16 AM	#21
rpmurray Cooling Savant Join Date: Apr 2006 Location: Tennessee Posts: 157	Re: Snap Server 4100 Lockup Day 8. Ta Da. Completed. We're back up and running in degraded mode. These are the final log entries: 12/10/2008 2:44:57 37 D SYS \| DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2D90 sts=19 12/10/2008 2:45:02 37 D SYS \| DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2D90 sts=19 12/10/2008 2:45:03 37 D SYS \| DISK: req=0xDB37C0 dev=0x80000 fn=1 blk=0xFAB2D90 sts=19 12/10/2008 2:45:09 37 D SYS \| DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2DA0 sts=20 12/10/2008 2:45:13 37 D SYS \| DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2DA0 sts=19 12/10/2008 2:45:13 37 D SYS \| DISK: req=0xDB37C0 dev=0x80000 fn=1 blk=0xFAB2DA0 sts=19 12/10/2008 2:45:18 37 D SYS \| DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2DB0 sts=20 12/10/2008 2:45:22 37 D SYS \| DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB2DB0 sts=19 12/10/2008 2:45:23 37 D SYS \| DISK: req=0xDB37C0 dev=0x80000 fn=1 blk=0xFAB2DB0 sts=19 12/10/2008 2:45:43 37 D SYS \| DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB6DC0 sts=7 12/10/2008 2:45:44 37 D SYS \| DISK: req=0x111E328 dev=0xC0000 fn=3 blk=0x1 sts=12 12/10/2008 2:45:45 37 D SYS \| DISK: req=0x111E328 dev=0xC0000 fn=3 blk=0x1 sts=12 12/10/2008 2:45:45 37 E L01 \| File System : Unrecoverable error on logical device 60000. Member 10000 failing 12/10/2008 2:45:45 37 W L01 \| File System : Disk I/O error on RAID-5 device 60000 12/10/2008 2:45:45 37 W D[80060000] \| File System : Logical device 80060000: no spares found to perform hot replacement 12/10/2008 2:45:45 37 D SYS \| DISK: req=0xDB37C0 dev=0xC0000 fn=1 blk=0xFAB6DC0 sts=1 12/10/2008 2:45:45 37 D SYS \| DISK: req=0xDB37C0 dev=0x80000 fn=1 blk=0xFAB6DC0 sts=1 12/10/2008 2:45:45 37 E L01 \| File System : RAID-5 device 60000 operating in degraded mode 12/10/2008 2:46:26 37 I L01 \| File System Check : Phase 1b - Rescan for more duplicate blocks 12/10/2008 2:46:26 37 I L01 \| File System Check : Phase 2 - Check pathnames 12/10/2008 5:28:14 37 I L01 \| File System Check : Phase 3 - Check connectivity 12/10/2008 5:29:26 37 I L01 \| File System Check : Phase 4 - Check reference counts 12/10/2008 5:31:13 37 I L01 \| File System Check : Phase 4b - Check backlinks 12/10/2008 5:35:08 37 I L01 \| File System Check : Phase 5 - Check cylinder groups 12/10/2008 5:35:08 37 W L01 \| File System Check : Blk(s) missing in bit maps (Salvaged) 12/10/2008 5:35:08 37 W L01 \| File System Check : Summary information bad (Salvaged) 12/10/2008 5:44:17 37 W L01 \| File System Check : Free blk count(s) wrong in superblk (Salvaged) 12/10/2008 5:44:17 37 W L01 \| File System Check : Modified flag set in superblock (Fixed) 12/10/2008 5:44:17 37 W L01 \| File System Check : Clean flag not set in superblock (Fixed) 12/10/2008 5:44:17 37 D SYS \| 21938076 bytes used during fsck() 12/10/2008 5:44:17 37 I L01 \| File System Check : 4333803 files, 44214049 used, 5142887 free (0 frags, 5142887 blocks, 0.0%% fragmentation) 12/10/2008 5:44:17 37 I L01 \| File System Check : *** File system was modified *** 12/10/2008 5:44:17 37 D SYS \| Elapsed time: 581400 s. 12/10/2008 5:44:17 37 D SYS \| Fsck cache statistics: 12/10/2008 5:44:17 37 D SYS \| total memory used for cache: 12674412 bytes 12/10/2008 5:44:17 37 D SYS \| total number of directories: 194962 12/10/2008 5:44:17 37 D SYS \| maximum depth of recursion in sorting: 6 12/10/2008 5:44:17 37 D SYS \| number of swaps in sorting phase: 2175356 12/10/2008 5:44:17 37 D SYS \| ----- generic i-node cache ----- 12/10/2008 5:44:17 37 D SYS \| cache entries: 2580 12/10/2008 5:44:17 37 D SYS \| cache hits: 266087710 (99%) 12/10/2008 5:44:17 37 D SYS \| cache misses: 2442895 (0%) 12/10/2008 5:44:17 37 D SYS \| reused cache entries: 2440960 12/10/2008 5:44:17 37 D SYS \| total reads from swap device: 2296288 12/10/2008 5:44:17 37 D SYS \| total writes to swap device: 1014858 12/10/2008 5:44:17 37 D SYS \| total writes skipped (clean blocks): 1426102 12/10/2008 5:44:17 37 D SYS \| average successful cache lookup: 1.00 iterations 12/10/2008 5:44:17 37 D SYS \| maximum successful cache lookup: 1 iterations 12/10/2008 5:44:17 37 D SYS \| average unsuccessful cache lookup: 1.00 iterations 12/10/2008 5:44:17 37 D SYS \| maximum unsuccessful cache lookup: 1 iterations 12/10/2008 5:44:17 37 D SYS \| ----- directory i-node cache ----- 12/10/2008 5:44:17 37 D SYS \| cache entries: 1290 12/10/2008 5:44:17 37 D SYS \| cache hits: 8054465 (99%) 12/10/2008 5:44:17 37 D SYS \| cache misses: 45759 (0%) 12/10/2008 5:44:17 37 D SYS \| reused cache entries: 46906 12/10/2008 5:44:17 37 D SYS \| total reads from swap device: 45759 12/10/2008 5:44:17 37 D SYS \| total writes to swap device: 26980 12/10/2008 5:44:17 37 D SYS \| total writes skipped (clean blocks): 19926 12/10/2008 5:44:17 37 D SYS \| average successful cache lookup: 1.00 iterations 12/10/2008 5:44:17 37 D SYS \| maximum successful cache lookup: 1 iterations 12/10/2008 5:44:17 37 D SYS \| average unsuccessful cache lookup: 1.00 iterations 12/10/2008 5:44:17 37 D SYS \| maximum unsuccessful cache lookup: 1 iterations 12/10/2008 5:44:17 37 I L01 \| File System Check : Cleanup completed... 12/10/2008 5:44:17 37 D SYS \| Update FDB 0x60000... 12/10/2008 5:44:17 37 I L01 \| File System : Opened FDB for device 0x60000 12/10/2008 5:44:17 37 D SYS \| Scheduled ACL Set and Propagate at /0/os_private for FDB_ID_0 12/10/2008 5:44:17 37 D SYS \| NFS: The hash table has been initialized. 12/10/2008 5:44:17 37 D SYS \| NFS: the NFSID <--->FDBID cache has been initialised. 12/10/2008 5:44:17 37 D SYS \| NFS Server Disabled. 12/10/2008 5:44:17 37 D SYS \| suspend_factor = E3A12 12/10/2008 5:44:17 37 D SYS \| DISK: Additional ARBs: 3548 (Mem: 581872) Total Arbs: 4356 (Mem: 714384) 12/10/2008 5:44:17 37 I SYS \| System Initialization : Initialization Complete! Memory to be released: 29462592 bytes. 12/10/2008 5:44:17 37 D SYS \| Restarted process timing 12/10/2008 5:44:17 37 D SYS \| Propagate on /0/os_private: Success - 15 files, 0 dirs; Errors - 0 files, 0 dirs 12/10/2008 5:44:17 37 I L01 \| File System : Logical set synchronization done on device 60000 Disk Status says: RAID5 - Large data protection disk Data protection disabled. One RAID 5 member has failed. Operating in degraded mode. Disk 1 has an amber LED. I'm backing up a few files I'd like to keep. I originally bought six drives for this when I was setting it up; two were as spares for just such a contingency. I'll see what happens when I change out the drive. It'll either accept the drive and rebuild, or it'll give me the same problem I had with the other Snap where it wouldn't bring a spare back into the RAID no matter what I did. So now we can add to the database that I could take up to 168 hours to do a disk check on a Snap 4100 480GB when a drive encounters a bad block.