I have an AVA-c16 instance running which I am using to pre-seed data to an S3 bucket from Commvault. This AVA-c16 instance came down "dirty" during an AWS incident yesterday and now it is reporting errors starting the Storage Optimization service.
I can talk to the S3 bucket fine but I get the following errors in the logs on startup:
(A full log is attached but this is an extract)
[megastore.WARN] (9251) Megastore /data was not shut down cleanly on a prior run
....
Jun 6 14:16:28 localhost rfsd[9249]: [megamount.NOTICE] (9251) cloud_dedup_enabled_ is 1
Jun 6 14:16:28 localhost rfsd[9249]: [megamount.NOTICE] (9251) archival_mode is 0
Jun 6 14:16:28 localhost rfsd[9249]: [megastore.INFO] (9251) Starting megastore for the volume rfsd_volume
Jun 6 14:16:28 localhost rfsd[9249]: [reverse_map.INFO] (9251) allocating 1910767616 bytes for 238845952 reverse map entries
Jun 6 14:16:29 localhost rfsd[9249]: [megastore.INFO] (9251) mandatory initialization : megastore is not empty
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) Replicator configuration:
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) hostname=s3-ap-southeast-2.amazonaws.com
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) interface=
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) port=443
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) web_protocol=
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) protocol_type=0
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) bucket=corelogic-au-ef-ava-backup
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) replication_retry_intvl_secs=0
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) max_replication_retry_intvl_secs=2048
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) max_replication_retries=20
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) S3 Storage Type: Standard
Jun 6 14:16:29 localhost rfsd[9249]: [thread_tuner.INFO] (9251) Setting maximum number of replicator threads to 48
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) Processor replicator initializing and starting 16 threads and 4 high priority threads
Jun 6 14:16:29 localhost hald[3614]: [hald.INFO]: hald_handle_query_request(), hald_main.c:631, build (null): No handler for bnode /hw/hal/hwraid/adapter
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) DR or upgrade from 1.x = 0
Jun 6 14:16:29 localhost rfsd[9249]: [replicationdb.INFO] (9251) Recovering log #1512
Jun 6 14:16:29 localhost rfsd[9249]: [replicationdb.INFO] (9251) Delete type=3 #1511
Jun 6 14:16:29 localhost rfsd[9249]: [replicationdb.INFO] (9251) Delete type=0 #1512
Jun 6 14:16:29 localhost rfsd[9249]: [replicator.INFO] (9251) database opened (no verification necessary)
Jun 6 14:16:29 localhost rfsd[9249]: [megastore.WARN] (9251) Megastore /data was not shut down cleanly on a prior run
..........
Jun 6 14:16:30 localhost rfsd[9249]: [megastore.INFO] (9251) Time stamp until which data is restorable : Fri Jun 3 18:44:15 2016
Jun 6 14:16:30 localhost rfsd[9249]: [upgrade.INFO] (9251) No upgrade needed
Jun 6 14:16:30 localhost rfsd[9249]: [replicator.INFO] (9251) Not replicating object with key info.yaml since cloud md5 matches with local md5
Jun 6 14:16:30 localhost rfsd[9249]: [upgrade.INFO] (9251) initializing hash store
Jun 6 14:16:32 localhost rfsd[9249]: [bs_log.INFO] (9251) Nothing to replay
Jun 6 14:16:32 localhost rfsd[9249]: [index_syncer.INFO] (9251) Processor IndexSyncer initializing and starting 1 threads and 0 high priority threads
Jun 6 14:16:33 localhost rfsd[9249]: [lock.ERR] (9251) Invalid magic in block header
Jun 6 14:16:33 localhost rfsd[9249]: [blk_arr.ERR] (9251) Failed to verify block header for block on device (path = /data/hash_store.dat, start offset = 8192, size = 2955685888, block size = 4096) at index 332030: invalid argument
Jun 6 14:16:33 localhost rfsd[9249]: [lock.ERR] (9251) Invalid magic in block header
Jun 6 14:16:33 localhost rfsd[9249]: [blk_arr.ERR] (9251) Failed to verify block header for block on device (path = /data/hash_store.dat, start offset = 8192, size = 2955685888, block size = 4096) at index 332031: invalid argument
Jun 6 14:16:34 localhost rfsd[9249]: [bs_index.ERR] (9251) Failed to read index from disk: invalid argument
Jun 6 14:16:34 localhost rfsd[9249]: [block_store.ERR] (9251) Failed to activate Index: invalid argument
Jun 6 14:16:34 localhost rfsd[9249]: [bs_index.INFO] (9251) Enqueuing 0 Index blocks for syncing
Jun 6 14:16:34 localhost rfsd[9249]: [index_syncer.INFO] (9251) Processor IndexSyncer shutting down 1 threads
Jun 6 14:16:34 localhost rfsd[9249]: [hash_stores.ERR] (9251) Failed to open block store: invalid argument
Jun 6 14:16:34 localhost rfsd[9249]: [upgrade.ERR] (9251) Failed to open hash store: invalid argument
Jun 6 14:16:34 localhost rfsd[9249]: [upgrade.ERR] (9251) Failed to initialize hash store
Jun 6 14:16:34 localhost rfsd[9249]: [megastore.ERR] (9251) Could not complete upgrade: invalid argument
Jun 6 14:16:34 localhost rfsd[9249]: [megastore.ERR] (9251) Component Initialization Failed: invalid argument
Jun 6 14:16:34 localhost rfsd[9249]: [megastore.ERR] (9251) Failed to initialize the Megastore: invalid argument
Jun 6 14:16:34 localhost rfsd[9249]: [megastore.ERR] (9251) Error in starting megastore for the volume rfsd_volume
Jun 6 14:16:34 localhost rfsd[9249]: [evict.INFO] (9251) Processor EvictProcessor shutting down 513 threads
Jun 6 14:16:34 localhost rfsd[9249]: [replicator.INFO] (9251) Shutting down replication manager thread
Jun 6 14:16:34 localhost rfsd[9249]: [replicator.INFO] (9251) Shutting down backend threads
Jun 6 14:16:34 localhost rfsd[9249]: [replicator.INFO] (9251) Shutting down replicator
Jun 6 14:16:34 localhost rfsd[9249]: [replicator.INFO] (9251) Shutting down all replication worker threads
Jun 6 14:16:34 localhost rfsd[9249]: [replicator.INFO] (9251) Processor replicator shutting down 20 threads
Jun 6 14:16:34 localhost rfsd[9249]: [replicator.INFO] (9251) Completed shutdown of replication worker threads
Jun 6 14:16:34 localhost rfsd[9249]: [replicator.INFO] (9251) Replicator shutdown complete
Jun 6 14:16:34 localhost rfsd[9249]: [replicator.INFO] (9251) ReplicationManager shutdown complete
Jun 6 14:16:34 localhost rfsd[9249]: [mutable_slab_manager.INFO] (9251) releasing partial slabs
Jun 6 14:16:34 localhost rfsd[9249]: [anchor_inserter.INFO] (9251) Processor AnchorHashInserter shutting down 1 threads
Jun 6 14:16:34 localhost rfsd[9249]: [megastore.INFO] (9251) Transaction Statistics for Transaction Manager rfsd_volume
Jun 6 14:16:34 localhost rfsd[9249]: [megastore.INFO] (9251) Log Records Per Transaction: Samples: 0 Cum. Total: 0 Min: 0 Max: 0 Mean: -nan Median: 0 Median Err: 5
Jun 6 14:16:34 localhost rfsd[9249]: [megastore.INFO] (9251) Payload Bytes Logged Per Transaction: Samples: 0 Cum. Total: 0 Min: 0 Max: 0 Mean: -nan Median: 0 Median Err: 5
Jun 6 14:16:36 localhost rfsd[9249]: [megamount.ERR] (9251) Failed to start megastore: invalid argument
Jun 6 14:16:36 localhost rfsd[9249]: [rfsd.ERR] (9251) Megamount initialization failed.
