IP Phone 3905 unregistration randomly.

luis.cabrera · ‎10-15-2014

Hi dears

We are experience some trouble with the 3905 phones, it is a CUCM 9.x, the issue began after the customer made some changes in his LAN/WAM network, the problem is that the 3905 phones release his ip address and take a new ip address over and over, regardless of the lease time that is infinite, Here is a phone log, if somebody can look at this and have any idea, I will appreciate that.

Thanks in advance.

12:10:32:233 x [CENTRAL] State transit PROVISIONING --> REGISTERING
12:10:32:255 [ipps] Enter func: ipps_sysConfigure() to configure external modules!!

12:10:32:261 [ipps] Exit func: ipps_sysConfigure(), finish configuration!!

12:10:32:262 [ipps] In func: ipps_sysStart()....start service..

12:10:32:263 [ipps] In func: mlcu_cleanLineInfo(), clean line info for unConfigure!

12:10:32:264 f [ipps] In func: mlcu_isKpmlEnabled(), KPML value = 3, blRet = 1

12:10:32:265 x [pcu] [pcuGetAccData][585]Paul AUTH_NAME=, PW=
12:10:32:266 x [pcu] [resolveCucmIPAddr][315] CUCM0 addr=10.56.240.57
12:10:32:270 w [pcu] [resolveCucmIPAddr()384] Decide register URI=10.56.240.57:5060

12:10:32:272 x [pcu] [resolveCucmIPAddr][315] CUCM1 addr=10.56.240.53
12:10:32:273 w [pcu] [resolveCucmIPAddr()400] Server(1)=10.56.240.53, Don't set register URI

12:10:32:274 x [pcu] [pcuGetAccData][664] Final data->proxy_info[0].server_ip=10.56.240.57, server=10.56.240.57, isSRST=0
12:10:32:275 x [pcu] [pcuGetAccData][664] Final data->proxy_info[1].server_ip=10.56.240.53, server=10.56.240.53, isSRST=0
12:10:32:282 x [pcu] [pcux_register][5956] name=58118, bulkreg=0
12:10:32:297 x [pcu] [_pcu_start():923] There is 2 available server

12:10:32:301 x [CENTRAL] Waiting event in REGISTERING
12:10:32:334 [sip] 00:47:04.332 sip_endpoint.c Module "mod-pjsua-log" registered
12:10:32:336 [sip] 00:47:04.335 sip_endpoint.c Module "mod-tsx-layer" registered
12:10:32:341 [sip] 00:47:04.340 sip_endpoint.c Module "mod-stateful-util" registered
12:10:32:344 [sip] 00:47:04.343 sip_endpoint.c Module "mod-ua" registered
12:10:32:346 [sip] 00:47:04.345 sip_endpoint.c Module "mod-100rel" registered
12:10:32:351 [sip] 00:47:04.350 sip_endpoint.c Module "mod-pjsua" registered
12:10:32:354 [sip] 00:47:04.352 sip_endpoint.c Module "mod-invite" registered
12:10:32:356 [sip] 00:47:04.354 sip_endpoint.c Module "mod-evsub" registered
12:10:32:361 [sip] 00:47:04.357 pjsua_core.c Init KPML module!!!!!!

12:10:32:363 [sip] 00:47:04.361 sip_endpoint.c Module "mod-kpml" registered
12:10:32:364 [sip] 00:47:04.363 pjsua_core.c Init dlgEvent module!!!!!!

12:10:32:366 [sip] 00:47:04.365 sip_endpoint.c Module "mod-event" registered
12:10:32:371 [sip] 00:47:04.370 sip_endpoint.c Module "mod-mwi" registered
12:10:32:373 [sip] 00:47:04.372 sip_endpoint.c Module "mod-refer" registered
12:10:32:375 [sip] 00:47:04.374 pjsua_kpml.c !!! pjsua_kpml_init
12:10:32:380 [sip] 00:47:04.376 sip_endpoint.c Module "mod-pjsua-kpml" registered
12:10:32:382 [sip] 00:47:04.381 sip_endpoint.c Module "mod-pjsua-im" registered
12:10:32:384 [sip] 00:47:04.383 sip_endpoint.c Module "mod-pjsua-options" registered
12:10:32:391 [sip] 00:47:04.390 pjsua_core.c 1 SIP worker threads created
12:10:32:393 [sip] 00:47:04.392 pjsua_core.c pjsua version 1.8.10 for i686-pc-linux-gnu initialized
12:10:32:395 [sip] 00:47:04.394 sip_endpoint.c Module "mod-pjsua-advsip" registered
12:10:32:403 [sip] 00:47:04.402 tcplis:5060 SIP TCP listener ready for incoming connections at 10.62.250.109:5060
12:10:32:405 [sip] 00:47:04.404 ctlslis:2002 SIP Cisco TLS has already registered the factory functions !

12:10:32:410 [sip] 00:47:04.406 pjsua_core.c SIP UDP socket reachable at 10.62.250.109:5060
12:10:32:414 [sip] 00:47:04.412 sip_transport. Transport udp0x139ea18 registered: type=UDP
12:10:32:416 [sip] 00:47:04.415 udp0x139ea18 SIP UDP transport started, published address is 10.62.250.109:5060
12:10:32:421 [sip] 00:47:04.420 sip_endpoint.c Module "mod-unsolicited-mwi" registered
12:10:32:423 [sip] 00:47:04.422 pjcu.c pjcuRcvHandler(CONN), REGISTER, eid=0, cid=-1

12:10:32:500 [sip] 00:47:04.496 pjcu.c [PJCU_ProcConnEvt():2609] case FSIP_CORE_REGISTER, PJCU_TASK_ID(0), eid(0)

12:10:32:503 [sip] 00:47:04.502 pjcu.c [pjcu_config_acc():595] eid(0) is not mapping with pjcu accid, add a new account
12:10:32:506 [sip] 00:47:04.504 pjsua_kpml.c !!! pjsua_kpml_init_acc
12:10:32:510 [sip] 00:47:04.506 pjsua_acc.c Account "TELECOMUNICACIONES" added with id 0
12:10:32:521 [sip] 00:47:04.517 sip_transport. Transport tcpc0x1b1c424 registered: type=TCP
12:10:32:523 [sip] 00:47:04.521 tcpc0x1b1c424 TCP client transport created
12:10:32:526 [sip] 00:47:04.524 tcpc0x1b1c424 TCP transport 10.62.250.109:3952 is connecting to 10.56.240.57:5060...
12:10:32:536 [sip] 00:47:04.535 pjsua_acc.c Registration sent
12:10:32:541 [sip] 00:47:04.537 pjcu.c [pjcu_config_acc():610] Add a new entity eid(0) mapping acc_id(0)("TELECOMUNICACIONES")
12:10:32:612 [sip] 00:47:04.610 tcpc0x1b1c424 TCP transport 10.62.250.109:3952 is connected to 10.56.240.57:5060
12:10:32:634 [sip] 00:47:04.632 pjsua_acc.c SIP outbound status for acc 0 is not active
12:10:32:640 [sip] 00:47:04.635 pjsua_acc.c "TELECOMUNICACIONES": registration success, status=200 (OK), will re-register in 120 seconds
12:10:32:641 w [pcu] [pcu_polling_sipserver_thread():1351] polling resumed..

12:10:32:645 [sip] 00:47:04.644 pjcu.c pjcuRcvHandler(KA), KA_REQUEST, eid=-1, p1=10.56.240.53:5060;transport=tcp

12:10:32:653 [sip] 00:47:04.651 pjcu.c pjcu_on_reg_state2(), Account["TELECOMUNICACIONES"] : OK, status=200
12:10:32:657 x [pcu] pcuRcvHandler(CALL), SRV_EV, eid=0, cid=65535,

12:10:32:661 x [pcu] [pcux_insrv_cb():7071] CUCM_DateTime:Fri, 10 Oct 2014 15:10:32 GMT
12:10:32:662 x [pcu] Sync time from server: Fri, 10 Oct 2014 15:10:32 GMT

12:10:32:670 x [pcu] [set_svr_type][1599] Bfe active_server_idx=0, serverType=0
12:10:32:671 x [pcu] [set_svr_type][1602] Aft serverType=0, Server Number=2

12:10:32:674 [ipps] ----- PCU: CC_SRV, pid=0, eid=0, cid=65535 -----
12:10:32:675 [ipps] In func: remoteNtyEvtProcess(), lib = 0, cid = 65535, ntyEv = 0

12:10:32:676 f [ipps] In func: remoteNtyEvtProcess(), recv inservice nty, svrType = 0, cause = 0
12:10:32:680 f [MMI] : In func: ui_nty(), lid = 0, cid = 65535, ntyEv = 0

12:10:32:681 x [CENTRAL] IPPS CB function(RegStatus) is called (1) with Line (0)
12:10:32:682 f [ipps] In func: mlcu_isKpmlEnabled(), KPML value = 3, blRet = 1

12:10:32:744 x [CENTRAL] Enter FSM: State(REGISTERING) | Event(REGISTER_OK) | Cause(0)
12:10:32:744 x [CENTRAL] State transit REGISTERING --> STANDBY
12:10:32:746 f [fos_task] [fos]: In func: fos_taskCreate(), create thread (NTP) OK, threadID = 74778
12:10:32:750 w [NTP] Created NTP task successful
12:10:32:751 x [CENTRAL] Waiting event in STANDBY
12:10:32:754 w [NTP] ----- szNTPSVR1=10.56.240.1, szNTPSVR2=0.0.0.0,
12:10:32:755 w [NTP] msntp_run() 1189 nSvrCount = 1
12:10:32:756 w [NTP] find_address() 58 hostname=10.56.240.1
12:10:32:762 w [NTP] run_client() 943
12:10:32:767 w [NTP] read_packet() 625 packet length=48
12:10:32:776 w [NTP] read_packet() 640 bNeedCheckLI=0, data->mode=4, failed=0, data->status=0, data->version=3, data->stratum=1
12:10:32:780 w [NTP] read_packet() 663 failed=0
12:10:32:783 w [NTP] run_client() 996 error=0.008498, minerr=0.000000
12:10:32:846 [sip] 00:47:04.844 pjcu_pjsip_api [pcu_rptREFER():2856]: Get Refer: eid: 0, accid: 0

12:10:32:852 x [pcu] pcuRcvHandler(CALL), REFER_EV, eid=0, cid=65535,

12:10:32:854 x [pcu] [pcux_refer_cb][7592]Find content type=multipart/mixed
12:10:32:855 x [pcu] [set_line_fwd][1318] fwd_num_len==0.

12:10:32:860 x [pcu] fwdInfo.forwardAddress=, tovoicemail=0
12:10:32:861 x [pcu] [pcux_2_pcu_notify_cb():867] pcux_2_pcu_notify_cb, cid=65535, e_NtyId=10

12:10:32:863 x [pcu] [process_xml_bulk_meg][5202] No contact line info
12:10:32:864 x [pcu] [process_xml_bulk_meg][5240] eid(0) MWI: no

12:10:32:865 x [pcu] [pcux_2_pcu_notify_cb():867] pcux_2_pcu_notify_cb, cid=65535, e_NtyId=3

12:10:32:871 x [pcu] [notify_ccs_action_cb][4735]:
prov_config_version=1412885478-648e886c-c34b-4274-9454-0cfa61fbe652
lastCMConfigVersion=1412885478-648e886c-c34b-4274-9454-0cfa61fbe652
cm_version=1412885478-648e886c-c34b-4274-9454-0cfa61fbe652

12:10:32:872 x [pcu] [pcux_2_pcu_notify_cb():867] pcux_2_pcu_notify_cb, cid=65535, e_NtyId=23

12:10:32:873 [ipps] ----- PCU: CC_NTY, pid=0, eid=0, cid=65535 -----
12:10:32:874 [ipps] In func: remoteNtyEvtProcess(), lib = 0, cid = 65535, ntyEv = 10

12:10:32:875 f [MMI] : In func: ui_nty(), lid = 0, cid = 65535, ntyEv = 10

12:10:32:880 [ipps] ----- PCU: CC_NTY, pid=0, eid=0, cid=65535 -----
12:10:32:881 [ipps] In func: remoteNtyEvtProcess(), lib = 0, cid = 65535, ntyEv = 3

12:10:32:882 f [MMI] : In func: ui_nty(), lid = 0, cid = 65535, ntyEv = 3

12:10:32:884 [ipps] ----- PCU: CC_NTY, pid=0, eid=0, cid=65535 -----
12:10:32:885 [ipps] In func: remoteNtyEvtProcess(), lib = 0, cid = 65535, ntyEv = 23

12:10:32:971 [sip] 00:47:04.966 sip_transport. Transport tcpc0x1b40018 registered: type=TCP
12:10:32:973 [sip] 00:47:04.972 tcpc0x1b40018 TCP client transport created
12:10:32:977 [sip] 00:47:04.975 tcpc0x1b40018 TCP transport 10.62.250.109:4140 is connecting to 10.56.240.53:5060...
12:10:32:985 [sip] 00:47:04.983 tcpc0x1b40018 TCP transport 10.62.250.109:4140 is connected to 10.56.240.53:5060
12:10:33:005 [sip] 00:47:05.003 pjcu.c pjcu_rpt_ka_status(), target(10.56.240.53:5060;transport=tcp): status=1, id=27

12:10:33:010 x [pcu] pcuRcvHandler(KA), KA_RESPONSE, eid=0, addr=10.56.240.53:5060;transport=tcp, status=1

12:10:33:012 x [pcu] [pcu_polling_sipserver_thread():1478] mark!

12:10:33:023 [sip] 00:47:05.021 tcpc0x1b40018 TCP transport destroyed normally, remote:10.56.240.53:5060
12:11:36:840 w [NTP] find_address() 58 hostname=10.56.240.1
12:11:36:843 w [NTP] run_client() 943
12:11:36:846 w [NTP] read_packet() 625 packet length=48
12:11:36:853 w [NTP] read_packet() 640 bNeedCheckLI=0, data->mode=4, failed=0, data->status=0, data->version=3, data->stratum=1
12:11:36:854 w [NTP] read_packet() 663 failed=0
12:11:36:856 w [NTP] run_client() 996 error=0.006011, minerr=0.000000
12:12:27:652 [sip] 00:48:59.651 pjsua_acc.c SIP outbound status for acc 0 is not active
12:12:27:655 [sip] 00:48:59.653 pjsua_acc.c "TELECOMUNICACIONES": registration success, status=200 (OK), will re-register in 120 seconds
12:12:27:660 [sip] 00:48:59.656 pjcu.c pjcu_on_reg_state2(), Account["TELECOMUNICACIONES"] : OK, status=200
12:12:27:663 x [pcu] pcuRcvHandler(CALL), SRV_EV, eid=0, cid=65535,

12:12:27:664 x [pcu] [pcux_insrv_cb():7071] CUCM_DateTime:Fri, 10 Oct 2014 15:12:27 GMT
12:12:27:666 x [pcu] [set_svr_type][1599] Bfe active_server_idx=0, serverType=0
12:12:27:666 x [pcu] [set_svr_type][1602] Aft serverType=0, Server Number=2

12:12:27:671 [ipps] ----- PCU: CC_SRV, pid=0, eid=0, cid=65535 -----
12:12:27:672 [ipps] In func: remoteNtyEvtProcess(), lib = 0, cid = 65535, ntyEv = 0

12:12:27:673 f [ipps] In func: remoteNtyEvtProcess(), recv inservice nty, svrType = 0, cause = 0
12:12:27:673 f [MMI] : In func: ui_nty(), lid = 0, cid = 65535, ntyEv = 0

12:12:27:674 x [CENTRAL] IPPS CB function(RegStatus) is called (1) with Line (0)
12:12:27:675 f [ipps] In func: mlcu_isKpmlEnabled(), KPML value = 3, blRet = 1

12:12:27:676 x [CENTRAL] Enter FSM: State(STANDBY) | Event(REGISTER_OK) | Cause(0)
12:12:27:680 x [CENTRAL] Unexpected event REGISTER_OK (cause=0) at STANDBY state
12:12:27:681 x [CENTRAL] Waiting event in STANDBY
12:12:33:022 [sip] 00:49:05.021 pjcu.c pjcuRcvHandler(KA), KA_REQUEST, eid=-1, p1=10.56.240.53:5060;transport=tcp

12:12:33:033 [sip] 00:49:05.031 sip_transport. Transport tcpc0x1b40018 registered: type=TCP
12:12:33:035 [sip] 00:49:05.033 tcpc0x1b40018 TCP client transport created
12:12:33:041 [sip] 00:49:05.036 tcpc0x1b40018 TCP transport 10.62.250.109:4848 is connecting to 10.56.240.53:5060...
12:12:33:045 [sip] 00:49:05.044 tcpc0x1b40018 TCP transport 10.62.250.109:4848 is connected to 10.56.240.53:5060
12:12:33:061 [sip] 00:49:05.056 pjcu.c pjcu_rpt_ka_status(), target(10.56.240.53:5060;transport=tcp): status=1, id=27

12:12:33:063 x [pcu] pcuRcvHandler(KA), KA_RESPONSE, eid=0, addr=10.56.240.53:5060;transport=tcp, status=1

12:12:33:071 [sip] 00:49:05.066 tcpc0x1b40018 TCP transport destroyed normally, remote:10.56.240.53:5060
12:12:33:073 x [pcu] [pcu_polling_sipserver_thread():1478] mark!

12:12:40:900 w [NTP] find_address() 58 hostname=10.56.240.1
12:12:40:903 w [NTP] run_client() 943
12:12:40:906 w [NTP] read_packet() 625 packet length=48
12:12:40:913 w [NTP] read_packet() 640 bNeedCheckLI=0, data->mode=4, failed=0, data->status=0, data->version=3, data->stratum=1
12:12:40:914 w [NTP] read_packet() 663 failed=0
12:12:40:916 w [NTP] run_client() 996 error=0.006029, minerr=0.000000
12:12:42:532 x [CENTRAL] CDP/LLDP-MED CB function is called
12:13:44:960 w [NTP] find_address() 58 hostname=10.56.240.1
12:13:44:963 w [NTP] run_client() 943
12:13:44:966 w [NTP] read_packet() 625 packet length=48
12:13:44:973 w [NTP] read_packet() 640 bNeedCheckLI=0, data->mode=4, failed=0, data->status=0, data->version=3, data->stratum=1
12:13:44:974 w [NTP] read_packet() 663 failed=0
12:13:44:976 w [NTP] run_client() 996 error=0.006113, minerr=0.000000
12:14:22:673 [sip] 00:50:54.671 pjsua_acc.c SIP outbound status for acc 0 is not active
12:14:22:675 [sip] 00:50:54.674 pjsua_acc.c "TELECOMUNICACIONES": registration success, status=200 (OK), will re-register in 120 seconds
12:14:22:681 [sip] 00:50:54.676 pjcu.c pjcu_on_reg_state2(), Account["TELECOMUNICACIONES"] : OK, status=200
12:14:22:684 x [pcu] pcuRcvHandler(CALL), SRV_EV, eid=0, cid=65535,

12:14:22:685 x [pcu] [pcux_insrv_cb():7071] CUCM_DateTime:Fri, 10 Oct 2014 15:14:22 GMT
12:14:22:686 x [pcu] [set_svr_type][1599] Bfe active_server_idx=0, serverType=0
12:14:22:690 x [pcu] [set_svr_type][1602] Aft serverType=0, Server Number=2

12:14:22:691 [ipps] ----- PCU: CC_SRV, pid=0, eid=0, cid=65535 -----
12:14:22:692 [ipps] In func: remoteNtyEvtProcess(), lib = 0, cid = 65535, ntyEv = 0

12:14:22:693 f [ipps] In func: remoteNtyEvtProcess(), recv inservice nty, svrType = 0, cause = 0
12:14:22:694 f [MMI] : In func: ui_nty(), lid = 0, cid = 65535, ntyEv = 0

12:14:22:695 x [CENTRAL] IPPS CB function(RegStatus) is called (1) with Line (0)
12:14:22:696 f [ipps] In func: mlcu_isKpmlEnabled(), KPML value = 3, blRet = 1

12:14:22:700 x [CENTRAL] Enter FSM: State(STANDBY) | Event(REGISTER_OK) | Cause(0)
12:14:22:700 x [CENTRAL] Unexpected event REGISTER_OK (cause=0) at STANDBY state
12:14:22:701 x [CENTRAL] Waiting event in STANDBY
12:14:33:023 [sip] 00:51:05.021 pjcu.c pjcuRcvHandler(KA), KA_REQUEST, eid=-1, p1=10.56.240.53:5060;transport=tcp

12:14:33:033 [sip] 00:51:05.032 sip_transport. Transport tcpc0x1b40018 registered: type=TCP
12:14:33:035 [sip] 00:51:05.034 tcpc0x1b40018 TCP client transport created
12:14:33:041 [sip] 00:51:05.036 tcpc0x1b40018 TCP transport 10.62.250.109:4747 is connecting to 10.56.240.53:5060...
12:14:33:046 [sip] 00:51:05.044 tcpc0x1b40018 TCP transport 10.62.250.109:4747 is connected to 10.56.240.53:5060
12:14:33:061 [sip] 00:51:05.056 pjcu.c pjcu_rpt_ka_status(), target(10.56.240.53:5060;transport=tcp): status=1, id=27

12:14:33:064 x [pcu] pcuRcvHandler(KA), KA_RESPONSE, eid=0, addr=10.56.240.53:5060;transport=tcp, status=1

12:14:33:072 [sip] 00:51:05.066 tcpc0x1b40018 TCP transport destroyed normally, remote:10.56.240.53:5060
12:14:33:074 x [pcu] [pcu_polling_sipserver_thread():1478] mark!

12:14:49:020 w [NTP] find_address() 58 hostname=10.56.240.1
12:14:49:023 w [NTP] run_client() 943
12:14:49:026 w [NTP] read_packet() 625 packet length=48
12:14:49:033 w [NTP] read_packet() 640 bNeedCheckLI=0, data->mode=4, failed=0, data->status=0, data->version=3, data->stratum=1
12:14:49:034 w [NTP] read_packet() 663 failed=0
12:14:49:036 w [NTP] run_client() 996 error=0.005959, minerr=0.000000
12:15:41:530 x [CENTRAL] CDP/LLDP-MED CB function is called
12:15:41:530 x [CENTRAL] CDP/LLDP CB, Adopting Local Admin setting
12:15:41:531 x [CENTRAL] Enter FSM: State(STANDBY) | Event(NET_POLICY_CHANGE) | Cause(3)
12:15:41:532 x [CENTRAL] Config VLAN, cause (3), voice 200 => 4095, native 1 => 4095
12:15:41:650 [ipps] ----- SYS: SY_STOP_EV -----
12:15:41:651 x [pcu] [polling_server_deinit][950] polling_server_deinit, available_proxy_count=2.

12:15:41:652 x [pcu] polling_server_deinit() waiting polling thread stop.

12:15:41:653 [ipps] Enter func: ipps_sysUnConfigure() to un-configure external modules !!

12:15:41:656 [ipps] ----- UIU: UI_END_ALL_CALL, lid=0, cid=65535 -----
12:15:41:656 f [ipps] sipesm, ev=EPCMD_END_ALL_CALL, state(LNST_ONHOOK), eid=0, cid=65535)
12:15:41:660 [ipps] ----- SYS: SY_UNCONFIGURE_EV -----
12:15:41:661 [ipps] In func: mlcu_cleanLineInfo(), clean line info for unConfigure!

12:15:41:661 [ipps] Exit func: ipps_sysUnConfigure(), finish un-configuration !!

12:15:41:665 w [pcu] [pcu_polling_sipserver_thread():1367] not created..

12:15:41:666 w [pcu] [pcu_polling_sipserver_thread():1342] polling stopped..

12:15:41:683 [sip] 00:52:14.682 pjcu.c pjcuRcvHandler(CONN), SHUTDOWN, eid=0, cid=-1

12:15:41:686 [sip] 00:52:14.684 pjcu.c [PJCU_ProcConnEvt():2655] case FSIP_CORE_SHUTDOWN, PJCU_TASK_ID(0), eid(0)
12:15:41:691 [sip] 00:52:14.687 pjcu.c [PJCU_ProcConnEvt():2666]pjsua_var.acc[0].subscribe_dialog.p_evsub=0x0)
12:15:41:695 [sip] 00:52:14.694 pjsua_core.c Shutting down...
12:15:41:700 [sip] 00:52:14.696 pjsua_pres.c Shutting down presence..
12:15:41:703 [sip] 00:52:14.701 pjsua_kpml.c Shutting down kpml..
12:15:41:713 [sip] 00:52:14.710 pjsua_acc.c Unregistration sent
12:15:41:722 [sip] 00:52:14.720 pjsua_acc.c "TELECOMUNICACIONES": unregistration success
12:15:41:725 [sip] 00:52:14.723 pjcu.c pjcu_on_reg_state2(), Account["TELECOMUNICACIONES"] : OK, status=200
12:15:41:731 [sip] 00:52:14.726 tcpc0x1b1c424 TCP connection closed, remote:10.56.240.57:5060
12:15:41:733 [sip] 00:52:14.732 sip_transport. Transport tcpc0x1b1c424 shutting down
12:15:41:736 [sip] 00:52:14.734 pjcu.c pjcu_tcp_connect_close(), TCP(0x1b1c424), addr: 10.56.240.57

12:15:41:741 [sip] 00:52:14.740 pjcu.c [pjcu_tcp_connect_close]Unregistering, Ignore tcp close event !

12:15:41:745 [sip] 00:52:14.743 tcpc0x1b1c424 TCP transport destroyed with reason 70016: Unknown pjlib error 70016, remote:10.56.240.57:5060
12:15:42:721 [sip] 00:52:15.720 pjsua_core.c Destroying...
12:15:42:723 [sip] 00:52:15.722 sip_transactio Stopping transaction layer module
12:15:42:725 [sip] 00:52:15.723 pjsua_advsip.c PJCU advsip module unregistered !
12:15:42:726 [sip] 00:52:15.725 sip_endpoint.c Module "mod-unsolicited-mwi" unregistered
12:15:42:731 [sip] 00:52:15.730 sip_endpoint.c Module "mod-pjsua-options" unregistered
12:15:42:733 [sip] 00:52:15.732 sip_endpoint.c Module "mod-pjsua-im" unregistered
12:15:42:735 [sip] 00:52:15.734 sip_endpoint.c Module "mod-pjsua-kpml" unregistered
12:15:42:737 [sip] 00:52:15.735 sip_endpoint.c Module "mod-pjsua" unregistered
12:15:42:741 [sip] 00:52:15.740 sip_endpoint.c Module "mod-stateful-util" unregistered
12:15:42:743 [sip] 00:52:15.742 sip_endpoint.c Module "mod-refer" unregistered
12:15:42:745 [sip] 00:52:15.744 sip_endpoint.c Module "mod-mwi" unregistered
12:15:42:750 [sip] 00:52:15.746 sip_endpoint.c Module "mod-event" unregistered
12:15:42:752 [sip] 00:52:15.751 sip_endpoint.c Module "mod-kpml" unregistered
12:15:42:754 [sip] 00:52:15.752 sip_endpoint.c Module "mod-evsub" unregistered
12:15:42:756 [sip] 00:52:15.754 sip_endpoint.c Module "mod-invite" unregistered
12:15:42:760 [sip] 00:52:15.756 sip_endpoint.c Module "mod-100rel" unregistered
12:15:42:762 [sip] 00:52:15.761 sip_endpoint.c Module "mod-ua" unregistered
12:15:42:764 [sip] 00:52:15.763 sip_transactio Transaction layer module destroyed
12:15:42:766 [sip] 00:52:15.765 sip_endpoint.c Module "mod-tsx-layer" unregistered
12:15:42:771 [sip] 00:52:15.767 sip_endpoint.c Module "mod-pjsua-advsip" unregistered
12:15:42:773 [sip] 00:52:15.771 sip_endpoint.c Module "mod-msg-print" unregistered
12:15:42:774 [sip] 00:52:15.773 sip_endpoint.c Module "mod-pjsua-log" unregistered
12:15:42:781 [sip] 00:52:15.780 tcplis:5060 SIP TCP listener destroyed
12:15:42:783 [sip] 00:52:15.782 ctlslis:2002 SIP CTLS listener destroyed
12:15:42:785 [sip] 00:52:15.784 sip_endpoint.c Endpoint 0x138e46c destroyed
12:15:42:790 [sip] 00:52:15.786 pjsua_core.c PJSUA destroyed...
12:15:46:680 w [NTP] Need stop NTP
12:15:46:681 w [NTP] msntp_stop() 1245
12:15:46:681 w [NTP] Stop NTP task successfully
12:15:46:682 x [CENTRAL] Provision CB function is called (6)
12:15:46:792 x [CENTRAL] DHCP CB function is called cause (12)
12:15:46:792 x [CENTRAL] DHCP CB function is called cause (14)
12:15:47:226 x [CENTRAL] DHCP CB function is called cause (4)
12:15:47:251 x [SW] switchConf_confVlan(), type: 0, voice: 4095, native: 4095
12:15:47:252 x [SW] swConfVlan(), nVoiceVID: 4095, nNativeVID: 4095, Freezed: 1
12:15:47:284 x [SW] swConfVlan(), No Voice Vlan
12:15:47:285 x [SW] switchConf_confVlan(), SW_VLAN_OPERA_TYPE_DEFAULT
12:15:47:320 x [CENTRAL] State transit STANDBY --> CONFIGURING_IP
12:15:47:321 x [CENTRAL] Begin to config ip
12:15:47:346 f [fos_task] [fos]: In func: fos_taskCreate(), create thread (dhcpTask) OK, threadID = 75799
12:15:47:521 x [CENTRAL] DHCP CB function is called cause (14)
12:15:47:540 x [CENTRAL] DHCP CB function is called cause (1)
12:15:47:541 x [CENTRAL] Waiting event in CONFIGURING_IP
12:15:47:541 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(PROV_CANCELED) | Cause(0)
12:15:47:542 x [CENTRAL] Unexpected event PROV_CANCELED (cause=0) at CONFIGURING_IP state
12:15:47:543 x [CENTRAL] Waiting event in CONFIGURING_IP
12:15:47:543 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(DHCP_RESPONSE) | Cause(12)
12:15:47:544 x [CENTRAL] Receive DHCP cause (12) in CONFIGURING_IP state
12:15:47:545 x [CENTRAL] IP address released
2014/10/10 12:15:47:545 1 Ip address released

12:15:47:546 x [CENTRAL] Waiting event in CONFIGURING_IP
12:15:47:546 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(DHCP_RESPONSE) | Cause(14)
12:15:47:550 x [CENTRAL] Receive DHCP cause (14) in CONFIGURING_IP state
12:15:47:660 x [CENTRAL] Waiting event in CONFIGURING_IP
12:15:47:661 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(DHCP_RESPONSE) | Cause(14)
12:15:47:661 x [CENTRAL] Receive DHCP cause (14) in CONFIGURING_IP state
12:15:47:770 x [CENTRAL] Waiting event in CONFIGURING_IP
12:16:41:546 x [CENTRAL] CDP/LLDP-MED CB function is called
12:16:41:546 x [CENTRAL] CDP/LLDP CB, type 1, voice 200, native 1
12:16:41:550 x [CENTRAL] CDP/LLDP-MED CB Info: voiceVlanId=200, nativeVlanId=1
12:16:41:551 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(NET_POLICY_CHANGE) | Cause(2)
12:16:41:551 x [CENTRAL] Config VLAN, cause (2), voice 4095 => 200, native 4095 => 1
12:16:41:670 [ipps] ----- SYS: SY_STOP_EV -----
12:16:41:671 f [pcu] [pcu_task_create]: PCU thread is not ready !!
12:16:41:672 [ipps] Enter func: ipps_sysUnConfigure() to un-configure external modules !!

12:16:41:676 [ipps] ----- UIU: UI_END_ALL_CALL, lid=0, cid=65535 -----
12:16:41:676 f [ipps] sipesm, ev=EPCMD_END_ALL_CALL, state(LNST_ONHOOK), eid=0, cid=65535)
12:16:41:680 [ipps] ----- SYS: SY_UNCONFIGURE_EV -----
12:16:41:681 [ipps] In func: mlcu_cleanLineInfo(), clean line info for unConfigure!

12:16:41:682 [ipps] Exit func: ipps_sysUnConfigure(), finish un-configuration !!

12:16:46:700 w [NTP] Need stop NTP
12:16:46:701 w [NTP] NTP task has not been created
12:16:46:702 x [CENTRAL] Provision CB function is called (6)
12:16:47:246 x [CENTRAL] DHCP CB function is called cause (4)
12:16:47:261 x [SW] switchConf_confVlan(), type: 1, voice: 200, native: 1
12:16:47:262 x [SW] swConfVlan(), nVoiceVID: 200, nNativeVID: 1, Freezed: 0
12:16:47:352 x [SW] switchConf_confVlan(), SW_VLAN_OPERA_TYPE_LLDPCDP
12:16:47:353 x [CENTRAL] Stays in CONFIGURING_IP state
12:16:47:354 x [CENTRAL] Begin to config ip
12:16:47:382 f [fos_task] [fos]: In func: fos_taskCreate(), create thread (dhcpTask) OK, threadID = 76823
12:16:47:551 x [CENTRAL] DHCP CB function is called cause (14)
12:16:47:570 x [CENTRAL] DHCP CB function is called cause (1)
12:16:47:571 x [CENTRAL] Waiting event in CONFIGURING_IP
12:16:47:571 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(PROV_CANCELED) | Cause(0)
12:16:47:572 x [CENTRAL] Unexpected event PROV_CANCELED (cause=0) at CONFIGURING_IP state
12:16:47:572 x [CENTRAL] Waiting event in CONFIGURING_IP
12:16:47:573 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(DHCP_RESPONSE) | Cause(14)
-0cfa61fbe652
cm_version=1412885478-648e886c-c34b-4274-9454-0cfa61fbe652

12:16:47:574 x [CENTRAL] Receive DHCP cause (14) in CONFIGURING_IP state
12:16:47:680 x [CENTRAL] Waiting event in CONFIGURING_IP
12:17:23:874 x [CENTRAL] DHCP CB function is called cause (5)
12:17:23:875 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(DHCP_RESPONSE) | Cause(7)
12:17:23:876 x [CENTRAL] Receive DHCP cause (7) in CONFIGURING_IP state
12:17:23:880 x [CENTRAL] Get Dynamic IP Address = 10.62.251.41
12:17:23:881 x [CENTRAL] Get Dynamic Netmask = 255.255.254.0
12:17:23:881 x [CENTRAL] Get Dynamic Default Gateway = 10.62.250.4
12:17:23:882 x [CENTRAL] Get dhcp server = 10.62.250.4
12:17:24:100 x [CENTRAL] Config DNS server, auto mode
12:17:24:102 x [CENTRAL] NO DNS server info
12:17:24:102 x [CENTRAL] No DNS Server IP
2014/10/10 12:17:24:103 1 No DNS Server IP

12:17:24:104 x [CENTRAL] NO DNS server info
12:17:24:106 x [CENTRAL] DNS Server 1 = 0.0.0.0
12:17:24:106 x [CENTRAL] DNS Server 2 = 0.0.0.0
12:17:24:110 x [CENTRAL] DNS Domain =
12:17:24:114 x [CENTRAL] Waiting event in CONFIGURING_IP
12:17:24:114 x [CENTRAL] Enter FSM: State(CONFIGURING_IP) | Event(CONFIG_DYNAMIC_IP_OK) | Cause(0)
12:17:24:115 x [CENTRAL] State transit CONFIGURING_IP --> CONFIGURING_TFTP
12:17:24:125 x [CENTRAL] Save IP Info
12:17:24:126 x [CENTRAL] IP Address = 10.62.251.41
12:17:24:126 x [CENTRAL] Netmask = 255.255.254.0
12:17:24:130 x [CENTRAL] Gateway = 10.62.250.4
12:17:24:130 x [CENTRAL] DNS 1 = 0.0.0.0
12:17:24:131 x [CENTRAL] DNS 2 = 0.0.0.0
12:17:24:131 x [CENTRAL] DNS 3 = 0.0.0.0
12:17:24:132 x [CENTRAL] DNS 4 = 0.0.0.0
12:17:24:133 x [CENTRAL] DNS 5 = 0.0.0.0
12:17:24:133 x [CENTRAL] Domain =
12:17:24:271 x [CENTRAL] Config TFTP, DHCP mode
12:17:24:273 x [CENTRAL] TFTP 1 = 10.56.240.52
12:17:24:274 x [CENTRAL] TFTP 2 = 10.56.240.57
12:17:24:274 x [CENTRAL] TFTP string =
12:17:24:275 x [CENTRAL] TFTP op66 = 0.0.0.0
12:17:24:276 x [CENTRAL] Waiting event in CONFIGURING_TFTP
12:17:24:276 x [CENTRAL] Enter FSM: State(CONFIGURING_TFTP) | Event(CONFIG_TFTP_OK) | Cause(0)
12:17:24:280 x [CENTRAL] Save TFTP 1 = 10.56.240.52
12:17:24:281 x [CENTRAL] Save TFTP 2 = 10.56.240.57
12:17:24:281 x [CENTRAL] Save TFTP string(op66) = 0.0.0.0
12:17:24:283 x [CENTRAL] State transit CONFIGURING_TFTP --> PROVISIONING
12:17:24:310 x [CENTRAL] Start provision
12:17:24:311 x [CENTRAL] Waiting event in PROVISIONING
12:17:24:321 f [fos_task] [fos]: In func: fos_taskCreate(), create thread (tftp0) OK, threadID = 77850
2014/10/10 12:17:24:610 1 succeed to get SEPC4143C97EC61.cnf.xml

12:17:29:334 f [PROVISION] saveCucmArrayToConfig() i=0, szBuf=10.56.240.1
12:17:29:335 f [PROVISION] saveCucmArrayToConfig() i=0, szBuf=Directed Broadcast
12:17:29:336 f [PROVISION] saveCucmArrayToConfig() i=1, szBuf=0.0.0.0
12:17:29:337 f [PROVISION] saveCucmArrayToConfig() i=1, szBuf=Directed Broadcast
12:17:29:451 f [fos_task] [fos]: In func: fos_taskCreate(), create thread (tftp1) OK, threadID = 78875
2014/10/10 12:17:29:681 1 succeed to get CP3905.9-2-2-0.loads

12:17:29:685 x [PROVISION] image name after delete prefix= 3905.9-2-2-0.ZZ

12:17:29:692 w [PROVISION] Needn't to update tzUpdate file.
12:17:29:704 f [i18n] : In i18nFont_initiateLayoutEngine open font file OK.
12:17:29:705 f [i18n] : In i18nFont_initiateLayoutEngine open font file filesize = 15300.
12:17:29:706 f [i18n] : In i18nFont_initiateLayoutEngine calloc file size OK.
12:17:29:711 f [i18n] : In i18nFont_initiateLayoutEngine read file size OK.
12:17:29:711 f [i18n] : In i18nFont_initiateLayoutEngine open font file FontDataSize=15300.
12:17:29:712 f [i18n] : In i18nFont_initiateLayoutEngine bufsize=3076.
12:17:29:720 f [i18n] : In i18nFont_initiateLayoutEngine call RbmpReset kret=0.
12:17:30:491 w [PROVISION] provCfg_isNeedDnldOtherFile() ------softKeyFile =SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml
12:17:30:584 f [fos_task] [fos]: In func: fos_taskCreate(), create thread (tftp0) OK, threadID = 79898
2014/10/10 12:17:30:900 1 File Not Found : Chile/g3-tones.xml

12:17:30:903 f [fos_task] [fos]: In func: fos_taskCreate(), create thread (tftp1) OK, threadID = 80923
2014/10/10 12:17:31:220 1 File Not Found : Chile/g3-tones.xml

12:17:31:222 f [PROVISION] provCfg_parseXMLFile(): open the [/mnt/flash/local_saved/g3-tones.xml] file error
12:17:31:223 w [PROVISION] local tone is wrong, DUT can only use default tone
12:17:31:225 f [fos_task] [fos]: In func: fos_taskCreate(), create thread (tftp0) OK, threadID = 81946
2014/10/10 12:17:31:487 1 succeed to get SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml

12:17:32:466 x [CENTRAL] Provision CB function is called (2)
12:17:32:467 x [CENTRAL] Enter FSM: State(PROVISIONING) | Event(PROV_CFG_NO_CHANGE) | Cause(0)
12:17:32:472 x [CENTRAL] DSCP value no change(96)
12:17:32:491 x [SW] switchConf_updateCfg(), Span to PC Disable : 1
12:17:32:491 x [SW] switchConf_updateCfg(), PC port Disable : 0
12:17:32:492 x [SW] switchConf_updateCfg(), PC Voice VLAN Access : 0
12:17:32:492 x [SW] switchConf_updateCfg(), SIP DSCP for Audio : 46
12:17:32:493 x [CENTRAL] vlanCandidateCheck().
12:17:32:494 x [CENTRAL] State transit PROVISIONING --> REGISTERING
12:17:32:516 [ipps] Enter func: ipps_sysConfigure() to configure external modules!!

12:17:32:522 [ipps] Exit func: ipps_sysConfigure(), finish configuration!!

12:17:32:523 [ipps] In func: ipps_sysStart()....start service..

12:17:32:524 [ipps] In func: mlcu_cleanLineInfo(), clean line info for unConfigure!

12:17:32:525 f [ipps] In func: mlcu_isKpmlEnabled(), KPML value = 3, blRet = 1

12:17:32:526 x [pcu] [pcuGetAccData][585]Paul AUTH_NAME=, PW=
12:17:32:530 x [pcu] [resolveCucmIPAddr][315] CUCM0 addr=10.56.240.57
12:17:32:531 w [pcu] [resolveCucmIPAddr()384] Decide register URI=10.56.240.57:5060

12:17:32:533 x [pcu] [resolveCucmIPAddr][315] CUCM1 addr=10.56.240.53
12:17:32:533 w [pcu] [resolveCucmIPAddr()400] Server(1)=10.56.240.53, Don't set register URI

12:17:32:535 x [pcu] [pcuGetAccData][664] Final data->proxy_info[0].server_ip=10.56.240.57, server=10.56.240.57, isSRST=0
12:17:32:536 x [pcu] [pcuGetAccData][664] Final data->proxy_info[1].server_ip=10.56.240.53, server=10.56.240.53, isSRST=0
12:17:32:543 x [pcu] [pcux_register][5956] name=58118, bulkreg=0
12:17:32:561 x [pcu] [_pcu_start():923] There is 2 available server

12:17:32:562 x [CENTRAL] Waiting event in REGISTERING
12:17:32:595 [sip] 00:54:05.593 sip_endpoint.c Module "mod-pjsua-log" registered
12:17:32:600 [sip] 00:54:05.596 sip_endpoint.c Module "mod-tsx-layer" registered
12:17:32:603 [sip] 00:54:05.601 sip_endpoint.c Module "mod-stateful-util" registered
12:17:32:605 [sip] 00:54:05.604 sip_endpoint.c Module "mod-ua" registered
12:17:32:610 [sip] 00:54:05.606 sip_endpoint.c Module "mod-100rel" registered
12:17:32:612 [sip] 00:54:05.611 sip_endpoint.c Module "mod-pjsua" registered
12:17:32:615 [sip] 00:54:05.613 sip_endpoint.c Module "mod-invite" registered
12:17:32:617 [sip] 00:54:05.615 sip_endpoint.c Module "mod-evsub" registered
12:17:32:622 [sip] 00:54:05.621 pjsua_core.c Init KPML module!!!!!!

12:17:32:624 [sip] 00:54:05.622 sip_endpoint.c Module "mod-kpml" registered
12:17:32:626 [sip] 00:54:05.624 pjsua_core.c Init dlgEvent module!!!!!!

12:17:32:630 [sip] 00:54:05.626 sip_endpoint.c Module "mod-event" registered
12:17:32:632 [sip] 00:54:05.631 sip_endpoint.c Module "mod-mwi" registered
12:17:32:634 [sip] 00:54:05.633 sip_endpoint.c Module "mod-refer" registered
12:17:32:636 [sip] 00:54:05.635 pjsua_kpml.c !!! pjsua_kpml_init
12:17:32:641 [sip] 00:54:05.640 sip_endpoint.c Module "mod-pjsua-kpml" registered
12:17:32:643 [sip] 00:54:05.642 sip_endpoint.c Module "mod-pjsua-im" registered
12:17:32:645 [sip] 00:54:05.644 sip_endpoint.c Module "mod-pjsua-options" registered
12:17:32:652 [sip] 00:54:05.651 pjsua_core.c 1 SIP worker threads created
12:17:32:654 [sip] 00:54:05.653 pjsua_core.c pjsua version 1.8.10 for i686-pc-linux-gnu initialized
12:17:32:656 [sip] 00:54:05.655 sip_endpoint.c Module "mod-pjsua-advsip" registered
12:17:32:664 [sip] 00:54:05.663 tcplis:5060 SIP TCP listener ready for incoming connections at 10.62.251.41:5060
12:17:32:666 [sip] 00:54:05.665 ctlslis:2002 SIP Cisco TLS has already registered the factory functions !

12:17:32:672 [sip] 00:54:05.670 pjsua_core.c SIP UDP socket reachable at 10.62.251.41:5060
12:17:32:675 [sip] 00:54:05.673 sip_transport. Transport udp0x139ea18 registered: type=UDP
12:17:32:680 [sip] 00:54:05.676 udp0x139ea18 SIP UDP transport started, published address is 10.62.251.41:5060
12:17:32:682 [sip] 00:54:05.681 sip_endpoint.c Module "mod-unsolicited-mwi" registered
12:17:32:684 [sip] 00:54:05.683 pjcu.c pjcuRcvHandler(CONN), REGISTER, eid=0, cid=-1

12:17:32:751 [sip] 00:54:05.750 pjcu.c [PJCU_ProcConnEvt():2609] case FSIP_CORE_REGISTER, PJCU_TASK_ID(0), eid(0)

12:17:32:754 [sip] 00:54:05.753 pjcu.c [pjcu_config_acc():595] eid(0) is not mapping with pjcu accid, add a new account
12:17:32:757 [sip] 00:54:05.755 pjsua_kpml.c !!! pjsua_kpml_init_acc
12:17:32:762 [sip] 00:54:05.760 pjsua_acc.c Account "TELECOMUNICACIONES" added with id 0
12:17:32:772 [sip] 00:54:05.771 sip_transport. Transport tcpc0x1b1c424 registered: type=TCP
12:17:32:774 [sip] 00:54:05.773 tcpc0x1b1c424 TCP client transport created
12:17:32:780 [sip] 00:54:05.775 tcpc0x1b1c424 TCP transport 10.62.251.41:3705 is connecting to 10.56.240.57:5060...
12:17:32:790 [sip] 00:54:05.786 pjsua_acc.c Registration sent
12:17:32:792 [sip] 00:54:05.791 pjcu.c [pjcu_config_acc():610] Add a new entity eid(0) mapping acc_id(0)("TELECOMUNICACIONES")
12:17:32:872 [sip] 00:54:05.871 tcpc0x1b1c424 TCP transport 10.62.251.41:3705 is connected to 10.56.240.57:5060
12:17:32:900 w [pcu] [pcu_polling_sipserver_thread():1351] polling resumed..

12:17:32:904 [sip] 00:54:05.902 pjcu.c pjcuRcvHandler(KA), KA_REQUEST, eid=-1, p1=10.56.240.53:5060;transport=tcp

12:17:32:910 [sip] 00:54:05.915 sip_transport. Transport tcpc0x1b4e018 registered: type=TCP
12:17:32:922 [sip] 00:54:05.920 tcpc0x1b4e018 TCP client transport created
12:17:32:926 [sip] 00:54:05.924 tcpc0x1b4e018 TCP transport 10.62.251.41:3229 is connecting to 10.56.240.53:5060...
12:17:32:935 [sip] 00:54:05.934 tcpc0x1b4e018 TCP transport 10.62.251.41:3229 is connected to 10.56.240.53:5060
12:17:32:951 [sip] 00:54:05.946 pjcu.c pjcu_rpt_ka_status(), target(10.56.240.53:5060;transport=tcp): status=1, id=27

12:17:32:953 x [pcu] pcuRcvHandler(KA), KA_RESPONSE, eid=0, addr=10.56.240.53:5060;transport=tcp, status=1

12:17:32:955 x [pcu] [pcu_polling_sipserver_thread():1478] mark!

12:17:32:973 [sip] 00:54:05.971 tcpc0x1b4e018 TCP transport destroyed normally, remote:10.56.240.53:5060
12:17:33:093 [sip] 00:54:06.091 pjsua_acc.c SIP outbound status for acc 0 is not active
12:17:33:096 [sip] 00:54:06.094 pjsua_acc.c "TELECOMUNICACIONES": registration success, status=200 (OK), will re-register in 120 seconds
12:17:33:102 [sip] 00:54:06.100 pjcu.c pjcu_on_reg_state2(), Account["TELECOMUNICACIONES"] : OK, status=200
12:17:33:106 x [pcu] pcuRcvHandler(CALL), SRV_EV, eid=0, cid=65535,

Mohamed Amine Jaafar · ‎01-26-2015

Seems that we have the same issue.

Did you manage to solve this ? What was the problem ?

Thank you in advance.

aelkhalkhali1 · ‎06-14-2016

Hi;

I'm facing the same problem.

did you resolve this issue.

Thanks;

Leonardo Santana · ‎10-14-2016

Hello,

I have the same issue with the 3905 flapping between Registered and Provisioning

CUCM Version: 8.6.2.25900-8

3905 Firmware: CP3905.9-4-1SR2-2

What could be causing this issue?

Regards

Leonardo Santana

Regards
Leonardo Santana

*** Rate All Helpful Responses***

Mohamed Amine Jaafar · ‎10-18-2016

For us, we managed to mitigate as much as possible the issue, yet did not have fully solve it.

In our case the issue was related to 3905 keeping releasing its VLAN config learnt from CDP.

This is caused by a high multicast/broadcast traffic, including the traffic coming through the access VLAN passed through to the PC.

Here’re in fact the few lines that were causing problem :

12:15:41:530 x [CENTRAL] CDP/LLDP-MED CB function is called
12:15:41:530 x [CENTRAL] CDP/LLDP CB, Adopting Local Admin setting
12:15:41:531 x [CENTRAL] Enter FSM: State(STANDBY) | Event(NET_POLICY_CHANGE) | Cause(3)
12:15:41:532 x [CENTRAL] Config VLAN, cause (3), voice 200 => 4095, native 1 => 4095
12:15:41:650 [ipps] ----- SYS: SY_STOP_EV -----

For this, we have managed to reduce the CDP timer on the switches to only 15 seconds.

Switch-1# conf t
Switch-1(config)# cdp timer 15
Switch-1(config)# end
Switch-1# wr

With this on the switches, the phones are refreshed more frequently and less suspected to lose a CDP packet.

That time, we opened a TAC case (634095259) about the problem and we had a confirmation that, actually, "the Cisco 3905 hardware is not as powerful as other high-end phone models, so it will not be able to handle the heavy multicast packets on your network, and the phone’s performance will degrade significantly, respond slowly and/or freeze. This is hitting the performance limit of the Cisco 3905 with the heavy multicast packets".

That's it.

Also, forcing the switch port to Access VLAN only to the actual voice vlan should solve this issue, but this was not an option for our customer. We finally chose to flood even more our network with more CDP packets........

Leonardo Santana · ‎10-18-2016

Hello Mohamed,

At my IP Phones i see this logs:

03:53:48:970 w [NTP] Need stop NTP
03:53:48:971 w [NTP] msntp_stop() 1245
03:53:48:972 w [NTP] Stop NTP task successfully
03:53:48:973 x [CENTRAL] State transit STANDBY --> PROVISIONING
03:53:48:975 x [CENTRAL] Start provision
03:53:48:976 x [CENTRAL] Waiting event in PROVISIONING
r FSM: State(STANDBY) | Event(REGISTER_OK) | Cause(0)
e=REGISTERED, server_index=0, active=0, standby=1, preferMode=1

At the switch i see this logs:

Oct 18 10:16:54.826 GMT-3: %LINEPROTO-5-UPDOWN: Line protocol on Interface FastEthernet0/44, changed state to down
Oct 18 10:16:55.095 GMT-3: %ILPOWER-5-IEEE_DISCONNECT: Interface Fa0/44: PD removed
Oct 18 10:16:55.833 GMT-3: %LINK-3-UPDOWN: Interface FastEthernet0/44, changed state to down
Oct 18 10:16:56.059 GMT-3: %ILPOWER-7-DETECT: Interface Fa0/44: Power Device detected: IEEE PD
Oct 18 10:16:57.074 GMT-3: %ILPOWER-5-POWER_GRANTED: Interface Fa0/44: Power granted
Oct 18 10:17:32.743 GMT-3: %LINK-3-UPDOWN: Interface FastEthernet0/44, changed state to up
Oct 18 10:17:33.750 GMT-3: %LINEPROTO-5-UPDOWN: Line protocol on Interface FastEthernet0/44, changed state to up

The IP Phone is turning off i dont know why

We have a few IP Phones at this switch, we have watts available to all IP Phones.

show power inline
Available:370.0(w) Used:60.9(w) Remaining:309.1(w)

Regards

Regards
Leonardo Santana

*** Rate All Helpful Responses***

Mohamed Amine Jaafar · ‎10-18-2016

Hello,

I don't know if it's related to NTP but in my opinion I don't think so.

I have re-reviewed my log files and I also found the few lines about NTP stopping

<sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1601@10.1.33.13><sip:1601@10.1.33.13><sip:1601@10.1.33.13><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060><sip:1261@10.1.33.13:5060>11:03:47:743   [sip]  02:28:28.742 sip_endpoint.c  Destroying endpoing instance..
11:03:47:745   [sip]  02:28:28.743 sip_transactio  Stopping transaction layer module
11:03:47:746   [sip]  02:28:28.745 pjsua_advsip.c  PJCU advsip module unregistered !
11:03:47:751   [sip]  02:28:28.750 sip_transactio  Transaction layer module destroyed
11:03:47:762   [sip]  02:28:28.760    tcplis:5060  SIP TCP listener destroyed
11:03:47:765   [sip]  02:28:28.763 sip_endpoint.c  Endpoint 0x131c46c destroyed
11:03:47:770   [sip]  02:28:28.766   pjsua_core.c  PJSUA destroyed...
11:03:51:730 w [NTP] Need stop NTP 
11:03:51:731 w [NTP] NTP task has not been created

In fact, the unregistration already happened at that time! the NTP log line is occuring when the IP Phone doesn't even have a VLAN ID config and even lesser an IP address.

The defaulting to VLAN 4095 already happened before that.

12:15:41:713 [sip] 00:52:14.710 pjsua_acc.c Unregistration sent
12:15:41:722 [sip] 00:52:14.720 pjsua_acc.c "TELECOMUNICACIONES": unregistration success
12:15:41:725 [sip] 00:52:14.723 pjcu.c pjcu_on_reg_state2(), Account["TELECOMUNICACIONES"] : OK, status=200
12:15:41:731 [sip] 00:52:14.726 tcpc0x1b1c424 TCP connection closed, remote:10.56.240.57:5060

[.............]

12:15:46:680 w [NTP] Need stop NTP
12:15:46:681 w [NTP] msntp_stop() 1245
12:15:46:681 w [NTP] Stop NTP task successfully

So as far as I'm concerned, the NTP log lines are just a consequence and not a cause by itself.

Did you try to force the port of a 3905 IP phone to access vlan instead of voice vlan ?

Silvano Ferreira de Souza · ‎08-23-2018

Someone managed to solve this problem that happens with the 3905 IP phone, I have 450 IP phone 3905 in my network and had to reduce the CDP time to 5 seconds to mitigate the problem. The others phone model work fine.

Silvano Ferreira de Souza · ‎10-15-2018

Hi Guys

I just did the firmware upgrade to CP3905.9-4-1SR2-2 and solved my problem. CDP time is default on all switches and all working fine.