"Error encountered: ERROR: Final installdb run unsuccessful" during firmware cop installation

[Brett Hanson]

Hi all,

Just a heads up to anyone else who encounters this error when installing device firmware cop files onto CUCM.

We were upgrading the firmware on our CUCM cluster (small - consists of 1 x Publisher and 1 x Subscriber) - running 8.0.2.40000-1

I was installing:

cmterm-7936-sccp.3-3-21.cop.sgn

cmterm-7937-1-4-4-SCCP.cop.sgn

cmterm-7941_7961-sccp.9-3-1SR2-1.cop.sgn

cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn

When doing so on the publisher server - it was throwing the following error output (note that the files actually ended up on the TFTP server but devices were not picking up the new firmware):

Installation Status

File           cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn

Start Time           Thu Mar 06 19:34:24 WST 2014

Status

Error encountered: ERROR: Final installdb run unsuccessful

03/06/2014 19:33:42 file_list.sh|Starting file_list.sh|<LVL::Info>

03/06/2014 19:33:42 file_list.sh|Parse argument method=sftp|<LVL::Debug>

03/06/2014 19:33:42 file_list.sh|Parse argument source_dir=/|<LVL::Debug>

03/06/2014 19:33:42 file_list.sh|Parse argument dest_file=/var/log/install/downloaded_versions|<LVL::Debug>

03/06/2014 19:33:42 file_list.sh|Parse argument remote_host=10.133.1.240|<LVL::Debug>

03/06/2014 19:33:42 file_list.sh|Parse argument user_name=ccmadministrator|<LVL::Debug>

03/06/2014 19:33:42 file_list.sh|Calling SFTP command with metering off|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|SFTP command complete (0)|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|List file (pre-filtered):|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|(CAPTURE) RSA|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|(CAPTURE) UC|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|(CAPTURE) WIRELESS|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|(CAPTURE) asa914-k8.bin|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|(CAPTURE) cmterm-7936-sccp.3-3-21.cop.sgn|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|(CAPTURE) cmterm-7937-1-4-4-SCCP.cop.sgn|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|(CAPTURE) cmterm-7941_7961-sccp.9-3-1SR2-1.cop.sgn|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|(CAPTURE) cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn|<LVL::Debug>

03/06/2014 19:33:43 file_list.sh|/usr/local/bin/base_scripts/filter.sh file=/var/log/install/downloaded_versions|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|Parse argument file=/var/log/install/downloaded_versions|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|No patch type specified. Optional.|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|No upgrade mode specifed. Optional.|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|Current version is 8.0.2.40000-1|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|Processing token "RSA"|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|INorOUT=OUT RSA: Not a signed patch file|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|Processing token "UC"|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|INorOUT=OUT UC: Not a signed patch file|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|Processing token "WIRELESS"|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|INorOUT=OUT WIRELESS: Not a signed patch file|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|Processing token "asa914-k8.bin"|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|INorOUT=OUT asa914-k8.bin: Not a signed patch file|<LVL::Debug>

03/06/2014 19:33:43 filter.sh|Processing token "cmterm-7936-sccp.3-3-21.cop.sgn"|<LVL::Debug>

03/06/2014 19:33:44 filter.sh|INorOUT=IN cmterm-7936-sccp.3-3-21.cop.sgn: filter passed|<LVL::Debug>

03/06/2014 19:33:44 filter.sh|Processing token "cmterm-7937-1-4-4-SCCP.cop.sgn"|<LVL::Debug>

03/06/2014 19:33:44 filter.sh|INorOUT=IN cmterm-7937-1-4-4-SCCP.cop.sgn: filter passed|<LVL::Debug>

03/06/2014 19:33:44 filter.sh|Processing token "cmterm-7941_7961-sccp.9-3-1SR2-1.cop.sgn"|<LVL::Debug>

03/06/2014 19:33:44 filter.sh|INorOUT=IN cmterm-7941_7961-sccp.9-3-1SR2-1.cop.sgn: filter passed|<LVL::Debug>

03/06/2014 19:33:44 filter.sh|Processing token "cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn"|<LVL::Debug>

03/06/2014 19:33:44 filter.sh|INorOUT=IN cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn: filter passed|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|List file (post-filtered):|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) RSA:1|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) UC:1|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) WIRELESS:1|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) asa914-k8.bin:1|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) cmterm-7936-sccp.3-3-21.cop.sgn:0|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) cmterm-7937-1-4-4-SCCP.cop.sgn:0|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) cmterm-7941_7961-sccp.9-3-1SR2-1.cop.sgn:0|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn:0|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|List file (pre-structured):|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) RSA:1|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) UC:1|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) WIRELESS:1|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) asa914-k8.bin:1|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) cmterm-7936-sccp.3-3-21.cop.sgn:0|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) cmterm-7937-1-4-4-SCCP.cop.sgn:0|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) cmterm-7941_7961-sccp.9-3-1SR2-1.cop.sgn:0|<LVL::Debug>

03/06/2014 19:33:44 file_list.sh|(CAPTURE) cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn:0|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|List file (post-structured):|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE) <InstallList>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE)     <FilteredItem type="" file="RSA" result="1"/>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE)     <FilteredItem type="" file="UC" result="1"/>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE)     <FilteredItem type="" file="WIRELESS" result="1"/>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE)     <FilteredItem type="" file="asa914-k8.bin" result="1"/>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE)     <InstallItem type="copfile" secure-file="cmterm-7936-sccp.3-3-21.cop.sgn" version="" file="cmterm-7936-sccp.3-3-21.cop" reboot="no"/>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE)     <InstallItem type="copfile" secure-file="cmterm-7937-1-4-4-SCCP.cop.sgn" version="" file="cmterm-7937-1-4-4-SCCP.cop" reboot="no"/>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE)     <InstallItem type="copfile" secure-file="cmterm-7941_7961-sccp.9-3-1SR2-1.cop.sgn" version="" file="cmterm-7941_7961-sccp.9-3-1SR2-1.cop" reboot="no"/>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE)     <InstallItem type="copfile" secure-file="cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn" version="" file="cmterm-7945_7965-sccp.9-3-1SR2-1.cop" reboot="no"/>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|(CAPTURE) </InstallList>|<LVL::Debug>

03/06/2014 19:33:46 file_list.sh|success|<LVL::Info>

03/06/2014 19:33:46 file_list.sh|file_list.sh complete (rc=0)|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|Starting upgrade_validate_file.sh|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|Parse argument method=sftp|<LVL::Debug>

03/06/2014 19:34:19 upgrade_validate_file.sh|Parse argument source_dir=/|<LVL::Debug>

03/06/2014 19:34:19 upgrade_validate_file.sh|Parse argument file_name=cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn|<LVL::Debug>

03/06/2014 19:34:19 upgrade_validate_file.sh|Parse argument remote_host=10.133.1.240|<LVL::Debug>

03/06/2014 19:34:19 upgrade_validate_file.sh|Parse argument user_name=ccmadministrator|<LVL::Debug>

03/06/2014 19:34:19 upgrade_validate_file.sh|Getting patch size via sftp for cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|Size of patch file = 6018125|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|Total space needs = 12036250|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|  Free space : 126461788160|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|Space needed : 24072500|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|There is enough space on device to proceed.|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|success|<LVL::Info>

03/06/2014 19:34:19 upgrade_validate_file.sh|upgrade_validate_file.sh complete (rc=0)|<LVL::Info>

03/06/2014 19:34:19 upgrade_get_file.sh|Starting upgrade_get_file.sh|<LVL::Info>

03/06/2014 19:34:19 upgrade_get_file.sh|Parse argument method=sftp|<LVL::Debug>

03/06/2014 19:34:19 upgrade_get_file.sh|Parse argument source_dir=/|<LVL::Debug>

03/06/2014 19:34:19 upgrade_get_file.sh|Parse argument file_name=cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn|<LVL::Debug>

03/06/2014 19:34:19 upgrade_get_file.sh|Parse argument dest_dir=/common/download/|<LVL::Debug>

03/06/2014 19:34:19 upgrade_get_file.sh|Parse argument remote_host=10.133.1.240|<LVL::Debug>

03/06/2014 19:34:19 upgrade_get_file.sh|Parse argument user_name=ccmadministrator|<LVL::Debug>

03/06/2014 19:34:20 upgrade_get_file.sh|Starting SFTP of cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn|<LVL::Info>

03/06/2014 19:34:21 upgrade_get_file.sh|SFTP command complete (0)|<LVL::Info>

03/06/2014 19:34:21 upgrade_get_file.sh|Download of iso file RTMTStart|<LVL::Notice>

03/06/2014 19:34:21 upgrade_get_file.sh|Create md5 "/common/download/cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn.md5"|<LVL::Info>

03/06/2014 19:34:21 upgrade_get_file.sh|MD5(/common/download/cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn)= e3:02:d3:e1:89:ff:a1:eb:0a:71:52:03:ad:d7:e2:85|<LVL::Debug>

03/06/2014 19:34:21 upgrade_get_file.sh|Create md5 complete|<LVL::Info>

03/06/2014 19:34:21 upgrade_get_file.sh|Authenticate file "/common/download/cmterm-7945_7965-sccp.9-3-1SR2-1.cop.sgn"|<LVL::Info>

03/06/2014 19:34:21 upgrade_get_file.sh|File authentication complete|<LVL::Debug>

03/06/2014 19:34:21 upgrade_get_file.sh|Download of iso file RTMTFinish|<LVL::Notice>

03/06/2014 19:34:22 upgrade_get_file.sh|success|<LVL::Info>

03/06/2014 19:34:22 upgrade_get_file.sh|upgrade_get_file.sh complete (rc=0)|<LVL::Info>

03/06/2014 19:34:24 Terminating active side processes

03/06/2014 19:34:24 Terminating active side processes done

03/06/2014 19:34:24 Terminating inactive side processes

03/06/2014 19:34:24 Calling /usr/local/bin/base_scripts/sd_killPartitionB_PIDs.sh

/

03/06/2014 19:34:24 Terminating inactive side processes done

(13953) Thu Mar 6 19:34:30 WST 2014

install option

(13953) Thu Mar 6 19:34:30 WST 2014

Successful untarring of option /common/download//cmterm-7945_7965-sccp.9-3-1SR2-1.cop.

(13953) Thu Mar 6 19:34:36 WST 2014

Publisher: Starting installdb... /bin/su -l informix -s /bin/sh -c "source /usr/local/cm/db/dblenv.bash /usr/local/cm ; source /usr/local/cm/db/informix/local/ids.env ; nice /usr/local/cm/bin/installdb -x /usr/local/cm/db/xml/xml"

disablenotify  rc[0]

xml DSN=ccm_super /usr/local/cm/db/xml/xml

installXml  rc[1]

enablenotify  dsn[DSN=ccm_super]

enablenotify  rc[0]

installdb Failure [-x] 1

(13953) Thu Mar 6 19:34:47 WST 2014

ERROR: Final installdb run unsuccessful

I'd read in various places to perform a CLI command "run loadxml" - which we did but it produced the following output:

admin:run loadxml

This command is processor intensive, and may take a few minutes to run.

It should only be run on the publisher.

Some services may require a restart afterwards.

This is a CPU intensive command and will take a considerable amount of time to complete. Do you want to continue (y/n)?

Starting loadxml

disablenotify  dsn[DSN=ccm_super]

disablenotify  rc[0]

xml DSN=ccm_super /usr/local/cm/db/xml/xml

installXml  rc[1]

enablenotify  dsn[DSN=ccm_super]

enablenotify  rc[0]

installdb Failure [-x] 1

loadxml function complete

Failure essentially.

Note that the installation went ahead without issues on the Subscriber servers after we tried on the publisher. I believe this is due to it only copying the files to the TFTP server and not updating the database.

I also noted that the following features vanished from the CUCM Administration GUI (the menus were there but the pages came up blank):

"Enterprise Paramaters"

"Enterprise Phone Configuration"

"Service Parameters" (after selecting "server" & "service" drop down options, nothing was displayed)

Within individual "Phone Configuration" - the entire "Product Specific Configuration Layout" was missing from all devices.

I was also unable to export the 'Cisco Database Installation Service' logs from RTMT - it threw an error to the status bar at the bottom stating "Collection cancelled for node <publisher> due to the error" (and there was no error info output...joy!).

I called in TAC and Roman Kramarski assisted me via WebEx to full resolution of the issue - thanks Roman

After running "run loadxml"

We ran the following command which showed us (after much wizzing by of entries) the list of log files, the 5th or so last file in the list being the log output from the "run loadxml" output -

The command: "file list activelog /cm/trace/dbl/sdi detail date"

Our file in question happened to be called "installdb20140306-230735.log" (like I said, was about 5th from the bottom of the list)

Next we viewed the file:

"file view activelog /cm/trace/dbl/sdi/installdb20140306-230735.log"

In the file, fairly close to the top, it showed the following error message:

"23:07:35.047 |   DOMErrorReporter::fatalError *ERROR* Fatal Error at file /usr/local/cm/db/xml/xml/366X_display_instance-fxo_port_gs.xml, line 56, column 22"

This, along with the output of the run loadxml command, indicated that "/usr/local/cm/db/xml/xml/366X_display_instance-fxo_port_gs.xml" file was corrupted or incomplete.

Roman (TAC) then used the Cisco access to root in order to look at the actual file.

It was incomplete - it ended mid closure of a tag:

"<name>OutputAttenuation</n#"

(Instead of "<name>OutputAttenuation</name>" plus a whole bucketload more output.

Luckily I had a fresh install of the exact same version of CUCM just installed on in a dev environment - so Roman was able to get into that one, TFTP the file out, and then TFTP the new file in.

We moved the old corrupt file into another folder (as we renamed it initially and then ran "run loadxml" which produced the error again) - copied the new complete file into the folder - then "run loadxml" ran successfully.

admin:run loadxml

This command is processor intensive, and may take a few minutes to run.

It should only be run on the publisher.

Some services may require a restart afterwards.

This is a CPU intensive command and will take a considerable amount of time to complete. Do you want to continue (y/n)?

Starting loadxml

disablenotify  dsn[DSN=ccm_super]

disablenotify  rc[0]

xml DSN=ccm_super /usr/local/cm/db/xml/xml

installXml  rc[0]

enablenotify  dsn[DSN=ccm_super]

enablenotify  rc[0]

installdb Success[-x]

loadxml function complete

NOTE that the running of run loadxml did not take that long and didn't cause any outages to my system.

After we did this - the installations went ahead successfully.

After a restart of the TFTP service on each server - firmware upgrades went ahead successfully.

Basically - you can do the initial troubleshooting of checking logs of run loadxml and then pass that detail to Cisco TAC to get them to use root access to copy a fresh version of the file across.

Hope this helps.

[Manuel Martinez Dominguez]

Hi Thanks for the information, this help me a lot, I have the same issue but with some differences, because when I search the error on the log file, I saw

08/25/2014 06:14:49.911 installdb|   DOMErrorReporter::fatalError *ERROR* Fatal Error at file , line 0, column 0
 message: An exception occurred! Type:RuntimeException, Message:The primary document entity could not be opened. Id=/usr/local/cm/db/xml/xml/ICS77XX_MRP2XX_display_instance-bri.xml|
08/25/2014 06:14:49.911 installdb|<--DOMErrorReporter::fatalError |

When I search the file I couldn´t find it, so I think this could be because I made a booteable ISO from an upgrade from the Cisco Page, so I go to the production server version 6.1.2 and copied the file missing into my lab and run the command "run loadxml" sucessfully, after that everything works great!

Thanks in advance for your time to post this.

Regards!