AltaVault - V2 vmware esx virtual appliance (Error: error: storage optimization service not re)

[Javedk]

Hello All,

We have a customer who is experiencing issue with the AltaVault - V2 vmware esx virtual appliance (evaluation version).

Initially he had issue with the data partition which he has fixed it on his own. Now, he is facing issues with the Storage optimization service. He is getting the below error:

"error: storage optimization service not ready"

As this is an evaluation product and not licensed, we do not have a record of the serial number. Hence, we are unable to log a case and direct him to the support.

Any help in pointing us in the right direction would be appreciated.

Regards,

Javed Khan

[chriswong]

Hi,

The AltaVault storage optimization service (the one in question) may be having errors for multiple reasons. You can review the system log (for red messages) to discover what the cause of the problem is. Goto the Maintenance > Service optimization page and stop and start the service, then view the error in the Maintenance > System Log page and post that problem set of messages in a message so I can review.

Regards,

Christopher

[Chiatan]

Hello Chris,

We are also having the similar problem, please find the logs below, hope you can help us on this 🙂

Jun 5 08:28:17 localhost mgmtd[1990]: [mgmtd.WARNING]: Exit with code 1 from /opt/rbt/bin/megastore_stats_dump.py
Jun 5 08:28:17 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:28:22 localhost statsd[2681]: message repeated 4 times: [ event_pending: event has no event_base set.]
Jun 5 08:28:24 localhost mgmtd[1990]: [mgmtd.WARNING]: Exit with code 1 from /opt/rbt/bin/megastore_stats_dump.py
Jun 5 08:28:24 localhost mgmtd[1990]: [mgmtd.WARNING]: Exit with code 1 from /usr/bin/du
Jun 5 08:28:27 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:28:32 localhost mgmtd[1990]: [mgmtd.WARNING]: Exit with code 1 from /opt/rbt/bin/megastore_stats_dump.py
Jun 5 08:28:32 localhost mgmtd[1990]: [mgmtd.WARNING]: Exit with code 1 from /usr/bin/du
Jun 5 08:28:32 localhost mgmtd[1990]: [mgmtd.WARNING]: Exit with code 1 from /opt/rbt/bin/megastore_stats_dump.py
Jun 5 08:28:32 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:28:34 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:28:34 localhost mgmtd[1990]: [mgmtd.WARNING]: Exit with code 1 from /opt/rbt/bin/megastore_stats_dump.py
Jun 5 08:28:34 localhost mgmtd[1990]: [mgmtd.WARNING]: Exit with code 1 from /usr/bin/du
Jun 5 08:28:37 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:28:40 localhost hald[2688]: [hald.INFO]: Support query handler called
Jun 5 08:28:40 localhost webasd[19195]: [web.INFO]: web: User admin viewing SMB page.
Jun 5 08:28:40 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:28:42 localhost statsd[2681]: message repeated 2 times: [ event_pending: event has no event_base set.]
Jun 5 08:28:44 localhost hald[2688]: [hald.INFO]: Support query handler called
Jun 5 08:28:44 localhost webasd[19195]: [web.INFO]: web: User admin viewing Storage Optimization Service page.
Jun 5 08:28:45 localhost mgmtd[1990]: [mgmtd.NOTICE]: Starting optimization service...
Jun 5 08:28:45 localhost pm[1976]: [pm.INFO]: Restarting process rfsd from STOPPED state
Jun 5 08:28:45 localhost webasd[19195]: [web.INFO]: web: Received return code 0, return message 'Starting optimization service...\n' from gclSession pygs_handle_any_response
Jun 5 08:28:45 localhost mgmtd[1990]: [mgmtd.INFO]: EVENT: /pm/events/proc/state_changed
Jun 5 08:28:45 localhost pm[4990]: [pm.INFO]: Process environment TCMALLOC_LARGE_ALLOC_REPORT_THRESHOLD=274877906944
Jun 5 08:28:45 localhost pm[4990]: [pm.INFO]: Process environment RBT_DEBUG_MODE=14
Jun 5 08:28:45 localhost pm[1976]: event_pending: event has no event_base set.
Jun 5 08:28:45 localhost pm[1976]: [pm.NOTICE]: Launched rfsd with pid 4990
Jun 5 08:28:45 localhost mgmtd[1990]: [mgmtd.INFO]: EVENT: /pm/events/proc/state_changed
Jun 5 08:28:45 localhost mgmtd[1990]: [mgmtd.INFO]: EVENT: /pm/events/proc/restart
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) RfsContext Start
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) OpenSSL 1.0.2k-fips 26 Jan 2017
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) built on: reproducible build, date unspecified
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) platform: debian-amd64
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) compiler: gcc -I. -I.. -I../include -fPIC -DOPENSSL_PIC -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -I/work/jenkins-cagbuild/workspace/CI-CLP-dev/openssl-fips-canister/export/usr/lib/openssl-fips-canister/include/ -m64 -
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) DL_ENDIAN -g -O2 -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -Wl,-z,relro -Wa,--noexecstack -Wall -DMD32_REG_T=int -DOPENSSL_IA32_SSE2 -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_MONT5 -DOPENSSL
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) _BN_ASM_GF2m -I/work/jenkins-cagbuild/workspace/CI-CLP-dev/openssl-fips-canister/export/usr/lib/openssl-fips-canister/include -DRC4_ASM -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DMD5_ASM -DAES_ASM -DVPAES_ASM -DBSAES_ASM -DWHIRLPOOL_ASM -D
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) GHASH_ASM -DECP_NISTZ256_ASM
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) OPENSSLDIR: "/usr/lib/ssl"
Jun 5 08:28:45 localhost rfsd[4990]: [ctl.INFO] (4990) /etc/rfsd.conf set curl.timeout=10800
Jun 5 08:28:45 localhost rfsd[4990]: [ctl.INFO] (4990) /etc/rfsd.conf set encoder.labels_per_slab_cutoff=0
Jun 5 08:28:45 localhost rfsd[4990]: [ctl.INFO] (4990) /etc/rfsd.conf set encoder.max_load_anchor_slabs=12
Jun 5 08:28:45 localhost rfsd[4990]: [ctl.INFO] (4990) /etc/rfsd.conf set encoder.max_pinned_anchor_slabs=12
Jun 5 08:28:45 localhost rfsd[4990]: [ctl.INFO] (4990) /etc/rfsd.conf set encoder.max_slabs_for_ref=24
Jun 5 08:28:45 localhost rfsd[4990]: [ctl.INFO] (4990) /etc/rfsd.conf set labelmap.partial_reclaim_enabled=false
Jun 5 08:28:45 localhost rfsd[4990]: [vault.INFO] (4990) access_key not configured yet
Jun 5 08:28:45 localhost rfsd[4990]: [vault.INFO] (4990) secret_key not configured yet
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) rbt_internal=/data
Jun 5 08:28:45 localhost statsd[2681]: [statsd.INFO]: session 16: accepted client 'rfsd-4990' for authenticated user 'admin' (uid 0, gid 0) authorization key 'admin', interactive 'false'
Jun 5 08:28:45 localhost mgmtd[1990]: [mgmtd.INFO]: session 53: accepted client 'rfsd-4990' for authenticated user 'admin' (uid 0, gid 0) authorization key 'admin', interactive 'false'
Jun 5 08:28:45 localhost rfsd[4990]: [shelf_config.INFO] (4990) Adding shelf: path=/data device=
Jun 5 08:28:45 localhost rfsd[4990]: [shelf_config.INFO] (4990) Adding shelf evicter config: num_entries= 4194304 reserve=2097152 reserve_incr=500000 max_secs_between_syncs=1800 max_unsynced_changes=1000000
Jun 5 08:28:45 localhost rfsd[4990]: [mgmt_gcl_session.INFO] (4992) connected to mgmtd
Jun 5 08:28:45 localhost rfsd[4990]: [mgmt_gcl_session.INFO] (4993) connected to statsd
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) Continuing RfsContext initialization
Jun 5 08:28:45 localhost rfsd[4990]: [backend/storage/s3.ERR] (4990) access key not provided.
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.ERR] (4990) Cloud provider credentials incomplete: access key not provided.
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.ERR] (4990) rfsd configuration file does not have all required parameters set
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) failed to start rfsd
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) tearing down RfsContext
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) Megamount not running
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.INFO] (4990) Shutting down backend threads
Jun 5 08:28:45 localhost rfsd[4990]: [megastore.WARN] (4990) Attempt to shut down uninitialized Megastore
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.NOTICE] (4990) rfsd shut down cleanly.
Jun 5 08:28:46 localhost rfsd[4990]: [ctl.INFO] (4991) ctl thread exiting
Jun 5 08:28:46 localhost rfsd[4990]: [mgmt_connection.INFO] (4990) Deinitializaing mgmt connections
Jun 5 08:28:46 localhost rfsd[4990]: [mgmt_gcl_session.INFO] (4992) disconnected from mgmtd
Jun 5 08:28:46 localhost rfsd[4990]: [mgmt_gcl_session.INFO] (4993) disconnected from statsd
Jun 5 08:28:46 localhost statsd[2681]: [statsd.NOTICE]: statsd/provider handle_session_close 16
Jun 5 08:28:46 localhost pm[1976]: [pm.NOTICE]: Process rfsd (pid 4990) exited with code 255
Jun 5 08:28:46 localhost mgmtd[1990]: [mgmtd.INFO]: EVENT: /pm/events/proc/exited
Jun 5 08:28:46 localhost pm[1976]: [pm.INFO]: Forking then execing binary "/bin/bash" with argv "/bin/bash /sbin/afail.sh -n rfsd -b /opt/rbt/bin/rfsd -p 4990 -u \"1s\" -x 255".
Jun 5 08:28:46 localhost pm[4994]: [pm.INFO]: Process environment USER=admin
Jun 5 08:28:46 localhost mgmtd[1990]: [mgmtd.INFO]: EVENT: /pm/events/proc/state_changed
Jun 5 08:28:46 localhost mgmtd[1990]: [mgmtd.INFO]: Process exit: rfsd
Jun 5 08:28:46 localhost mgmtd[1990]: [mgmtd.INFO]: Unexpected exit of process rfsd.
Jun 5 08:28:46 localhost mgmtd[1990]: [mgmtd.INFO]: EVENT: /pm/events/failure/unexpected_exit
Jun 5 08:28:46 localhost mgmtd[1990]: [mgmtd.INFO]: Forking then execing binary "/bin/systemctl" with argv "/bin/systemctl stop nfs-kernel-server".
Jun 5 08:28:46 localhost pm[1976]: [pm.INFO]: afail.sh (pid 4994) exited with code 0
Jun 5 08:28:46 localhost systemd[1]: Stopped LSB: Kernel NFS server support.
Jun 5 08:28:46 localhost mgmtd[1990]: [mgmtd.INFO]: Forking then execing binary "/opt/rbt/bin/collect-stats" with argv "/opt/rbt/bin/collect-stats stop".
Jun 5 08:28:46 localhost mgmtd[1990]: [mgmtd.ERR]: Failed exit with signal 15 (SIGTERM) from /opt/rbt/bin/collect-stats
Jun 5 08:28:47 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:29:00 localhost statsd[2681]: message repeated 5 times: [ event_pending: event has no event_base set.]
Jun 5 08:29:01 localhost CRON[5089]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:29:01 localhost CRON[5089]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:29:01 localhost CRON[5089]: pam_unix(cron:session): session closed for user root
Jun 5 08:29:01 localhost CRON[5089]: pam_unix(cron:session): session closed for user root
Jun 5 08:29:02 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:30:00 localhost statsd[2681]: message repeated 21 times: [ event_pending: event has no event_base set.]
Jun 5 08:30:01 localhost CRON[5603]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:30:01 localhost CRON[5602]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:30:01 localhost CRON[5603]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:30:01 localhost CRON[5602]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:30:01 localhost CRON[5603]: pam_unix(cron:session): session closed for user root
Jun 5 08:31:01 localhost CRON[6138]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:31:01 localhost CRON[6138]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:31:01 localhost CRON[6138]: pam_unix(cron:session): session closed for user root
Jun 5 08:31:01 localhost CRON[6138]: pam_unix(cron:session): session closed for user root
Jun 5 08:31:02 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:31:07 localhost statsd[2681]: message repeated 2 times: [ event_pending: event has no event_base set.]
Jun 5 08:31:10 localhost hald[2688]: [hald.INFO]: Support query handler called
Jun 5 08:31:10 localhost webasd[19195]: [web.INFO]: web: User admin viewing System Logs page.
Jun 5 08:31:12 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:31:20 localhost statsd[2681]: message repeated 4 times: [ event_pending: event has no event_base set.]
Jun 5 08:31:21 localhost hald[2688]: [hald.INFO]: Support query handler called
Jun 5 08:31:21 localhost webasd[19195]: [web.INFO]: web: User admin viewing System Logs page.
Jun 5 08:31:22 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:32:00 localhost statsd[2681]: message repeated 13 times: [ event_pending: event has no event_base set.]
Jun 5 08:32:01 localhost CRON[6501]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:32:01 localhost CRON[6501]: pam_unix(cron:session): session opened for user root by (uid=0)
Jun 5 08:32:01 localhost CRON[6501]: pam_unix(cron:session): session closed for user root
Jun 5 08:32:01 localhost CRON[6501]: pam_unix(cron:session): session closed for user root
Jun 5 08:32:02 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:32:20 localhost statsd[2681]: message repeated 7 times: [ event_pending: event has no event_base set.]
Jun 5 08:32:21 localhost hald[2688]: [hald.INFO]: Support query handler called
Jun 5 08:32:21 localhost webasd[19195]: [web.INFO]: web: User admin viewing System Logs page.
Jun 5 08:32:22 localhost statsd[2681]: event_pending: event has no event_base set.
Jun 5 08:32:34 localhost statsd[2681]: message repeated 3 times: [ event_pending: event has no event_base set.]
Jun 5 08:32:34 localhost hald[2688]: [hald.INFO]: Support query handler called
Jun 5 08:32:34 localhost webasd[19195]: [web.INFO]: web: User admin viewing System Logs page.
Jun 5 08:32:35 localhost hald[2688]: [hald.INFO]: Support query handler called
Jun 5 08:32:35 localhost webasd[19195]: [web.INFO]: web: User admin viewing System Logs page.

Thanks

Chaitan

[ekashpureff]

Chiatan -

This part of the logs caught my eye:

Jun 5 08:28:45 localhost rfsd[4990]: [backend/storage/s3.ERR] (4990) access key not provided.
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.ERR] (4990) Cloud provider credentials incomplete: access key not provided.
Jun 5 08:28:45 localhost rfsd[4990]: [rfsd.ERR] (4990) rfsd configuration file does not have all required parameters set

That would cause you problems ...

I hope this response has been helpful to you.

At your service,

Eugene E. Kashpureff
eugene.kashpureff@acsacs.com
Senior Systems Architect / NetApp Certified Instructor
http://www.linkedin.com/in/eugenekashpureff

(P.S. I appreciate points for helpful or correct answers.)

[Chiatan]

Thanks for the response, is it right to understand, altavault need to access the cloud, before it starts the services ?

[ekashpureff]

Chiatan -

Apparently.

I ran through the system settings and cloud settings in the Wizard Dashboard right after installing my AVA-v2 and have had no issues.

I think Amazon will even give you a free S3 bucket if you're a new AWS user.

See the S3 getting started web page:

http://docs.aws.amazon.com/AmazonS3/latest/gsg/GetStartedWithS3.html

I hope this response has been helpful to you.

At your service,

Eugene E. Kashpureff, Sr.
Independent NetApp Consultant http://www.linkedin.com/in/eugenekashpureff
Senior NetApp Instructor, FastLane US http://www.fastlaneus.com/
(P.S. I appreciate 'kudos' on any helpful posts.)

[chriswong]

Hi,

The AltaVault service will not start without connectivity to a cloud. This is required of the solution.

The easiest way to ensure the requirements are set up for this is to use the Configure > Setup Wizard > Cloud Settings wizard and ensure you provide cloud credentials and create an encryption key. A successful run of the wizard will yield the result 'Cloud Connection Check Successful' message. 

You can watch this youtube video for further details about the setup process.

https://www.youtube.com/watch?v=ZbLPRJK0_ig&index=3&list=PLdXI3bZJEw7n7OC-zMBaWb4PTIyctosn5&t=2s

Regards,

Christopher

[netappmagic]

Hi Chris, I have similar issue, service seems running, but "status not ready". I am trying to set up a vAppliance and in dr-test mode. Following what you suggested, I got the follownig logs/errors as below. Please advice what I should do? Thanks!

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [mgmt/statsd.INFO] (10040) connected to statsd

Jun 11 04:35:19 avltappliance01 mgmtd[3596]: [mgmtd.INFO]: session 79: accepted client 'rfsd-10036' for authenticated user 'admin' (uid 0, gid 0) authorization key 'admin', interactive 'false'

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [mgmt/mgmtd.INFO] (10039) connected to mgmtd

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [replicator.ERR] (10038) Cannot be started in restore mode when the remote bucket does not have rbt_oids.dat

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [replicator.ERR] (10038) test_cloud failed in restore mode:no such file/directory

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [rfsd.ERR] (10038) Cloud test failed: no such file/directory

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [rfsd.ERR] (10038) Cloud test failed

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [rfsd.INFO] (10036) tearing down RfsContext

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [rfsd.INFO] (10036) Megamount not running

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [rfsd.INFO] (10036) Shutting down backend threads

Jun 11 04:35:19 avltappliance01 rfsd[10036]: [mgmt/mgmtd.NOTICE] (10036) rfsd sent event to mgmtd: /rbt/rfsd/events/notready

Jun 11 04:35:19 avltappliance01 mgmtd[3596]: [mgmtd.INFO]: EVENT: /rbt/rfsd/events/notready

Jun 11 04:35:19 avltappliance01 mgmtd[3596]: [mgmtd.INFO]: in rfsd_notup

Jun 11 04:35:19 avltappliance01 mgmtd[3596]: [mgmtd.ERR]: Error no message binding from rfsd.

Jun 11 04:35:20 avltappliance01 statsd[4075]: event_pending: event has no event_base set.

Jun 11 04:35:32 statsd[4075]: last message repeated 4 times

Jun 11 04:35:32 avltappliance01 hald[4085]: [hald.INFO]: Support query handler called

Jun 11 04:35:32 avltappliance01 webasd[4091]: [web.INFO]: web: User admin viewing System Logs page.

[chriswong]

Hi,

An AltaVault appliance must be configured to the cloud and have previously backed up data to that cloud before you can perform a test with a AVA-v in DR-test mode. If you follow the Administration guide, chapter 14 that explains how to use DR-test mode for testing recoveries of data from the cloud.

If you're using the same appliance as the original appliance for DR-test activity, then you'll need to clear the local cache first ('datastore format local' command after you stop the optimization service, and before you issue the 'replication recovery dr-test' command). If you are using a new appliance and not the original (i.e. simulating the outage of the original site), then you'll need to ensure that the instructions in ch14 are used to import the configuration and enable the appliance in dr-test mode.

Regards,

Christopher

[Chiatan]

Hello Chris,

One more issue, we are having difficulty in connecting Altavault to Snapcentre, we are getting error API server is not configured.

 Failed - 
Host: API server is not configured

Thanks

Chaitan