Re: CMS not registering as CFB on CUCM

jayender.n · ‎10-09-2018

CMS not registering as CFB on the CUCM for ad-hoc VC calls.

CUCM Ver: 12
CMS ver : 2.4

Secure SIP trunk working fine with calls.

Using Private CA to sign all the certificates, no certificate errors when using FQDN to access CMS from browser.

Using port 445 on webadmin.
CA certificate added on callmanager-trust.
Client Authentication and (1.3.6.1.5.5.7.3.2)
Server Authentication (1.3.6.1.5.5.7.3.1) enabled in certificate.
https://FQDN/api/v1/system/status opens fine, no errors.

Jaime Valencia · ‎10-09-2018

Does tomcat trusts the webadmin certificate?

HTH

java

if this helps, please rate

jayender.n · ‎10-09-2018

CA used to sign Webadmin CSR is in CallManager-trust. As per documentation it needs to be in Callmanager-trust only. Same CA used to sign callmanager CSR and CA loaded on to the CMS.

I will add it tomcat-trust and check again.

Any other certification, CSR, signing and uploading tips/steps might be useful.
Also any suggestion on CMS hostname and domain under DNS on CMS.

Below are CUCM logs
========================================================================================================================
SipMcuControl(1,100,36,17) |1,100,42,1.89^*^* |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] Device Name=CFB_CMS Primary Uri=https://MY-FQDN:445/RPC2/ Pkid=4087cdc5-95ae-7343-a7cc-f41ee0425a40 Http Handler Ind Type=0
00420329.001 |14:55:59.318 |AppInfo |HttpManager - wait_HttpHandlerInd pkid[4087cdc5-95ae-7343-a7cc-f41ee0425a40], pURI[https://MY-FQDN:445/RPC2/], sURI[], RReqTimer[10000], enableLB[0]
00420329.002 |14:55:59.318 |AppInfo |HttpManager - received HttpHandlerInd (insert) - and no handler yet
00420329.003 |14:55:59.318 |AppInfo |HttpManager::sendGetHostByNameReq - send req for pURI[https://MY-FQDN:445/RPC2/]
00420329.004 |14:55:59.318 |AppInfo |HttpManager::getAddrFromHostName token https
00420329.005 |14:55:59.318 |AppInfo |HttpManager::getAddrFromHostName token MY-FQDN
00420329.006 |14:55:59.318 |AppInfo |HttpManager::getAddrFromHostName token 445
00420329.007 |14:55:59.318 |AppInfo |HttpManager::getAddrFromHostName token RPC2
00420329.008 |14:55:59.318 |AppInfo |HttpManager::getAddrFromHostName hScheme https, and hHost MY-FQDN , and value size 4 and port 445
00420330.000 |14:55:59.318 |SdlSig |QueryAssociatedSipdStatus |restart0 |SIPD(1,100,84,1) |SipMcuControl(1,100,36,17) |1,100,42,1.89^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] AssociatedSipdType = 0
00420331.000 |14:55:59.318 |SdlSig |AssociatedSipdStatusInd |waitSipTrunkLookUp |SipMcuControl(1,100,36,17) |SIPD(1,100,84,1) |1,100,42,1.89^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] SipdStatus = INService
00420332.000 |14:55:59.590 |SdlSig |DbObjectCacheTimer |initialized |Db(1,100,213,1) |SdlTimerService(1,100,3,1) |1,100,150,1.1^*^* |[T:H-H:0,N:0,L:0,V:0,Z:0,D:0] AppCorr: 0
00420333.000 |14:55:59.797 |SdlSig |ConnStartInd |wait |HttpHandler(1,100,39,14) |HttpHandler(1,100,39,14) |1,100,39,14.1^*^* |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] host=MY-FQDN
00420334.000 |14:55:59.797 |SdlSig |ConnOosInd |wait |HttpHandler(1,100,39,14) |HttpHandler(1,100,39,14) |1,100,39,14.2^*^* |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] host=MY-FQDN
00420334.001 |14:55:59.798 |AppInfo |ConnectionFailureToPDP - A connection request from Unified CM to the policy decision point failed Policy Decision Point:https://MY-FQDN:445/RPC2/ The cause of the connection failure:No response from PDP App ID:Cisco CallManager Cluster ID:StandAloneCluster Node ID:NXTRA-DC-CUCM01
00420334.002 |14:55:59.798 |AlarmErr |AlarmClass: CallManager, AlarmName: ConnectionFailureToPDP, AlarmSeverity: Error, AlarmMessage: , AlarmDescription: A connection request from Unified CM to the policy decision point failed, AlarmParameters: PolicyDecisionPoint:https://MY-FQDN:445/RPC2/, FailedToConnectReason:No response from PDP, AppID:Cisco CallManager, ClusterID:StandAloneCluster, NodeID:NXTRA-DC-CUCM01,
00420335.000 |14:55:59.798 |SdlSig |ConnStopInd |wait |HttpHandler(1,100,39,14) |HttpHandler(1,100,39,14) |1,100,39,14.3^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] host=MY-FQDN
00420336.000 |14:55:59.799 |SdlSig |ConnStartInd |wait |HttpHandler(1,100,39,14) |HttpHandler(1,100,39,14) |1,100,39,14.4^*^* |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] host=MY-FQDN
00420337.000 |14:55:59.799 |SdlSig |ConnOosInd |wait |HttpHandler(1,100,39,14) |HttpHandler(1,100,39,14) |1,100,39,14.5^*^* |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] host=MY-FQDN
00420337.001 |14:55:59.799 |AppInfo |ConnectionFailureToPDP - A connection request from Unified CM to the policy decision point failed Policy Decision Point:https://MY-FQDN:445/RPC2/ The cause of the connection failure:No response from PDP App ID:Cisco CallManager Cluster ID:StandAloneCluster Node ID:NXTRA-DC-CUCM01
00420337.002 |14:55:59.799 |AlarmErr |AlarmClass: CallManager, AlarmName: ConnectionFailureToPDP, AlarmSeverity: Error, AlarmMessage: , AlarmDescription: A connection request from Unified CM to the policy decision point failed, AlarmParameters: PolicyDecisionPoint:https://MY-FQDN:445/RPC2/, FailedToConnectReason:No response from PDP, AppID:Cisco CallManager, ClusterID:StandAloneCluster, NodeID:NXTRA-DC-CUCM01,
00420338.000 |14:55:59.799 |SdlSig |ConnStopInd |wait |HttpHandler(1,100,39,14) |HttpHandler(1,100,39,14) |1,100,39,14.6^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] host=MY-FQDN
00420338.001 |14:55:59.799 |Stopping | | |HttpHandler(1,100,39,14) |HttpHandler(1,100,39,14) | |NumOfCurrentInstances: 1
00420339.000 |14:56:00.005 |SdlSig |DeviceEventReceiptMonitoringTimer |wait |StationInit(1,100,65,1) |SdlTimerService(1,100,3,1) |1,100,150,1.1^*^* |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0]
00420340.000 |14:56:00.592 |SdlSig |DbObjectCacheTimer |initialized |Db(1,100,213,1) |SdlTimerService(1,100,3,1) |1,100,150,1.1^*^* |[T:H-H:0,N:0,L:0,V:0,Z:0,D:0] AppCorr: 0
00420341.000 |14:56:00.840 |Created | | |SdlTCPConnection(1,100,14,673) |SdlTCPListener(1,100,12,4) | |NumOfCurrentInstances: 11
00420342.000 |14:56:00.841 |SdlSig |SdlConnectionInd |wait |SIPTcp(1,100,74,1) |SdlTCPConnection(1,100,14,673) |1,100,12,4.667^*^* |*TraceFlagOverrode
========================================================================================================================
CMS Logs

Oct 8 08:29:25 user.notice callbridge init: Module 0 starting /etc/init.d/S99webbridge
Oct 8 08:29:25 user.notice callbridge init: Module 0 stopping /etc/init.d/S99webbridge
Oct 8 08:29:25 daemon.info callbridge : starting pid 4110, tty '': '/sbin/getty 38400 tty1'
Oct 8 08:29:25 user.info callbridge webbridge_launch: observed address event: ipv4.module.interfaces.observed.eth4.addresses
Oct 8 08:29:25 user.notice callbridge WEBADMIN_PROXY: [Mon Oct 08 08:29:25.721829 2018] [lbmethod_heartbeat:notice] [pid 4151:tid 140215997101824] AH02282: No slotmem from mod_heartmonitor
Oct 8 08:29:25 user.notice callbridge CUCM: Starting CUCM escalation
Oct 8 08:29:25 user.notice callbridge WEBADMIN_PROXY: [Mon Oct 08 08:29:25.723394 2018] [mpm_event:notice] [pid 4151:tid 140215997101824] AH00489: Apache/2.4.27 (Unix) CiscoSSL/1.0.2n.6.1.368-fips configured -- resuming normal operations
Oct 8 08:29:25 user.notice callbridge WEBADMIN_PROXY: [Mon Oct 08 08:29:25.723433 2018] [core:notice] [pid 4151:tid 140215997101824] AH00094: Command line: '/usr/bin/httpd -f /etc/httpd/webadmin.conf.ssl'
Oct 8 08:29:27 user.info callbridge cucm-esc: INFO: Starting CUCM escalation script
Oct 8 08:29:27 user.info callbridge cucm-esc.CallClearingThread: INFO: No conferences, waiting until a new conference joins.
Oct 8 08:29:27 user.info callbridge cucm-esc: INFO: Listening on 127.0.0.1:8081
Oct 8 08:29:40 kern.info callbridge kernel: [ 64.559504] docker0: port 1(veth07f0ced) entered forwarding state
Oct 8 08:34:11 user.info callbridge host:server: [USAGE] : {"1" : [[0,0.000,0],[0],[[0,0,0,0,0,0,0],[0,0,0,0,0,0,0],[0,0,0,0,0,0,0],[0,0,0,0,0,0,0],[0,0,0,0,0,0,0]]]}
Oct 8 08:34:11 user.info callbridge host:server: [USAGE] : {"2" : [0,0.000,0.000,0,0]}
Oct 8 08:34:44 kern.warning callbridge kernel: [ 368.460610] kworker/dying (6) used greatest stack depth: 12608 bytes left
Oct 8 08:37:18 auth.info callbridge sshd[5705]: Operating in CiscoSSL FIPS mode
Oct 8 08:37:18 auth.info callbridge sshd[5705]: Operating in CiscoSSL Common Criteria mode
Oct 8 08:37:18 auth.err callbridge sshd[5705]: error: key_load_public: invalid format
Oct 8 08:37:18 auth.err callbridge sshd[5705]: error: key_load_private: invalid format
Oct 8 08:37:18 auth.err callbridge sshd[5705]: error: key_load_public: invalid format
Oct 8 08:37:18 auth.err callbridge sshd[5705]: error: Could not load host key: /etc/ssh_host_ed25519_key
Oct 8 08:37:18 auth.info callbridge sshd[5705]: FIPS mode initialized
Oct 8 08:37:23 auth.info callbridge sshd[5705]: Accepted keyboard-interactive/pam for admin from 192.170.5.89 port 56741 ssh2
Oct 8 08:37:30 local0.info callbridge sftp: admin granted permission to access log
Oct 8 08:37:30 local0.info callbridge sftp: admin requests open of log for reading: success
Oct 8 08:37:31 kern.warning callbridge kernel: [ 535.371060] traffic shaping: rejected: IN=eth4 OUT= MAC=00:0c:29:b2:71:19:00:09:0f:09:00:14:08:00 src=192.170.5.89 DST=10.240.41.16 LEN=40 TOS=0x00 PREC=0x00 TTL=121 ID=7651 DF PROTO=TCP SPT=56741 DPT=22 WINDOW=61320 RES=0x00 ACK URGP=0
Oct 8 08:37:31 kern.warning callbridge kernel: [ 535.371189] traffic shaping: rejected: IN=eth4 OUT= MAC=00:0c:29:b2:71:19:00:09:0f:09:00:14:08:00 src=192.170.5.89 DST=10.240.41.16 LEN=40 TOS=0x00 PREC=0x00 TTL=121 ID=7652 DF PROTO=TCP SPT=56741 DPT=22 WINDOW=61320 RES=0x00 ACK URGP=0
Oct 8 08:37:31 kern.warning callbridge kernel: [ 535.371351] traffic shaping: rejected: IN=eth4 OUT= MAC=

Shashank Mahajan · ‎12-05-2018

I see the following error in CUCM logs:

00420334.001 |14:55:59.798 |AppInfo |ConnectionFailureToPDP - A connection request from Unified CM to the policy decision point failed Policy Decision Point:https://MY-FQDN:445/RPC2/ The cause of the connection failure:No response from PDP App ID:Cisco CallManager Cluster ID:StandAloneCluster Node ID:NXTRA-DC-CUCM01

This error suggests a cert problem or a CCM service restart needed. If you are sure that certs are correct and uploaded to the correct trust store, then a Call Manager service restart on all nodes is what i believe should resolve this issue.

mmaamm238 · ‎02-09-2020

Thank you

After rebooting CUCM it worked.

jayender.n · ‎10-10-2018

Its still not working. Any suggestions?

Jaime Valencia · ‎10-10-2018

I'd take another look at the certificates and make sure they're as per the CMS certificate guidelines:

Oct 8 08:37:18 auth.err callbridge sshd[5705]: error: key_load_public: invalid format
Oct 8 08:37:18 auth.err callbridge sshd[5705]: error: key_load_private: invalid format
Oct 8 08:37:18 auth.err callbridge sshd[5705]: error: key_load_public: invalid format

Did you restart tomcat after uploading the root CA from webadmin?

HTH

java

if this helps, please rate

Sergey Bodikov · ‎10-30-2018

We got exact same problem after upgrading to 2.4.1.

Sergey Bodikov · ‎12-05-2018

Our problem was indeed in certificates, but certificates described in tls sip trust <trust bundle> section of configuration (there was old version of certs that was deleted from CUCM).
Its odd but we got same configuration in 2.2.1 and 2.2.10 and all worked fine (at least CMS get successful registration in CUCM as CFB). Stopped working when we updated to 2.3.7 (prior updating to 2.4.1).
Is there any changes to mechanics of tls sip verification that affect functionality of CUCM-CMS interop?