Tue Feb 9 14:55:36 2016 [INFO] [GW.PROV(pid=431)]: ERX - Processing state GWP_STATE_ACTIVE_PROVISIONED_RoutingIPv4_DONE (0x800000) Tue Feb 9 14:55:36 2016 [INFO] [PACM.PROVISION(pid=1330)]: cfm_report_config() succesfilly - ; Tue Feb 9 14:55:36 2016 [INFO] [PACM.PROVISION(pid=1330)]: cfm_report_config() succesfilly - File received; Tue Feb 9 14:55:36 2016 [ERROR] [PACM.PROVISION(pid=1330)]: TFTP Connection ended. Tue Feb 9 14:55:36 2016 [INFO] [PACM.PROVISION(pid=977)]: start TFTP COMMIT Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: Reading file Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: Opened local file mta/mta-300020.cfg Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: Read 365 bytes Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: Authenticating file Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: Getting digest from file. Tue Feb 9 14:55:36 2016 [ERROR] [COMMON_COMPONENTS.TLV_PARSER(pid=977)]: 1st pass PARSER_UNKNOWNN_TYPE_TWO_BYTE_LEN - unknown type ptr 208f9 Tue Feb 9 14:55:36 2016 [ERROR] [COMMON_COMPONENTS.TLV_PARSER(pid=977)]: 1st pass PARSER_UNKNOWNN_TYPE_TWO_BYTE_LEN - unknown type ptr 20a63 Tue Feb 9 14:55:36 2016 [INFO] [COMMON_COMPONENTS.TLV_PARSER(pid=977)]: PARSER_UNKNOWNN_TYPE_TWO_BYTE_LEN - unknown type ptr 208f9 Tue Feb 9 14:55:36 2016 [INFO] [COMMON_COMPONENTS.TLV_PARSER(pid=977)]: PARSER_UNKNOWNN_TYPE_TWO_BYTE_LEN - unknown type ptr 20a63 Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: Checking Hash Tue Feb 9 14:55:36 2016 [INFO] [PACM.PROVISION(pid=977)]: configuration file integrity verified Tue Feb 9 14:55:36 2016 [INFO] [PACM.PROVISION(pid=977)]: TFTP File Commit - check file structure Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: CFM_ParameterParserStart: enter to TlvParseExtended Tue Feb 9 14:55:36 2016 [ERROR] [PACM.SNMP(pid=771)]: Failed to get MTA provision status in End point interface configure Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: CFM_ParameterParserStart: TlvParseExtended finished Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: CFM_ParameterParserStart: num 254 valid Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP MIB:sipCfgDigitMap = x.T Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for DIGIT MAP from SIP application code. Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for BUSY DIGIT MAP from SIP application code. Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for PROXY DIGIT MAP from SIP application code. Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP/EUE MIB: Set shdb notify event succeeded. Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP MIB:sipCfgPortUserName = 0123456789 Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP MIB:sipCfgPortDisplayName = 0123456789 Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP MIB:sipCfgPortLogin = 0123456789 Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP MIB:sipCfgPortPassword = abcd Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP MIB: sipCfgProxyType = 1 Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP MIB:sipCfgRegistrarAdr = sip.server.net Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=771)]: SIP MIB: sipCfgRegistrarType = 1 Tue Feb 9 14:55:36 2016 [INFO] [PACM.PROVISION(pid=977)]: TFTP File Commit - check DB parameters Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [PACM.VOIM(pid=977)]: Recieved message Type = 5 Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [PACM.VOIM(pid=977)]: Recieved message Type = 5 Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: Conf file final tests succeed Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [COMMON_COMPONENTS.GIM(pid=977)]: nid=8197: type SRN with 0 bytes data Tue Feb 9 14:55:36 2016 [INFO] [PACM.PROVISION(pid=977)]: start TFTP CLEANUP Tue Feb 9 14:55:36 2016 [INFO] [PACM.CFM(pid=977)]: cleaning up... Tue Feb 9 14:55:36 2016 [WARNING] [PACM.CFM(pid=977)]: SHA1_freeCS: TBD - clear cypto information after use Tue Feb 9 14:55:36 2016 [INFO] [PACM.MTA_CONTROL(pid=977)]: prov timer flag = TRUE Tue Feb 9 14:55:36 2016 [INFO] [PACM.MTA_CONTROL(pid=977)]: turning down prov timer Tue Feb 9 14:55:36 2016 [INFO] [PACM.MTA_CONTROL(pid=977)]: LOOPV: Setting loop voltage status ON Tue Feb 9 14:55:36 2016 [INFO_VERBOSE] [COMMON_COMPONENTS.GIM(pid=977)]: nid=8199: type NRN with 4 bytes data Tue Feb 9 14:55:36 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='OOS', src=LineCard, event=Cold Reset Tue Feb 9 14:55:36 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=2, state='OOS', src=LineCard, event=Cold Reset Tue Feb 9 14:55:36 2016 [INFO] [PACM.MTA_CONTROL(pid=977)]: ************************************************* Tue Feb 9 14:55:36 2016 [INFO] [PACM.MTA_CONTROL(pid=977)]: ************************************************* Tue Feb 9 14:55:36 2016 [INFO] [PACM.MTA_CONTROL(pid=977)]: PC PROVISIONING COMPLETED SUCCESSFULLY. STATUS: Pass Tue Feb 9 14:55:36 2016 [INFO] [PACM.MTA_CONTROL(pid=977)]: ************************************************* Tue Feb 9 14:55:36 2016 [INFO] [PACM.MTA_CONTROL(pid=977)]: ************************************************* Tue Feb 9 14:55:36 2016 [INFO] [PACM.SNMP(pid=771)]: Success building vbl Tue Feb 9 14:55:36 2016 [INFO] [PACM.SNMP(pid=771)]: pk_mdb_DevEvLevel_get: success Tue Feb 9 14:55:36 2016 [INFO] [PACM.SNMP(pid=771)]: Success building vbl Tue Feb 9 14:55:40 2016 [INFO_VERBOSE] [DOCSIS.US(pid=450)]: rngRspData: usId1: d-Gain: 0.00 (New:44.75 dBmV), Time: 0.000000, Freq: 0 (SUCCESS) Tue Feb 9 14:55:42 2016 [INFO_VERBOSE] [DOCSIS.US(pid=450)]: rngRspData: usId1: d-Gain: 0.00 (New:44.75 dBmV), Time: 0.000000, Freq: 0 (SUCCESS) Tue Feb 9 14:55:43 2016 [WARNING] [GW.DHCP_CLIENT(pid=1130)]: DHCP failed ?DHCP Solicit sent, No DHCP Advertise received Tue Feb 9 14:55:44 2016 [INFO_VERBOSE] [DOCSIS.US(pid=450)]: rngRspData: usId1: d-Gain: 0.00 (New:44.75 dBmV), Time: 0.000000, Freq: 0 (SUCCESS) [wan0] debug, entering kernel listen mode [wan0] debug, Sending renew... [wan0] debug, Received a packet Tue Feb 9 14:55:46 2016 [INFO_VERBOSE] [DOCSIS.US(pid=450)]: rngRspData: usId1: d-Gain: 0.00 (New:44.75 dBmV), Time: 0.000000, Freq: 0 (SUCCESS) [wan0] debug, found a plugin option 14:55:48.920000 ra0 Custom driver event:(iNIC) BSS(ra0) channel switch to 6 (event->u.data.flags:0x213) Tue Feb 9 14:55:48 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 0 Tue Feb 9 14:55:48 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 1 Tue Feb 9 14:55:48 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 2 Tue Feb 9 14:55:48 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 2 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 2 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 3 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 3 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 3 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 4 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 4 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 4 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 5 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 5 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 5 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 6 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 6 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 6 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 7 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 7 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 7 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 8 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 8 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 8 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 9 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 9 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 9 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 10 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 10 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 10 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 11 Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.SIP(pid=884)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 11 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 11 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: RVSTACK_RUN Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: LC:Template changed to 4 Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: PowerRingFrequency set to index 0 Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: Min hookflash time set to 300 ms (0x12c) Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: Min disconnect time set to 1000 ms (0x3e8) Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: LC:Template changed to 4 Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: PowerRingFrequency set to index 0 Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: Min hookflash time set to 300 ms (0x12c) Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: Min disconnect time set to 1000 ms (0x3e8) Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.MTA(pid=884)]: prevAdminStates 0x1 Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='OOS', src=PCMG, event=Line IS Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.LC(pid=884)]: Provisioning bitmap 0x1 received Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.CALLP_DBG(pid=884)]: Sending provisioning bit mask (1) to the Linecard Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP state change: endpoint = 1, 'OOS' -> 'IDLE' Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: RegClient:0x3fca68 registrationTimer = 99 id=2e72a0 Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=2, state='OOS', src=LineCard, event=OnHook Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=2, state='OOS', src=CallP, event=Cold Reset Timer Expiry Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=CallP, event=Cold Reset Timer Expiry Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=Cold Reset Tue Feb 9 14:55:49 2016 [ERROR] [ARRIS.CALLP_SWERR(pid=884)]: LC Cold Reset while IS on line 1! Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=2, state='OOS', src=LineCard, event=OnHook Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: SIP Dial Features handling event: 3 for line: 0 Tue Feb 9 14:55:49 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=884)]: DIALF reset on line: 0 Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=CallP, event=Cold Reset Timer Expiry Tue Feb 9 14:55:49 2016 [INFO] [ARRIS.SIP(pid=884)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook Tue Feb 9 14:55:49 2016 [INFO] [PACM.SNMP(pid=771)]: pk_mdb_DevEvLevel_get: success Tue Feb 9 14:55:49 2016 [INFO] [PACM.SNMP(pid=771)]: Success building vbl