Cisco 8831 not registering

[Ryan Espedido]

Hi,

We have a Cisco 8831 running on sip8831.10-3-1SR3-5 firmware. After unpluging LAN connection (phone is powered via PoE) and rebooting, it will not register to CUCM anymore. We need to reset security setting again for the IP phone to register again to CUCM.

CUCM is 11.5.1.13902-2 with latest device pack 11.5.1.14604-1

Has anyone experience this and what was your fix? or is this a known bug?

Ryan

[Rolando Valenzuela]

This sound about right?

https://bst.cloudapps.cisco.com/bugsearch/bug/CSCuj43533/?referring_site=bugquickviewredir

[pkinane]

Doesn't seem right to me.

1. They are on a higher version of firmware than the fixed version of code for CSCuj43533
2. CSCuj43533 states AC power as a part of the conditions but in this scenario they are using POE
3. The workaround in CSCuj43533 is to unplug the AC power whereas the workaround for this post is to reset the security settings.
4. Did you read the bug?

[pkinane]

Please do the following:

1. Span the switchport in order to get a pcap
2. Reproduce the issue
3. Collect ALL the phone status messages
4. Collect ALL the phone console logs
5. Save the pcap

Send over the data from points 3/4/5

[Ryan Espedido]

Hi pkinane,

I uploaded requested logs to:

https://drive.google.com/drive/folders/1w0kFHLhUUsjw9QAlwa5mM_svNh24C3pd

[pkinane]

.

[pkinane]

Please send me the output of the command below. Run the command on the CUCM publisher. Thank you.

run sql select paramname,paramvalue from processconfig where paramname='ClusterSecurityMode'

I'm 99% sure you are impacted by CSCva82202; however, I want to confirm your cluster's mode before moving forward.

I read about 10 cases where this bug was identified as the culprit for 8831 phones not registering. Some were resetting the security settings as a workaround to get the phone to register. I found these cases by looking into the messages I saw in the phone console logs.

They removed the g3-tones.xml.sgn then installed ciscocm.tftp_tzupdate_version_v1.0.cop.sgn to make sure the issue doesn't resurface.

If you are on a fixed version of CUCM for CSCva82202, you can still be impacted by the bug due to old files remaining on the system.

[Ryan Espedido]

Hi pkinane,

Thank you for the feedback. I will get the details you need on Monday. If it helps, the CUCM cluster is in non-secure mode.

If I am affected, is my next action item is to:

1. remove g3-tones.xml.sgn

2. install ciscocm.tftp_tzupdate_version_v1.0.cop.sgn

Regards,

Ryan

[pkinane]

Ryan,

Thank you for the information. The purpose of the sql command is to see if you are in mixed mode or not and it seems you are not based on your statement.

The steps below would be the appropriate action plan for this issue. Please reply back and let us know how it goes.

1. download g3-tones.xml.sgn from the primary TFTP server as a backup
2. remove g3-tones.xml.sgn from the primary tftp server for the impacted phone
   
3. restart the TFTP service for the primary TFTP
4. try to reproduce the issue
5. If the issue is not reproduced, delete g3-tones.xml.sgn from any subsequent TFTP servers then restart the TFTP service on those servers
6. install ciscocm.tftp_tzupdate_version_v1.0.cop.sgn on all TFTP servers to prevent the issue from returning
   

[pkinane]

Any update, @Ryan Espedido?

[Ryan Espedido]

Hi pkinane,

I removed g3-tones.xml.sgn and restarted TFTP server. Afterwards, recreated the issue by unplugging patch cord. The IP phone successfully registered after reboot and issue was not recreated, hopefully, solved. I will now install tzupdate and provide feedback again.

Regards,

Ryan

[Ryan Espedido]

It seems that cop file is not compatible with existing CUCM version. See logs below:

01/09/2018 13:07:48 file_list.sh|Starting file_list.sh|<LVL::Info>
01/09/2018 13:07:48 file_list.sh|Parse argument method=remote_sftp|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|Parse argument source_dir=/|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|Parse argument dest_file=/var/log/install/downloaded_versions|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|Parse argument remote_host=10.140.64.13|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|Parse argument user_name=cisco|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|is_upgrade_lock_available: Upgrade lock is available.|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|status in upgrade status.xml upgrade.stage.checksumming|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|acquire_upgrade_lock: Lock is free, creating lock (pid: 12827)|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|clear_upgrade_status: Status file removed|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|Parse argument fromVersion=11.5.1.13902-2|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|_set_upgrade_status_attribute: fromVersion set to 11.5.1.13902-2|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|Parse argument status=upgrade.stage.determining.files|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|_set_upgrade_status_attribute: status set to upgrade.stage.determining.files|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|Process remote SFTP request|<LVL::Info>
01/09/2018 13:07:49 file_list.sh|Calling SFTP command with metering off|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|SFTP command complete (0)|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|List file (pre-filtered):|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|(CAPTURE) ciscocm.tftp_tzupdate_version_v1.0.cop.sgn|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|(CAPTURE) cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop.sgn|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|(CAPTURE) cmterm-devicepack11.5.1.14064-1.cop.sgn|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|/opt/cisco/install/bin/filter file=/var/log/install/downloaded_versions|<LVL::Debug>
01/09/2018 13:07:49 filter|Parse argument file=/var/log/install/downloaded_versions|<LVL::Debug>
01/09/2018 13:07:49 filter|No patch type specified. Optional.|<LVL::Debug>
01/09/2018 13:07:49 filter|No upgrade mode specifed. Optional.|<LVL::Debug>
01/09/2018 13:07:53 filter|Processing filter candidate names|<LVL::Debug>
01/09/2018 13:07:53 filter|Process "ciscocm.tftp_tzupdate_version_v1.0.cop.sgn"|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (plm..*.cop)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (plm..*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-.*\.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-.*\.cop\.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (uc-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (uc-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (uc-friendly-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (uc-friendly-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (ciscocm..*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (ciscocm..*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter|INorOUT=IN ciscocm.tftp_tzupdate_version_v1.0.cop.sgn: Filter passed.|<LVL::Debug>
01/09/2018 13:07:54 filter|Process "cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop.sgn"|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (plm..*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (plm..*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-.*\.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-.*\.cop\.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter|INorOUT=IN cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop.sgn: Filter passed.|<LVL::Debug>
01/09/2018 13:07:54 filter|Process "cmterm-devicepack11.5.1.14064-1.cop.sgn"|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (plm..*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (plm..*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop.sgn)|<LVL::Debug>

01/09/2018 13:07:54 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter|INorOUT=IN cmterm-devicepack11.5.1.14064-1.cop.sgn: Filter passed.|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|List file (post-filtered):|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <?xml version="1.0" encoding="UTF-8"?>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <InstallList>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <InstallItem type="cop" secure-file="ciscocm.tftp_tzupdate_version_v1.0.cop.sgn" version="0.0.0.0-0" file="ciscocm.tftp_tzupdate_version_v1.0.cop" reboot="no" signed="yes" unrestricted="no"/>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <InstallItem type="cop" secure-file="cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop.sgn" version="0.0.0.0-0" file="cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop" reboot="no" signed="yes" unrestricted="no"/>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <InstallItem type="cop" secure-file="cmterm-devicepack11.5.1.14064-1.cop.sgn" version="11.5.1.14064-1" file="cmterm-devicepack11.5.1.14064-1.cop" reboot="no" signed="yes" unrestricted="no"/>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) </InstallList>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|success|<LVL::Info>
01/09/2018 13:07:54 file_list.sh|file_list.sh complete (rc=0)|<LVL::Info>
01/09/2018 13:07:54 file_list.sh|is_upgrade_lock_available: Upgrade lock is not available.|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|is_upgrade_in_progress: Already locked by this process (pid: 12827).|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|release_upgrade_lock: Releasing lock (pid: 12827)|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Starting upgrade_validate_file.sh|<LVL::Info>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument method=remote_sftp|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument source_dir=/|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument file_name=ciscocm.tftp_tzupdate_version_v1.0.cop.sgn|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument remote_host=10.140.64.13|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument user_name=cisco|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument file_type=cop|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument file_signed=yes|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|is_upgrade_lock_available: Upgrade lock is available.|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|status in upgrade status.xml upgrade.stage.determining.files|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|acquire_upgrade_lock: Lock is free, creating lock (pid: 27020)|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|clear_upgrade_status: Status file removed|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument status=upgrade.stage.validating|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|_set_upgrade_status_attribute: status set to upgrade.stage.validating|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Process remote SFTP request|<LVL::Info>
01/09/2018 13:08:12 upgrade_validate_file.sh|Get //ciscocm.tftp_tzupdate_version_v1.0.cop.sgn size via sftp|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|Size of file obtained from sftp is 43702095|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|Total space needed is 87404190|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|Check free space|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|(CAPTURE) Free space: 10427916288, Needed space: 87404190|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|There is enough space on device to proceed.|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|Remote SFTP request complete (0)|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|success|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|upgrade_validate_file.sh complete (rc=0)|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|Parse argument status=upgrade.stage.validated|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|_set_upgrade_status_attribute: status set to upgrade.stage.validated|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|is_upgrade_lock_available: Upgrade lock is not available.|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|is_upgrade_in_progress: Already locked by this process (pid: 27020).|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|release_upgrade_lock: Releasing lock (pid: 27020)|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|Unmount DVD|<LVL::Info>
01/09/2018 13:08:15 upgrade_get_file.sh|Starting upgrade_get_file.sh|<LVL::Info>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument method=remote_sftp|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument source_dir=/|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument file_name=ciscocm.tftp_tzupdate_version_v1.0.cop.sgn|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument dest_dir=/common/download/|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument remote_host=10.140.64.13|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument user_name=cisco|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument version=0.0.0.0-0|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument file_type=cop|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument file_signed=yes|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|is_upgrade_lock_available: Upgrade lock is available.|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|status in upgrade status.xml upgrade.stage.validated|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|acquire_upgrade_lock: Lock is free, creating lock (pid: 30878)|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument toVersion=0.0.0.0-0|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|_set_upgrade_status_attribute: toVersion set to 0.0.0.0-0|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument status=upgrade.stage.downloading|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|_set_upgrade_status_attribute: status set to upgrade.stage.downloading|<LVL::Debug>
01/09/2018 13:08:16 upgrade_get_file.sh|Process remote SFTP request|<LVL::Info>
01/09/2018 13:08:16 upgrade_get_file.sh|source_dir=/, dest_file=/common/download//ciscocm.tftp_tzupdate_version_v1.0.cop.sgn, file_name=ciscocm.tftp_tzupdate_version_v1.0.cop.sgn|<LVL::Debug>
01/09/2018 13:08:16 upgrade_get_file.sh|Starting SFTP|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|SFTP request complete|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|Download of iso file RTMTStart|<LVL::Notice>
01/09/2018 13:08:36 upgrade_get_file.sh|Parse argument status=upgrade.stage.checksumming|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|_set_upgrade_status_attribute: status set to upgrade.stage.checksumming|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|Create md5 "/common/download/ciscocm.tftp_tzupdate_version_v1.0.cop.sgn.md5"|<LVL::Info>
01/09/2018 13:08:36 upgrade_get_file.sh|MD5(/common/download/ciscocm.tftp_tzupdate_version_v1.0.cop.sgn)= a2:0d:9f:07:ce:85:04:07:85:e3:23:ed:29:17:36:66|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|Create md5 complete|<LVL::Info>
01/09/2018 13:08:36 upgrade_get_file.sh|Authenticate file "/common/download/ciscocm.tftp_tzupdate_version_v1.0.cop.sgn"|<LVL::Info>
01/09/2018 13:08:38 upgrade_get_file.sh|File authentication complete|<LVL::Debug>
01/09/2018 13:08:38 upgrade_get_file.sh|Download of iso file RTMTFinish|<LVL::Notice>
01/09/2018 13:08:38 upgrade_get_file.sh|Process preflight|<LVL::Info>
01/09/2018 13:08:38 upgrade_get_file.sh|Skipping preflight since file type is COP|<LVL::Debug>
01/09/2018 13:08:39 upgrade_get_file.sh|success|<LVL::Info>
01/09/2018 13:08:39 upgrade_get_file.sh|upgrade_get_file.sh complete (rc=0)|<LVL::Info>
01/09/2018 13:08:39 upgrade_get_file.sh|is_upgrade_lock_available: Upgrade lock is not available.|<LVL::Debug>
01/09/2018 13:08:39 upgrade_get_file.sh|is_upgrade_in_progress: Already locked by this process (pid: 30878).|<LVL::Debug>
01/09/2018 13:08:39 upgrade_get_file.sh|release_upgrade_lock: Releasing lock (pid: 30878)|<LVL::Debug>

01/09/2018 13:09:19 sd_cancelInstall.sh|Pre-upgrade cancel/clean-up initiated
01/09/2018 13:09:19 sd_cancelInstall.sh|Canceling active side processes
01/09/2018 13:09:19 sd_cancelInstall.sh|Canceling active side processes done
01/09/2018 13:09:19 sd_cancelInstall.sh|Canceling inactive side processes
01/09/2018 13:09:19 sd_cancelInstall.sh|Skipping IDS shared memory clean up since this is a COP
01/09/2018 13:09:20 sd_cancelInstall.sh|Canceling inactive side processes done

[18/01/09_13:09:27] locale_install.sh: Successful untarring of /common/download//ciscocm.tftp_tzupdate_version_v1.0.cop
01/09/2018 13:09:27 Current active version is 11.5.1.13902-2.i386
01/09/2018 13:09:27 major=11
01/09/2018 13:09:27 minor=5
01/09/2018 13:09:27 maint=1
01/09/2018 13:09:27 build=13902-2
01/09/2018 13:09:27 active version=11.5.1.13902-2
01/09/2018 13:09:27 Cop version incompatible, exit
[18/01/09_13:09:27] locale_install.sh: ERROR: Copstart script of /common/download//ciscocm.tftp_tzupdate_version_v1.0.cop failed

01/09/2018 13:07:48 file_list.sh|Starting file_list.sh|<LVL::Info>
01/09/2018 13:07:48 file_list.sh|Parse argument method=remote_sftp|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|Parse argument source_dir=/|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|Parse argument dest_file=/var/log/install/downloaded_versions|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|Parse argument remote_host=10.140.64.13|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|Parse argument user_name=cisco|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|is_upgrade_lock_available: Upgrade lock is available.|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|status in upgrade status.xml upgrade.stage.checksumming|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|acquire_upgrade_lock: Lock is free, creating lock (pid: 12827)|<LVL::Debug>
01/09/2018 13:07:48 file_list.sh|clear_upgrade_status: Status file removed|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|Parse argument fromVersion=11.5.1.13902-2|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|_set_upgrade_status_attribute: fromVersion set to 11.5.1.13902-2|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|Parse argument status=upgrade.stage.determining.files|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|_set_upgrade_status_attribute: status set to upgrade.stage.determining.files|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|Process remote SFTP request|<LVL::Info>
01/09/2018 13:07:49 file_list.sh|Calling SFTP command with metering off|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|SFTP command complete (0)|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|List file (pre-filtered):|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|(CAPTURE) ciscocm.tftp_tzupdate_version_v1.0.cop.sgn|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|(CAPTURE) cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop.sgn|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|(CAPTURE) cmterm-devicepack11.5.1.14064-1.cop.sgn|<LVL::Debug>
01/09/2018 13:07:49 file_list.sh|/opt/cisco/install/bin/filter file=/var/log/install/downloaded_versions|<LVL::Debug>
01/09/2018 13:07:49 filter|Parse argument file=/var/log/install/downloaded_versions|<LVL::Debug>
01/09/2018 13:07:49 filter|No patch type specified. Optional.|<LVL::Debug>
01/09/2018 13:07:49 filter|No upgrade mode specifed. Optional.|<LVL::Debug>
01/09/2018 13:07:53 filter|Processing filter candidate names|<LVL::Debug>
01/09/2018 13:07:53 filter|Process "ciscocm.tftp_tzupdate_version_v1.0.cop.sgn"|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (plm..*.cop)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (plm..*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:53 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-.*\.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-.*\.cop\.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (uc-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (uc-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (uc-friendly-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (uc-friendly-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (ciscocm..*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (ciscocm..*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter|INorOUT=IN ciscocm.tftp_tzupdate_version_v1.0.cop.sgn: Filter passed.|<LVL::Debug>
01/09/2018 13:07:54 filter|Process "cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop.sgn"|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (plm..*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (plm..*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-.*\.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-.*\.cop\.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter|INorOUT=IN cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop.sgn: Filter passed.|<LVL::Debug>
01/09/2018 13:07:54 filter|Process "cmterm-devicepack11.5.1.14064-1.cop.sgn"|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (plm..*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (plm..*.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against patch pattern (UCSInstall_UCOS_UNRST_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against es pattern (UCSInstall_UCOS_UNRST_ES[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against su pattern (UCSInstall_UCOS_UNRST_SU[0-9]*_[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.sgn.iso)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (dp-ffr.[1-9]-[0-9]-[0-9]+.*.cop.sgn)|<LVL::Debug>

01/09/2018 13:07:54 filter| Match against cop pattern (cm-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (po-locale-.*_.*-[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop)|<LVL::Debug>
01/09/2018 13:07:54 filter| Match against cop pattern (cmterm-devicepack[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+-[0-9]+.cop.sgn)|<LVL::Debug>
01/09/2018 13:07:54 filter|INorOUT=IN cmterm-devicepack11.5.1.14064-1.cop.sgn: Filter passed.|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|List file (post-filtered):|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <?xml version="1.0" encoding="UTF-8"?>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <InstallList>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <InstallItem type="cop" secure-file="ciscocm.tftp_tzupdate_version_v1.0.cop.sgn" version="0.0.0.0-0" file="ciscocm.tftp_tzupdate_version_v1.0.cop" reboot="no" signed="yes" unrestricted="no"/>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <InstallItem type="cop" secure-file="cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop.sgn" version="0.0.0.0-0" file="cmterm-8831-sip.10-3-1SR3-5-EU.k3.cop" reboot="no" signed="yes" unrestricted="no"/>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) <InstallItem type="cop" secure-file="cmterm-devicepack11.5.1.14064-1.cop.sgn" version="11.5.1.14064-1" file="cmterm-devicepack11.5.1.14064-1.cop" reboot="no" signed="yes" unrestricted="no"/>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|(CAPTURE) </InstallList>|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|success|<LVL::Info>
01/09/2018 13:07:54 file_list.sh|file_list.sh complete (rc=0)|<LVL::Info>
01/09/2018 13:07:54 file_list.sh|is_upgrade_lock_available: Upgrade lock is not available.|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|is_upgrade_in_progress: Already locked by this process (pid: 12827).|<LVL::Debug>
01/09/2018 13:07:54 file_list.sh|release_upgrade_lock: Releasing lock (pid: 12827)|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Starting upgrade_validate_file.sh|<LVL::Info>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument method=remote_sftp|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument source_dir=/|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument file_name=ciscocm.tftp_tzupdate_version_v1.0.cop.sgn|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument remote_host=10.140.64.13|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument user_name=cisco|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument file_type=cop|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument file_signed=yes|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|is_upgrade_lock_available: Upgrade lock is available.|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|status in upgrade status.xml upgrade.stage.determining.files|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|acquire_upgrade_lock: Lock is free, creating lock (pid: 27020)|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|clear_upgrade_status: Status file removed|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Parse argument status=upgrade.stage.validating|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|_set_upgrade_status_attribute: status set to upgrade.stage.validating|<LVL::Debug>
01/09/2018 13:08:12 upgrade_validate_file.sh|Process remote SFTP request|<LVL::Info>
01/09/2018 13:08:12 upgrade_validate_file.sh|Get //ciscocm.tftp_tzupdate_version_v1.0.cop.sgn size via sftp|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|Size of file obtained from sftp is 43702095|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|Total space needed is 87404190|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|Check free space|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|(CAPTURE) Free space: 10427916288, Needed space: 87404190|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|There is enough space on device to proceed.|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|Remote SFTP request complete (0)|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|success|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|upgrade_validate_file.sh complete (rc=0)|<LVL::Info>
01/09/2018 13:08:13 upgrade_validate_file.sh|Parse argument status=upgrade.stage.validated|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|_set_upgrade_status_attribute: status set to upgrade.stage.validated|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|is_upgrade_lock_available: Upgrade lock is not available.|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|is_upgrade_in_progress: Already locked by this process (pid: 27020).|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|release_upgrade_lock: Releasing lock (pid: 27020)|<LVL::Debug>
01/09/2018 13:08:13 upgrade_validate_file.sh|Unmount DVD|<LVL::Info>
01/09/2018 13:08:15 upgrade_get_file.sh|Starting upgrade_get_file.sh|<LVL::Info>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument method=remote_sftp|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument source_dir=/|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument file_name=ciscocm.tftp_tzupdate_version_v1.0.cop.sgn|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument dest_dir=/common/download/|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument remote_host=10.140.64.13|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument user_name=cisco|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument version=0.0.0.0-0|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument file_type=cop|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument file_signed=yes|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|is_upgrade_lock_available: Upgrade lock is available.|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|status in upgrade status.xml upgrade.stage.validated|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|acquire_upgrade_lock: Lock is free, creating lock (pid: 30878)|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument toVersion=0.0.0.0-0|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|_set_upgrade_status_attribute: toVersion set to 0.0.0.0-0|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|Parse argument status=upgrade.stage.downloading|<LVL::Debug>
01/09/2018 13:08:15 upgrade_get_file.sh|_set_upgrade_status_attribute: status set to upgrade.stage.downloading|<LVL::Debug>
01/09/2018 13:08:16 upgrade_get_file.sh|Process remote SFTP request|<LVL::Info>
01/09/2018 13:08:16 upgrade_get_file.sh|source_dir=/, dest_file=/common/download//ciscocm.tftp_tzupdate_version_v1.0.cop.sgn, file_name=ciscocm.tftp_tzupdate_version_v1.0.cop.sgn|<LVL::Debug>
01/09/2018 13:08:16 upgrade_get_file.sh|Starting SFTP|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|SFTP request complete|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|Download of iso file RTMTStart|<LVL::Notice>
01/09/2018 13:08:36 upgrade_get_file.sh|Parse argument status=upgrade.stage.checksumming|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|_set_upgrade_status_attribute: status set to upgrade.stage.checksumming|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|Create md5 "/common/download/ciscocm.tftp_tzupdate_version_v1.0.cop.sgn.md5"|<LVL::Info>
01/09/2018 13:08:36 upgrade_get_file.sh|MD5(/common/download/ciscocm.tftp_tzupdate_version_v1.0.cop.sgn)= a2:0d:9f:07:ce:85:04:07:85:e3:23:ed:29:17:36:66|<LVL::Debug>
01/09/2018 13:08:36 upgrade_get_file.sh|Create md5 complete|<LVL::Info>
01/09/2018 13:08:36 upgrade_get_file.sh|Authenticate file "/common/download/ciscocm.tftp_tzupdate_version_v1.0.cop.sgn"|<LVL::Info>
01/09/2018 13:08:38 upgrade_get_file.sh|File authentication complete|<LVL::Debug>
01/09/2018 13:08:38 upgrade_get_file.sh|Download of iso file RTMTFinish|<LVL::Notice>
01/09/2018 13:08:38 upgrade_get_file.sh|Process preflight|<LVL::Info>
01/09/2018 13:08:38 upgrade_get_file.sh|Skipping preflight since file type is COP|<LVL::Debug>
01/09/2018 13:08:39 upgrade_get_file.sh|success|<LVL::Info>
01/09/2018 13:08:39 upgrade_get_file.sh|upgrade_get_file.sh complete (rc=0)|<LVL::Info>
01/09/2018 13:08:39 upgrade_get_file.sh|is_upgrade_lock_available: Upgrade lock is not available.|<LVL::Debug>
01/09/2018 13:08:39 upgrade_get_file.sh|is_upgrade_in_progress: Already locked by this process (pid: 30878).|<LVL::Debug>
01/09/2018 13:08:39 upgrade_get_file.sh|release_upgrade_lock: Releasing lock (pid: 30878)|<LVL::Debug>

01/09/2018 13:09:19 sd_cancelInstall.sh|Pre-upgrade cancel/clean-up initiated
01/09/2018 13:09:19 sd_cancelInstall.sh|Canceling active side processes
01/09/2018 13:09:19 sd_cancelInstall.sh|Canceling active side processes done
01/09/2018 13:09:19 sd_cancelInstall.sh|Canceling inactive side processes
01/09/2018 13:09:19 sd_cancelInstall.sh|Skipping IDS shared memory clean up since this is a COP
01/09/2018 13:09:20 sd_cancelInstall.sh|Canceling inactive side processes done

[18/01/09_13:09:27] locale_install.sh: Successful untarring of /common/download//ciscocm.tftp_tzupdate_version_v1.0.cop
01/09/2018 13:09:27 Current active version is 11.5.1.13902-2.i386
01/09/2018 13:09:27 major=11
01/09/2018 13:09:27 minor=5
01/09/2018 13:09:27 maint=1
01/09/2018 13:09:27 build=13902-2
01/09/2018 13:09:27 active version=11.5.1.13902-2
01/09/2018 13:09:27 Cop version incompatible, exit
[18/01/09_13:09:27] locale_install.sh: ERROR: Copstart script of /common/download//ciscocm.tftp_tzupdate_version_v1.0.cop failed

[pkinane]

@Ryan Espedido, I see your system is 11.5.1.13902-2 so you are good to go.

Here is a snippet from the read me for the cop file.

The fixes provided in this COP file (ciscocm.tftp_tzupdate_version_v1.0.cop.sgn)
are only intended for CUCM 11.5.1.10000-6 through 11.5.1.12028-1 and will only
install on these versions. The fixes in the COP file are included in 11.5(1)
Engineering Special 11.5.1.12029-1 and higher as well as 11.5(1)SU2.

[kminnyc]

Thank you *so* much for posting this. I was pulling my hair out for 3 days troubleshooting this exact issue. This was our first 8831 install, so I had assumed something was wrong with either the hardware or our configuration. 

Our behavior was identical to the original post:

- Brand new 8831 out of the box

- We tried every firmware imaginable on the 8831 

- We tried different configurations for the phone on CallManager

- Every case resulted in the 8831 displaying "Registering..." and a status of "Rejected" in CallManager

- Going into 'Admin Settings > Reset Settings > Security' would allow the phone to register and operate normally, but was throwing constant (every second) errors in the local phone error log.

Performing the steps of removing the g3-tones.xml.sgn file and applying the ciscocm.tftp_tzupdate_version_v1.0.cop.sgn fix also worked in our environment (which is 11.5.1.11900-26)

[pkinane]

You're welcome. I'm glad I was able to help out.