IBM DS5K Controller Boot

` Reset, Power-Up Diagnostics 3600 Processor DRAM 01 Data lines 02 Address lines 4470 ZIP 01 Register read 03 Register data lines 3710 RPA Memory 01 Data lines 02 Address lines 3300 NVSRAM 01 Data lines 440B Ethernet 82573 #1 01 Register read 02 Register address lines 03 Register data lines 04 MDI Register test 05 Interrupt test 06 Serial EEPROM validation 440C Ethernet 82573 #2 01 Register read 02 Register address lines 03 Register data lines 04 MDI Register test 05 Interrupt test 06 Serial EEPROM validation 6BD1 Drive Channel 1--Tachyon QE4 01 TachLite Register Test 6BD2 Drive Channel 2--Tachyon QE4 01 TachLite Register Test 6BD3 Drive Channel 3--Tachyon QE4 01 TachLite Register Test 6BD4 Drive Channel 4--Tachyon QE4 01 TachLite Register Test 6BD5 Drive Channel 5--Tachyon QE4 01 TachLite Register Test 6BD6 Drive Channel 6--Tachyon QE4 01 TachLite Register Test 6BD7 Drive Channel 7--Tachyon QE4 01 TachLite Register Test 6BD8 Drive Channel 8--Tachyon QE4 01 TachLite Register Test 65D0 Host Channel 1--Tachyon QE8 01 TachLite Register Test 65D1 Host Channel 2--Tachyon QE8 01 TachLite Register Test 65D2 Host Channel 3--Tachyon QE8 01 TachLite Register Test 65D3 Host Channel 4--Tachyon QE8 01 TachLite Register Test 3900 Real-Time Clock 01 RT Clock Tick Diagnostic Manager exited normally. - Loop 1 of 1
Passed
Passed

Passed
Passed

Passed
Passed

Passed

Passed
Passed
Passed
Passed
Passed
Passed

Passed
Passed
Passed
Passed
Passed
Passed

Passed

Passed

Passed

Passed

Passed

Passed

Passed

Passed

Passed

Passed

Passed

Passed

Passed

Current date: 09/17/19 time: 19:22:01

Send for Service Interface or baud rate change EHCI Controller found. Waiting to attach to USBD...Done. 09/18/19-04:02:02 (usbPlatformInit): NOTE: USB Initialization Complete 09/18/19-04:02:02 (tRAID): NOTE: Set Powerup State 09/18/19-04:02:02 (tRAID): NOTE: SOD Sequence is Normal, 0 Found Bulk Device with 1 Logical Units at node 2 Instantiating /bd0 as rawFs, device = 0x10001 09/18/19-04:02:04 (tRAID): NOTE: Installed Protocols:
09/18/19-04:02:04 (tRAID): NOTE: Required Protocols:
eth0: LinkUp event 09/18/19-04:02:06 (tRAID): NOTE: SYMBOL: SYMbolAPI registered. 09/18/19-04:02:06 (tRAID): WARN: RCBBitmapManager total RPA size = 0 09/18/19-04:02:06 (tRAID): NOTE: b_isn is a stub 09/18/19-04:02:06 (tRAID): NOTE: lost persistent dq data because buffer was modified or size changed. 09/18/19-04:02:13 (tRAID): NOTE: eel::VirtualDriveEvent allocating 4096 objects 09/18/19-04:02:13 (tRAID): NOTE: SOD: Instantiation Phase Complete 09/18/19-04:02:13 (tRAID): NOTE: I2C transaction returned 0x0011a15f 09/18/19-04:02:13 (tRAID): NOTE: I2C transaction returned 0x0011a15f 09/18/19-04:02:13 (tRAID): NOTE: I2C transaction returned 0x0011a55f 09/18/19-04:02:13 (tRAID): NOTE: I2C transaction returned 0x0011a55f 09/18/19-04:02:13 (tRAID): NOTE: I2C transaction returned 0x0011a95f 09/18/19-04:02:13 (tRAID): NOTE: I2C transaction returned 0x0011a95f 09/18/19-04:02:13 (tRAID): NOTE: I2C transaction returned 0x0011ad5f 09/18/19-04:02:13 (tRAID): NOTE: I2C transaction returned 0x0011ad5f 09/18/19-04:02:13 (tRAID): NOTE: Inter-Controller Communication Channels Opened 09/18/19-04:02:13 (tRAID): NOTE: LockMgr Role is Slave 09/18/19-04:02:14 (utlTimer): NOTE: fcnChannelReport ==> ~0 ~1 ~2 ~3 ~4 ~5 ~6 ~7 09/18/19-04:02:17 (IOSched): NOTE: Extended Link Down ==> Chan 4 09/18/19-04:02:18 (IOSched): NOTE: Extended Link Down ==> Chan 0 09/18/19-04:02:19 (tRAID): NOTE: WWN baseName 000600a0-b86e5fe6 (valid==>SigMatch) 09/18/19-04:02:19 (tRAID): NOTE: spmEarlyData: No data available 09/18/19-04:02:20 (tRAID): NOTE: SOD: Pre-Initialization Phase Complete 09/18/19-04:02:20 (utlTimer): NOTE: fcnChannelReport ==> ~0 ~1 ~2 ~3 ~4 ~5 ~6 ~7 ~8 -9 -10 -11 09/18/19-04:02:26 (utlTimer): NOTE: fcnChannelReport ==> ~0 ~1 ~2 ~3 ~4 ~5 ~6 ~7 ~8 =9 =10 =11 09/18/19-04:02:33 (tRAID): NOTE: ACS: autoCodeSync(): Process start. Comm Mode: 0, Status: 1 09/18/19-04:02:33 (iacTask7): NOTE: ACS: Acs Needed on Alt: No, StateCode: 0, ReasonCode = 2 09/18/19-04:02:33 (tRAID): NOTE: SOD: Code Synchronization Initialization Phase Complete 09/18/19-04:02:34 (tRAID): NOTE: USM Mgr initialization complete with 0 records. 09/18/19-04:02:35 (NvpsPersistentSyncM): NOTE: NVSRAM Persistent Storage updated successfully 09/18/19-04:02:35 (tRAID): NOTE: EDR - recieved 1 small records 09/18/19-04:02:35 (tRAID): NOTE: EDR - recieved 0 large records 09/18/19-04:02:37 (tRAID): NOTE: DVC configuration written on backup device 09/18/19-04:02:37 (tRAID): NOTE: Acquire 5.232 ms 09/18/19-04:02:39 (iacTask7): NOTE: fbm:altValidateSubModelID: Sub-Model IDs Validated 09/18/19-04:02:42 (tRAID): NOTE: PM - reading DB (records 1..0) 09/18/19-04:02:44 (utlTimer): NOTE: fcnChannelReport ==> ~0 1 ~2 3 ~4 5 ~6 7 ~8 =9 =10 =11 09/18/19-04:02:45 (utlTimer): NOTE: fcnChannelReport ==> ~0 1 2 3 ~4 5 6 7 ~8 =9 =10 =11 09/18/19-04:02:45 (iconMgr1): WARN: Drive not found in DriveMgr::removeDriveAlt 09/18/19-04:02:45 (iconMgr2): WARN: Drive not found in DriveMgr::removeDriveAlt 09/18/19-04:02:45 (iconMgr7): WARN: Drive not found in DriveMgr::removeDriveAlt 09/18/19-04:02:45 (iconMgr8): WARN: Drive not found in DriveMgr::removeDriveAlt 09/18/19-04:02:48 (tRAID): NOTE: CCM:readCheckpointFromNvsram for this 0x81e312c0 alt 0x0 09/18/19-04:02:48 (tRAID): NOTE: CCM: validateCacheMem() cache memory is invalid 09/18/19-04:02:48 (tRAID): NOTE: CCM: validateCacheMem() Initializing my partition 09/18/19-04:02:48 (utlTimer): NOTE: fcnChannelReport ==> ~0 1 2 3 4 5 6 7 ~8 =9 =10 =11 09/18/19-04:02:48 (tRAID): WARN: PSTOR: PstorRecordManager::readRecord data block not found 09/18/19-04:02:48 (tRAID): WARN: CCM: setupRcbBitmapRegion(): Sync RPA RCB bitmap region from pstor 09/18/19-04:02:48 (tRAID): NOTE: Cache: Restoring RCB region of this controller ... 09/18/19-04:02:49 (tRAID): NOTE: Cache: RCB region restore of this controller completed 09/18/19-04:02:49 (tRAID): WARN: Failed to alt backup volumes from PBM 09/18/19-04:02:49 (tRAID): ERROR: Failed to get backup volume pointers for this controller 09/18/19-04:02:49 (tRAID): WARN: CCM: startRestoreProcessing() Restore of RCBs failed, let alternate takeover 09/18/19-04:02:49 (tRAID): NOTE: CCM: discardBackup(): Discarding backup volumes and deleting backup status record from pstor 09/18/19-04:02:49 (tRAID): WARN: Attempt to delete FSB pool (P ) with 8600578 FSBs allocated. 09/18/19-04:02:49 (tRAID): WARN: Attempt to delete FSB pool () with 12484866 FSBs allocated. 09/18/19-04:02:49 (tRAID): WARN: CCM: checkRecoveryNeededFromAlt(): Backup was attempted but no backup status record present in Pstor 09/18/19-04:02:49 (tRAID): WARN: CCM: checkRecoveryNeededFromAlt(): This or alternate is not partitioned for mirroring,hence alternate cannot take over, -- There will be data loss 09/18/19-04:02:50 (tRAID): NOTE: CCM: initialize(): Configuring cache 09/18/19-04:02:52 (utlTimer): NOTE: fcnChannelReport ==> 0 1 2 3 4 5 6 7 ~8 =9 =10 =11 09/18/19-04:02:53 (tRAID): NOTE: Starting UWManager::initialize, entries 2046, invalid index -1 09/18/19-04:02:53 (tRAID): NOTE: Size of NVSRAM IW Queue is 0 09/18/19-04:02:53 (tRAID): NOTE: No DSM Device found for Drive 09/18/19-04:02:53 (tRAID): NOTE: No DSM Device found for Drive 09/18/19-04:02:53 (tRAID): NOTE: No DSM Device found for Drive 09/18/19-04:02:53 (tRAID): NOTE: No DSM Device found for Drive

Exception: Invalid Opcode pc: 0x00000415 (Unknown Program Counter)

Registers: edi = 5 esi = 100 ebp = 12c1080 esp = 12c1024 ebx = 12c1064 edx = de569a4 ecx = 0 eax = 52504d56 eflags = 246 pc = 415

Stack Trace: 5a396f vxTaskEntry +f : sodMain (0, 0, 0, 0, 0, 0, 0, 0, 0, 0) 4b5bb2d sodMain +1f1 : _Z17sodInitializationv () ??? 4b5a7a0 _Z17sodInitializationv+1a : _Z24sodInitializeApplicationv () ??? 4b5a2c6 _Z24sodInitializeApplicationv+c6 : _Z13sodLogStartupPFvvE () ??? 4b59faa _Z13sodLogStartupPFvvE+e4 : _ZN3vdm10initializeEv () ??? 4767166 _ZN3vdm10initializeEv+ab4 : _ZN3vdm18VolumeGroupManager12completeInitEPN3txn17MasterTransactionE () ??? 472e4ab _ZN3vdm18VolumeGroupManager12completeInitEPN3txn17MasterTransactionE+ab : _ZN3vdm18VolumeGroupManager28setCacheFlushLimitForRestoreEv ([d93b60c, e030 ʌ 9#DCsֹs)H؟ARNING: Reset by alternate controller

Current date: 09/17/19 time: 19:23:11

Send for Service Interface or baud rate change EHCI Controller found. Waiting to attach to USBD...Done. 09/18/19-04:03:12 (usbPlatformInit): NOTE: USB Initialization Complete 09/18/19-04:03:12 (tRAID): NOTE: SOD Sequence is Normal, 0 09/18/19-04:03:13 (tRAID): NOTE: SODRebootLoop- Limit:5 Cnt:1 Found Bulk Device with 1 Logical Units at node 2 Instantiating /bd0 as rawFs, device = 0x10001 09/18/19-04:03:14 (tRAID): NOTE: Installed Protocols:
09/18/19-04:03:14 (tRAID): NOTE: Required Protocols:
eth0: LinkUp event 09/18/19-04:03:16 (tRAID): NOTE: SYMBOL: SYMbolAPI registered. 09/18/19-04:03:16 (tRAID): WARN: RCBBitmapManager total RPA size = 0 09/18/19-04:03:16 (tRAID): NOTE: b_isn is a stub 09/18/19-04:03:17 (tRAID): NOTE: eel::VirtualDriveEvent allocating 4096 objects 09/18/19-04:03:17 (tRAID): NOTE: SOD: Instantiation Phase Complete 09/18/19-04:03:17 (tRAID): NOTE: I2C transaction returned 0x0011a15f 09/18/19-04:03:17 (tRAID): NOTE: I2C transaction returned 0x0011a15f 09/18/19-04:03:17 (tRAID): NOTE: I2C transaction returned 0x0011a55f 09/18/19-04:03:17 (tRAID): NOTE: I2C transaction returned 0x0011a55f 09/18/19-04:03:17 (tRAID): NOTE: I2C transaction returned 0x0011a95f 09/18/19-04:03:17 (tRAID): NOTE: I2C transaction returned 0x0011a95f 09/18/19-04:03:17 (tRAID): NOTE: I2C transaction returned 0x0011ad5f 09/18/19-04:03:17 (tRAID): NOTE: I2C transaction returned 0x0011ad5f 09/18/19-04:03:18 (utlTimer): NOTE: fcnChannelReport ==> ~0 ~1 ~2 ~3 ~4 ~5 ~6 ~7 09/18/19-04:03:18 (tRAID): NOTE: Inter-Controller Communication Channels Opened 09/18/19-04:03:18 (tRAID): NOTE: LockMgr Role is Slave 09/18/19-04:03:19 (tRAID): NOTE: WWN baseName 000600a0-b86e5fe6 (valid==>SoftRst) 09/18/19-04:03:19 (tRAID): NOTE: spmEarlyData: Using cached data 09/18/19-04:03:20 (tRAID): NOTE: SOD: Pre-Initialization Phase Complete 09/18/19-04:03:21 (utlTimer): NOTE: fcnChannelReport ==> ~0 ~1 ~2 ~3 ~4 ~5 ~6 ~7 ~8 -9 -10 -11 09/18/19-04:03:27 (utlTimer): NOTE: fcnChannelReport ==> ~0 ~1 ~2 ~3 ~4 ~5 ~6 ~7 ~8 =9 =10 =11 09/18/19-04:03:30 (tRAID): NOTE: ACS: autoCodeSync(): Process start. Comm Mode: 0, Status: 1 09/18/19-04:03:30 (tRAID): NOTE: SOD: Code Synchronization Initialization Phase Complete 09/18/19-04:03:30 (NvpsPersistentSyncM): NOTE: NVSRAM Persistent Storage updated successfully 09/18/19-04:03:30 (tRAID): NOTE: USM Mgr initialization complete with 0 records. 09/18/19-04:03:31 (tRAID): NOTE: EDR - recieved 1 small records 09/18/19-04:03:31 (tRAID): NOTE: EDR - recieved 0 large records 09/18/19-04:03:32 (tRAID): NOTE: DVC configuration written on backup device 09/18/19-04:03:32 (tRAID): NOTE: Acquire 5.129 ms 09/18/19-04:03:33 (tRAID): NOTE: PM - reading DB (records 1..0) 09/18/19-04:03:33 (tRAID): WARN: PSTOR: PstorRecordManager::readRecord data block not found 09/18/19-04:03:34 (tRAID): NOTE: CCM: initialize(): Configuring cache 09/18/19-04:03:37 (tRAID): NOTE: Starting UWManager::initialize, entries 2046, invalid index -1 09/18/19-04:03:37 (tRAID): NOTE: Size of NVSRAM IW Queue is 0 09/18/19-04:03:37 (tRAID): NOTE: No DSM Device found for Drive 09/18/19-04:03:37 (tRAID): NOTE: No DSM Device found for Drive 09/18/19-04:03:37 (tRAID): NOTE: No DSM Device found for Drive 09/18/19-04:03:37 (tRAID): NOTE: No DSM Device found for Drive 09/18/19-04:03:37 (tRAID): WARN: *** Volume 3 is now FAILED *** 09/18/19-04:03:40 (tRAID): NOTE: RTR: IO Released 09/18/19-04:03:40 (tRAID): NOTE: SOD: Initialization Phase Complete ============================================== Title: Disk Array Controller Copyright 2007-2010 LSI Logic Corporation, All Rights Reserved.

Name: RC Version: 07.60.40.00 Date: 05/26/2010 Time: 10:56:41 CDT Models: 7091 Manager: devmgr.v1060api09.Manager ==============================================

09/18/19-04:03:40 (tRAID): NOTE: sodMain Normal sequence finished, elapsed time = 28 seconds 09/18/19-04:03:40 (tRAID): NOTE: sodMain complete 09/18/19-04:03:41 (ProcessHandlers): NOTE: ddc backupAvailable invoked 09/18/19-04:03:41 (PersistentRestore): WARN: PSTOR: PstorRecordManager::readRecord data block not found 09/18/19-04:03:41 (PersistentRestore): WARN: IOManager::readBackupStatus - Pstor record does not exsit 09/18/19-04:03:41 (PersistentRestore): NOTE: IOManager::getBackupDataSize - read to pstor failed 09/18/19-04:03:41 (PersistentRestore): WARN: DDC Backup does not exists so aborting Restore. 09/18/19-04:03:41 (PersistentRestore): NOTE: DDC Restore Completed

09/18/19-04:03:41 (PersistentRestore): NOTE: IOManager::restoreData - m_DataSize:0xc1e00, m_StartAddress:0x0 09/18/19-04:03:41 (PersistentRestore): NOTE: IOManager::restoreData - Successful 09/18/19-04:03:41 (ProcessHandlers): NOTE: SYMbol available 09/18/19-04:03:41 (PersistentRestore): NOTE: DQ Restore Completed

09/18/19-04:03:41 (ProcessHandlers): NOTE: SOD: sodComplete Notification Complete 09/18/19-04:03:48 (utlTimer): NOTE: fcnChannelReport ==> 0 1 ~2 3 ~4 ~5 ~6 ~7 ~8 =9 =10 =11 09/18/19-04:03:49 (utlTimer): NOTE: fcnChannelReport ==> 0 1 2 3 ~4 ~5 ~6 ~7 ~8 =9 =10 =11 09/18/19-04:03:50 (utlTimer): NOTE: fcnChannelReport ==> 0 1 2 3 4 ~5 ~6 ~7 ~8 =9 =10 =11 09/18/19-04:03:51 (utlTimer): NOTE: fcnChannelReport ==> 0 1 2 3 4 5 ~6 ~7 8 =9 =10 =11 09/18/19-04:03:52 (utlTimer): NOTE: fcnChannelReport ==> 0 1 2 3 4 5 ~6 7 8 =9 =10 =11 09/18/19-04:03:56 (utlTimer): NOTE: fcnChannelReport ==> 0 1 2 3 4 5 6 7 8 =9 =10 =11 0x12a7b20 (tNetCfgInit): miiPhyInit check cable connection eth1: LinkDown event 09/18/19-04:04:06 (tNetCfgInit): NOTE: Network Ready 09/18/19-04:04:20 (utlTimer): WARN: Extended Link Down Timeout on channel 9 09/18/19-04:04:20 (utlTimer): WARN: Extended Link Down Timeout on channel 10 09/18/19-04:04:21 (utlTimer): WARN: Extended Link Down Timeout on channel 11 09/18/19-04:18:39 (symTask1): NOTE: *** Volume 2 is now OPTIMAL *** 09/18/19-04:18:40 (ccmEventTask): NOTE: vdm::syncRequired(): Begin 09/18/19-04:18:40 (ccmEventTask): NOTE: vdm::syncRequired(): Complete, elapsed time = 0 seconds 09/18/19-04:18:40 (ccmEventTask): NOTE: CCM: reconfigureCache() reconfigSyncCache succeeded 09/18/19-04:18:40 (ccmEventTask): NOTE: CCM: reconfigureCache() quiesceVolumes succeeded 09/18/19-04:18:40 (ccmEventTask): NOTE: CCM: reconfigureCache() Partitioning for mirroring 09/18/19-04:18:40 (ccmEventTask): NOTE: CCM: reconfigureCache() initializing my partition 09/18/19-04:18:41 (ccmEventTask): NOTE: CCM: reconfigureCache() Initializing alt's mirror partition 09/18/19-04:18:42 (ccmEventTask): NOTE: CCM: reconfigureCache() configuring cache 09/18/19-04:18:43 (ccmEventTask): NOTE: CCM: reconfigureCacheCommon() clearing MOS 09/18/19-04:19:10 (symTask2): NOTE: *** Volume 3 is now OPTIMAL ***

09/18/19-04:19:59 (iconMgr1): NOTE: *** Volume 4 is now OPTIMAL *** `