Avamar: MCS Fails to Start after MCS Restore.

Analyze

• MC restart stops responding and fails. During MCS restart, the mcserver_data/prefs directory is clear which causes the MC service to fail to start. 

The following error is reported in the MCS.log:

>    Starting Administrator Server at: Tue Jul 21 09:56:34 PST 2020
>    <…>
>    Reload serviceMapInstall service: com.avamar.mc.st.SessionTicketService, processing time = 1873ms
>    Install service: com.avamar.mc.ras.McEbmsService, processing time = 1736ms
>    Thread com.avamar.mc.util.MCThreadPool-dbev.0 died.
>    java.lang.AssertionError: pgStatement.getConnection().getAutoCommit() should not throw
>            at org.postgresql.jdbc.BatchResultHandler.isAutoCommit(BatchResultHandler.java:105)
>            at org.postgresql.jdbc.BatchResultHandler.handleCompletion(BatchResultHandler.java:161)
>            at org.postgresql.core.ResultHandlerDelegate.handleCompletion(ResultHandlerDelegate.java:57)
>            at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:520)
>            at org.postgresql.jdbc.PgStatement.executeBatch(PgStatement.java:853)
>            at org.postgresql.jdbc.PgPreparedStatement.executeBatch(PgPreparedStatement.java:1546)
>            at com.avamar.mc.datatap.MCDataAccessObject._insertEvents(MCDataAccessObject.java:903)
>            at com.avamar.mc.datatap.MCDataAccessObject.access$1900(MCDataAccessObject.java:228)
>            at com.avamar.mc.datatap.MCDataAccessObject$EventsTableWriterRunnable.doRun(MCDataAccessObject.java:11216)
>            at com.avamar.mc.util.MCThreadPoolRunnable.run(MCThreadPoolRunnable.java:78)
>            at com.avamar.mc.util.MCThreadPool$PoolWorker.run(MCThreadPool.java:186)
>    Install service: com.avamar.mc.migration.MigrationService, processing time = 26ms
>    Start service container: processing time = 35478ms

• Further check of the MCS.log shows the following avsysreport information in the MCS.log:

>    time-09:57:15.00577 [com.avamar.mc.event.EventCEMCHandler$ConnectEMCThread#116] com.avamar.mc.util.ConnectEMC.getPartNumberRaw
>    FINE: HWPART - avsysreport stdout: [bash: /usr/local/avamar/bin/avsysreport: No such file or directory
>    === BEGIN === check.mcs (prerestore)
>    check.mcs                        passed
>    === PASS === check.mcs PASSED OVERALL (prerestore)
>    --restore modifies your Administrator Server database and preferences.
>    Do you want to proceed with the restore Y/N? [Y]: Decrypting all registered passwords….
>    see MCCipher log for details: /usr/local/avamar/var/mc/server_log/mccipher.log.0
>    Stopping the database server.
>    Database server stopped.
>    removing data dir /usr/local/avamar/var/mc/server_data
>    INFO: /usr/local/avamar/var/mc already exists
>                                                     
>    creating /usr/local/avamar/var/mc/server_data/postgres/data with permissions 0755
>    
>    Please wait....
>    time--01:57:15.55859 [avmaint]  ERROR: <0001> maint::command::login error=MSG_ERR_PSWD_INVALID connection=tcp servaddr=10.10.10.72:27000 fd=3 bufsize=60000 isclosed=0
>    ERROR: avmaint: hfscreatetime: authentication failure
>    ERROR: command "ssh -q  -x  -o GSSAPIAuthentication=no admin@10.10.10.72 '/usr/local/avamar/bin/avsysreport syserror-context id=1 errtext="kernel error: Jul 12 08:27:25 avamar zzdpn[1564]: dpnctl: ERROR: 10 errors seen in output of "[ -r /etc/profile ] && /etc/profile ; echo Y | /usr/local/avamar/bin/mcserver.sh --restore --id=root --hfsport=27000 --hfsaddr=10.10.10.72 --password=*************""'" failed, return: 256, exitcode: 1, signal: 0, dumped core: 0
>    ]
>    time--09:57:15.00577 [com.avamar.mc.event.EventCEMCHandler$ConnectEMCThread#116] com.avamar.mc.util.ConnectEMC.getPartNumberXml
>    WARNING: HWPART - Output has error, please correct the command first.
>    time--09:57:15.00577 [com.avamar.mc.event.EventCEMCHandler$ConnectEMCThread#116] com.avamar.mc.util.ConnectEMC.addEvent
>    FINE: HWPART - No part # available for CEMC msg.

• The information above is due to GSAN attempting to insert an event into Management Console database (MCDB). However, due to special characters, MCS fails to recognize the correct sentence. 

GSAN uses the following command to get the event information:

>    grep geterrros /usr/local/avamar/var/mc/server_data/mcserver.log.0

>    FINE: exec polling command: '/usr/local/avamar/bin/avmaint geterrors 0.0 --startoffset=103025166 --hfsaddr=itqavamar002 --hfsport=27000  --quiet' elapsed: 0 exit code: 0
>    FINE: exec polling command: '/usr/local/avamar/bin/avmaint geterrors 0.0 --startoffset=103057976 --hfsaddr=itqavamar002 --hfsport=27000  --quiet' elapsed: 0 exit code: 0
>    FINE: exec polling command: '/usr/local/avamar/bin/avmaint geterrors 0.0 --startoffset=103090775 --hfsaddr=itqavamar002 --hfsport=27000  --quiet' elapsed: 0 exit code: 0

• Filter the startoffset from the MCS.log and run the following command to identify which event contains the restore information:

>    grep geterrors /usr/local/avamar/var/mc/server_data/mcserver.log.0 | awk '{print $8}' > startoffset.out

>    for i in `cat startoffset.out`; do echo ====$i===;avmaint geterrors 0.0 $i --quiet | grep restore; done.

• Identify the latest offset which reports the restore command:

>    ====--startoffset=104207809====
>    message="kernel error: May  6 15:57:10 itqavamar002 zzdpn[2105]: (0.0) 2021/05/06-09:38:09.99408 {0.0} [log-messages:109]  ERROR: <0001> kernel error: May  6 08:05:37 itqavamar002 zzdpn[2160]: dpnctl: ERROR: 2 errors seen in output of "[ -r /etc/profile ] && . /etc/profile ; echo 'Y' | /usr/local/avamar/bin/mcserver.sh --restore --id='root' --hfsport='27000' --hfsaddr='172.16.2.7' --password='*************'""/>

• Run avmaint geterrors directly and get the endoffset "104240584" for this error information:

>    root@itqavamar002:/home/admin/felix/#: /usr/local/avamar/bin/avmaint geterrors 0.0 --startoffset=104207809 --hfsaddr=itqavamar002 --hfsport=27000  --quiet

>    <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
>    <eventlist
>      startoffset="104207809"
>      maxlines="0"
>      endoffset="104240584"
>      eof="false"
>      restart="false"
>      count="196"
>      dup-count="171"
>      filter-count="0">
>     ...
>        message="kernel error: May  6 15:57:10 itqavamar002 zzdpn[2105]: (0.0) 2021/05/06-09:38:07.79070 {0.0} [log-messages:109]  ERROR: &lt;0001&gt; kernel error: May  5 18:51:45 itqavamar002 zzdpn[2112]: dpnctl: ERROR: 2 errors seen in output of &quot;[ -r /etc/profile ] &amp;&amp; . /etc/profile ; echo &apos;Y&apos; | /usr/local/avamar/bin/mcserver.sh --restore --id=&apos;root&apos; --hfsport=&apos;27000&apos; --hfsaddr=&apos;172.16.2.7&apos; --password=&apos;*************&apos;&quot;"/>

In the MC application, call the shell command line:

/usr/local/avamar/bin/avsysreport syserror-context id=1 errtext="kernel error: Jul 12 08:27:25 avamar zzdpn[1564]: dpnctl: 
ERROR: 10 errors seen in output of "[ -r /etc/profile ] && . /etc/profile ; echo Y | /usr/local/avamar/bin/mcserver.sh --restore --id=root --hfsport=27000 --hfsaddr=10.10.10.72 --password=*************""

As it contains characters " and ;, one command line is split into two. The MC code should avoid that.

1. Restore MCS

>       mcserver.sh --restore

2. Start the database

>       dbmaint.sh --db=on

3. The current offset in MCDB is 104306251, update error_idx to 104240584 in MCDB

>      mcdb=# select * from public.sv_elog_cache;
>       error_key | error_idx
>      -----------+-----------
>       0.0       |    104306251

4. Start MCS

>      mcserver.sh --start