Wed Feb 10 08:46:27 2016 [INFO] [PACM.PROVISION(pid=999)]: start TFTP transfer from 123.456.789.123, of file xxx/mta.cfg
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: Spawned ti_tftp client.
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: GW -  Bridge Dhcp Relay : PerBridge[1] is not Bridge and Skip
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: GW -  Bridge Dhcp Relay : PerBridge[2] is not Bridge and Skip
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: GW -  Bridge Dhcp Relay : HOTSPOT Enable and Skip
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: GW -  Bridge Dhcp Relay : PerBridge[4] is not Bridge and Skip
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: GW - DB_GW_STATE 2
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: GW - ******************************
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: GW - * IPv4 Routing (erouter0)
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: GW - ******************************
Wed Feb 10 08:46:27 2016 [INFO] [GW.PROV(pid=441)]: ERX - Processing state GWP_STATE_ACTIVE_PROVISIONED_RoutingIPv4_DONE (0x800000)
Wed Feb 10 08:46:27 2016 [INFO] [PACM.PROVISION(pid=1320)]: cfm_report_config() succesfilly - ;
Wed Feb 10 08:46:27 2016 [INFO] [PACM.PROVISION(pid=1320)]: cfm_report_config() succesfilly - File received;
Wed Feb 10 08:46:27 2016 [ERROR] [PACM.PROVISION(pid=1320)]: TFTP Connection ended.
Wed Feb 10 08:46:27 2016 [INFO] [PACM.PROVISION(pid=999)]: start TFTP COMMIT
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: Reading file
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: Opened local file xxx/mta.cfg 
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: Read 1068 bytes
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: Authenticating file
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: Getting digest from file.
Wed Feb 10 08:46:27 2016 [ERROR] [COMMON_COMPONENTS.TLV_PARSER(pid=999)]: 1st pass PARSER_UNKNOWNN_TYPE_TWO_BYTE_LEN - unknown type ptr 210a9
Wed Feb 10 08:46:27 2016 [ERROR] [COMMON_COMPONENTS.TLV_PARSER(pid=999)]: 1st pass PARSER_UNKNOWNN_TYPE_TWO_BYTE_LEN - unknown type ptr 214d2
Wed Feb 10 08:46:27 2016 [INFO] [COMMON_COMPONENTS.TLV_PARSER(pid=999)]: PARSER_UNKNOWNN_TYPE_TWO_BYTE_LEN - unknown type ptr 210a9
Wed Feb 10 08:46:27 2016 [INFO] [COMMON_COMPONENTS.TLV_PARSER(pid=999)]: PARSER_UNKNOWNN_TYPE_TWO_BYTE_LEN - unknown type ptr 214d2
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: Checking Hash
Wed Feb 10 08:46:27 2016 [INFO] [PACM.PROVISION(pid=999)]: configuration file integrity verified
Wed Feb 10 08:46:27 2016 [INFO] [PACM.PROVISION(pid=999)]: TFTP File Commit - check file structure
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: CFM_ParameterParserStart: enter to TlvParseExtended
Wed Feb 10 08:46:27 2016 [ERROR] [PACM.SNMP(pid=795)]: Failed to get MTA provision status in End point interface configure
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: CFM_ParameterParserStart:  TlvParseExtended finished
Wed Feb 10 08:46:27 2016 [INFO] [PACM.CFM(pid=999)]: CFM_ParameterParserStart: num 254 valid
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: 
SIP MIB:sipCfgDigitMap = x.T
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for DIGIT MAP from SIP application code.
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for BUSY DIGIT MAP from SIP application code.
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for PROXY DIGIT MAP from SIP application code.
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: SIP/EUE MIB: Set shdb notify event succeeded. 
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: 
SIP MIB: sipCfgProxyType = 0
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: 
SIP MIB:sipCfgRegistrarAdr = 123.456.789.123;5060
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: 
SIP MIB: sipCfgRegistrarType = 0
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: 
SIP MIB:sipCfgPortUserName = 0123456789
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: 
SIP MIB:sipCfgPortDisplayName = 0123456789
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: 
SIP MIB:sipCfgPortLogin = 0123456789
Wed Feb 10 08:46:27 2016 [INFO_VERBOSE] [ARRIS.SNMP(pid=795)]: 
SIP MIB:sipCfgPortPassword = password
Wed Feb 10 08:46:27 2016 [INFO] [PACM.PROVISION(pid=999)]: TFTP File Commit - check DB parameters
Wed Feb 10 08:46:28 2016 [INFO_VERBOSE] [PACM.VOIM(pid=999)]: Recieved message Type = 5
Wed Feb 10 08:46:28 2016 [INFO_VERBOSE] [PACM.VOIM(pid=999)]: Recieved message Type = 5
Wed Feb 10 08:46:28 2016 [INFO] [PACM.CFM(pid=999)]: Conf file final tests succeed
Wed Feb 10 08:46:28 2016 [INFO_VERBOSE] [COMMON_COMPONENTS.GIM(pid=999)]: nid=8197: type SRN with 0 bytes data
Wed Feb 10 08:46:28 2016 [INFO] [PACM.PROVISION(pid=999)]: start TFTP CLEANUP
Wed Feb 10 08:46:28 2016 [INFO] [PACM.CFM(pid=999)]: cleaning up...
Wed Feb 10 08:46:28 2016 [WARNING] [PACM.CFM(pid=999)]: SHA1_freeCS: TBD - clear cypto information after use
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: prov timer flag = TRUE
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: turning down prov timer
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: LOOPV: Setting loop voltage status ON
Wed Feb 10 08:46:28 2016 [INFO_VERBOSE] [COMMON_COMPONENTS.GIM(pid=999)]: nid=8199: type NRN with 4 bytes data
Wed Feb 10 08:46:28 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='OOS', src=LineCard, event=Cold Reset
Wed Feb 10 08:46:28 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=2, state='OOS', src=LineCard, event=Cold Reset
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: *************************************************
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: *************************************************
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: PC PROVISIONING COMPLETED SUCCESSFULLY. STATUS: Pass
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: *************************************************
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: *************************************************
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: MTA 24 - PROV_COMPLETE_PASS
Wed Feb 10 08:46:28 2016 [INFO] [PACM.MTA_CONTROL(pid=999)]: MSM event to activate voice via MSM_act_MTA24MTA25Ent
Wed Feb 10 08:46:28 2016 [INFO] [PACM.SNMP(pid=795)]: Success building vbl
Wed Feb 10 08:46:28 2016 [INFO] [PACM.SNMP(pid=795)]: pk_mdb_DevEvLevel_get: success
Wed Feb 10 08:46:28 2016 [INFO] [PACM.SNMP(pid=795)]: Success building vbl
Wed Feb 10 08:46:33 2016 [INFO_VERBOSE] [DOCSIS.US(pid=474)]: rngRspData: usId1: d-Gain: 0.00 (New:44.75 dBmV), Time: 0.000000, Freq: 0 (SUCCESS)
Wed Feb 10 08:46:35 2016 [WARNING] [GW.DHCP_CLIENT(pid=1120)]: DHCP failed ?DHCP Solicit sent, No DHCP Advertise received
Wed Feb 10 08:46:35 2016 [INFO_VERBOSE] [DOCSIS.US(pid=474)]: 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
Wed Feb 10 08:46:37 2016 [INFO_VERBOSE] [DOCSIS.US(pid=474)]: rngRspData: usId1: d-Gain: 0.00 (New:44.75 dBmV), Time: 0.000000, Freq: 0 (SUCCESS)
[wan0] debug, found a plugin option

08:46:40.200000   ra0      Custom driver event:(iNIC) BSS(ra0) channel switch to   6 (event->u.data.flags:0x213)
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 0
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 1
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 2
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 2
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 2
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 3
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 3
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 3
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 4
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 4
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 4
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 5
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 5
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 5
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 6
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 6
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 6
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 7
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 7
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 7
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 8
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 8
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 8
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 9
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 9
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 9
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 10
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 10
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 10
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_UserLineWarmOrHotlineNumber_get: invalid line 11
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.SIP(pid=905)]: ARRS_sip_db_WarmOrHotlineEnable_get: invalid line 11
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: Legacy SIP Update for Warm or HotLine Number from SIP application code for index 11
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: RVSTACK_RUN
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: LC:Template changed to 4
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: PowerRingFrequency set to index 0
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: Min hookflash time set to 300 ms (0x12c)
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: Min disconnect time set to 1000 ms (0x3e8)
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: LC:Template changed to 4
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: PowerRingFrequency set to index 0
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: Min hookflash time set to 300 ms (0x12c)
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: Min disconnect time set to 1000 ms (0x3e8)
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.MTA(pid=905)]: prevAdminStates 0x1
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='OOS', src=PCMG, event=Line IS
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.LC(pid=905)]: Provisioning bitmap 0x1 received
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.CALLP_DBG(pid=905)]: Sending provisioning bit mask (1) to the Linecard
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP state change: endpoint = 1, 'OOS' -> 'IDLE'
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: RegClient:0x3fca68 registrationTimer = 293 id=2e72a0 
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=2, state='OOS', src=LineCard, event=OnHook
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=CallP, event=Cold Reset Timer Expiry
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=2, state='OOS', src=CallP, event=Cold Reset Timer Expiry
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=Cold Reset
Wed Feb 10 08:46:40 2016 [ERROR] [ARRIS.CALLP_SWERR(pid=905)]: LC Cold Reset while IS on line 1!
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=2, state='OOS', src=LineCard, event=OnHook
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: SIP Dial Features handling event: 3 for line: 0
Wed Feb 10 08:46:40 2016 [INFO_VERBOSE] [ARRIS.SIP(pid=905)]: DIALF reset on line: 0
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=CallP, event=Cold Reset Timer Expiry
Wed Feb 10 08:46:40 2016 [INFO] [ARRIS.SIP(pid=905)]: SIP INPUT: endpoint=1, state='IDLE', src=LineCard, event=OnHook
Wed Feb 10 08:46:40 2016 [INFO] [PACM.SNMP(pid=795)]: pk_mdb_DevEvLevel_get: success
Wed Feb 10 08:46:40 2016 [INFO] [PACM.SNMP(pid=795)]: Success building vbl