Cisco Support Community
cancel
Showing results for 
Search instead for 
Did you mean: 
New Member

IP Phone 3905 unregistration randomly.

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, 

Everyone's tags (1)
6 REPLIES

Seems that we have the same

Seems that we have the same issue.

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

Thank you in advance.

New Member

Hi;

Hi;

I'm facing the same problem.

did you resolve this issue.

Thanks;

Hello,

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

For us, we managed to

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........

Hello Mohamed,

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

Hello,

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 ?

457
Views
0
Helpful
6
Replies
CreatePlease to create content