06-25-2018 12:10 AM - edited 03-05-2019 10:39 AM
I already have a 887 working with VDSL on a second location. I configured another 887 with the same config (changing logins, passwords and IP ranges) and while the connection seems to come up (ppp led goes on), the CD led starts blinking again after a short time and the connection goes down again. I contacted the ISP and they checked the line and everthing should be fine. Their own device also comes up without issues. When I took the 887 from the other location and connected it on the new location, the connection came up.
This is some debug output but I am not an expert so I can't make sense out of it. Any help would be appreciated. I can post both configs if that would help.
*Jun 23 09:03:45.188: %LINK-3-UPDOWN: Interface Dialer0, changed state to up
*Jun 23 09:03:48.252: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:03:48.908: VDSL 0: SM_LINE_SHOWTIME boolean event
*Jun 23 09:03:48.908: VDSL 0: line state : showtime !
*Jun 23 09:03:49.908: vdsl_daemon_sm VDSL 0: during state training, got event 18(showtime)
*Jun 23 09:03:49.908: @@@ vdsl_daemon_sm VDSL 0: training -> ready
*Jun 23 09:03:49.908: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=14, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0
*Jun 23 09:03:49.908: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 36 @0x1DD131C0
*Jun 23 09:03:49.908: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:03:49.908: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 14x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:49.908: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:49.908: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 001E: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:03:49.908: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:49.908: TX: Msg for opcode(14)...waiting for Response from Mailbox!
*Jun 23 09:03:50.020: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E002, total len= 36, msg len= 36, @618
*Jun 23 09:03:50.020: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 36 00x 02x 14x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.020: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 02x 00x
*Jun 23 09:03:50.020: 00x 00x 00x
*Jun 23 09:03:50.020: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD131E4, len= 36
*Jun 23 09:03:50.020: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD131C0
*Jun 23 09:03:50.020: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=14
*Jun 23 09:03:50.020: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D33C opcode=14 to caller
*Jun 23 09:03:50.020: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 14
*Jun 23 09:03:50.020: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:03:50.020: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.020: TX: Call for opcode 14 Success!
*Jun 23 09:03:50.020: VDSL 0: selected tc = 0, sysif = -1
*Jun 23 09:03:50.020: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=17, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0
*Jun 23 09:03:50.020: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 36 @0x1DD131C0
*Jun 23 09:03:50.020: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:03:50.020: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 17x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.020: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.020: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:03:50.020: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.020: TX: Msg for opcode(17)...waiting for Response from Mailbox!
*Jun 23 09:03:50.116: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 36, msg len= 36, @618
*Jun 23 09:03:50.116: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 36 00x 02x 17x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.116: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.116: 00x 00x 01x
*Jun 23 09:03:50.116: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD131E4, len= 36
*Jun 23 09:03:50.116: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD131C0
*Jun 23 09:03:50.116: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=17
*Jun 23 09:03:50.116: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D330 opcode=17 to caller
*Jun 23 09:03:50.116: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 17
*Jun 23 09:03:50.116: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:03:50.116: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.116: TX: Call for opcode 17 Success!
*Jun 23 09:03:50.116: ipc VDSL 0: vdsl_g997_atu_systemenabling_status_get,
*Jun 23 09:03:50.116: vdsl_g997_atu_systemenabling_status_get: Successful Return !
*Jun 23 09:03:50.116: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD138C0, rx buf @0x1DD138C0
*Jun 23 09:03:50.116: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD138C0, rx_len = 140 @0x1DD138C0
*Jun 23 09:03:50.116: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:03:50.116: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 10x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.120: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.120: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:03:50.120: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.120: TX: Msg for opcode(10)...waiting for Response from Mailbox!
*Jun 23 09:03:50.244: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E002, total len= 140, msg len= 140, @618
*Jun 23 09:03:50.244: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD138C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.244: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.244: 00x 116x 23x 00x 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.244: 00x 12x 4294967168x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 23 09:03:50.244: 00x 00x 4294967193x 00x 00x 00x 06x 00x 00x 30x 123x 00x 00x 00x 4294967193x 00x
*Jun 23 09:03:50.244: 00x 00x 00x 00x 00x 00x 00x 00x 01x 17x 109x 00x 01x 17x 109x 00x
*Jun 23 09:03:50.244: 00x 00x 00x
*Jun 23 09:03:50.244: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1394C, len= 140
*Jun 23 09:03:50.244: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 140, 0x1DD138C0
*Jun 23 09:03:50.244: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 23 09:03:50.244: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D33C opcode=10 to caller
*Jun 23 09:03:50.244: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10
*Jun 23 09:03:50.244: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:03:50.244: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.244: TX: Call for opcode 10 Success!
*Jun 23 09:03:50.244: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 23 09:03:50.244: vdsl_g997_channel_status_get: Successful Return !
*Jun 23 09:03:50.244: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD138C0, rx buf @0x1DD138C0
*Jun 23 09:03:50.244: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD138C0, rx_len = 140 @0x1DD138C0
*Jun 23 09:03:50.244: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:03:50.244: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 10x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 01x 00x 00x 00x
*Jun 23 09:03:50.244: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.244: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:03:50.244: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.244: TX: Msg for opcode(10)...waiting for Response from Mailbox!
*Jun 23 09:03:50.364: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 140, msg len= 140, @618
*Jun 23 09:03:50.364: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD138C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 01x 00x 00x 00x
*Jun 23 09:03:50.364: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.368: 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.368: 00x 01x 4294967184x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 23 09:03:50.368: 00x 00x 32x 00x 00x 00x 16x 00x 00x 00x 16x 00x 00x 00x 32x 00x
*Jun 23 09:03:50.368: 00x 00x 01x 00x 00x 00x 00x 00x 01x 17x 109x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.368: 00x 00x 00x
*Jun 23 09:03:50.368: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1394C, len= 140
*Jun 23 09:03:50.368: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 140, 0x1DD138C0
*Jun 23 09:03:50.368: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 23 09:03:50.368: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D330 opcode=10 to caller
*Jun 23 09:03:50.368: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10
*Jun 23 09:03:50.368: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:03:50.368: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.368: TX: Call for opcode 10 Success!
*Jun 23 09:03:50.368: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 23 09:03:50.368: vdsl_g997_channel_status_get: Successful Return !
*Jun 23 09:03:50.368: %CONTROLLER-5-UPDOWN: Controller VDSL 0, changed state to up
*Jun 23 09:03:50.368: VDSL 0: api (sys if get) ret = 0
*Jun 23 09:03:50.368: vdsl_daemon_sm VDSL 0: during state ready, got event 20(conn_mode_chk)
*Jun 23 09:03:50.368: @@@ vdsl_daemon_sm VDSL 0: ready -> mode_pending
*Jun 23 09:03:50.368: vdsl_daemon_sm VDSL 0: idle during state mode_pending
*Jun 23 09:03:50.368: @@@ vdsl_daemon_sm VDSL 0: mode_pending -> ready
*Jun 23 09:03:50.368: VDSL 0: tc mode selected = 0
*Jun 23 09:03:50.368: vdsl_daemon_sm VDSL 0: during state ready, got event 22(if_state_chk)
*Jun 23 09:03:50.368: @@@ vdsl_daemon_sm VDSL 0: ready -> readyLink b/w CPUs is set to PTMActivating PTM FPGA mode
*Jun 23 09:03:50.368: vdsl_daemon_sm VDSL 0: during state ready, got event 21(if_wakeup)
*Jun 23 09:03:50.368: @@@ vdsl_daemon_sm VDSL 0: ready -> running
*Jun 23 09:03:50.368: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD138C0, rx buf @0x1DD138C0
*Jun 23 09:03:50.368: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD138C0, rx_len = 140 @0x1DD138C0
*Jun 23 09:03:50.368: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:03:50.368: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 10x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.368: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.368: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 001E: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:03:50.368: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.368: TX: Msg for opcode(10)...waiting for Response from Mailbox!
*Jun 23 09:03:50.492: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E002, total len= 140, msg len= 140, @618
*Jun 23 09:03:50.492: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD138C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.492: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.492: 00x 116x 23x 00x 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.492: 00x 12x 4294967168x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 23 09:03:50.492: 00x 00x 4294967193x 00x 00x 00x 06x 00x 00x 30x 123x 00x 00x 00x 4294967193x 00x
*Jun 23 09:03:50.492: 00x 00x 00x 00x 00x 00x 00x 00x 01x 17x 109x 00x 01x 17x 109x 00x
*Jun 23 09:03:50.492: 00x 00x 00x
*Jun 23 09:03:50.492: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1394C, len= 140
*Jun 23 09:03:50.492: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 140, 0x1DD138C0
*Jun 23 09:03:50.492: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 23 09:03:50.492: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D33C opcode=10 to caller
*Jun 23 09:03:50.492: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10
*Jun 23 09:03:50.492: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:03:50.492: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.492: TX: Call for opcode 10 Success!
*Jun 23 09:03:50.492: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 23 09:03:50.492: vdsl_g997_channel_status_get: Successful Return !
*Jun 23 09:03:50.496: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=70, seq = 0, len=64, tx buf @0x1DD155C0, rx buf @0x1DD155C0
*Jun 23 09:03:50.496: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 64 @0x1DD155C0, rx_len = 4160 @0x1DD155C0
*Jun 23 09:03:50.496: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:03:50.496: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 70x 01x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 23 09:03:50.496: 102x 105x 103x 32x 101x 116x 104x 49x 32x 117x 112x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.496: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.496: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 16x 00x
*Jun 23 09:03:50.496: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382,
total len= 64, msg len= 64, @28
*Jun 23 09:03:50.496: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.496: TX: Msg for opcode(70)...waiting for Response from Mailbox!
*Jun 23 09:03:50.700: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 4160, msg len= 4160, @618
*Jun 23 09:03:50.700: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD155C0, len= 4160 00x 02x 70x 02x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 23 09:03:50.700: 102x 105x 103x 32x 101x 116x 104x 49x 32x 117x 112x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.700: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.700: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 4294967191x
*Jun 23 09:03:50.700: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x
*Jun 23 09:03:50.700: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 00x 00x 00x 00x 00x 00x 26x 17x 00x
*Jun 23 09:03:50.700: 67x 05x 4294967232x
*Jun 23 09:03:50.700: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD16600, len= 4160
*Jun 23 09:03:50.700: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 4160, 0x1DD155C0
*Jun 23 09:03:50.700: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=70
*Jun 23 09:03:50.700: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D330 opcode=70 to caller
*Jun 23 09:03:50.700: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 70
*Jun 23 09:03:50.700: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:03:50.700: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.700: TX: Call for opcode 70 Success!
*Jun 23 09:03:50.700: ipc VDSL 0: vdsl_send_modem_command,
*Jun 23 09:03:50.700: vdsl_send_modem_command: Successful Return !
*Jun 23 09:03:50.800: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=91, seq = 0, len=76, tx buf @0x1DD131C0, rx buf @0x1DD131C0
*Jun 23 09:03:50.800: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 76 @0x1DD131C0, rx_len = 76 @0x1DD131C0
*Jun 23 09:03:50.800: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:03:50.800: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 91x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.800: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.800: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.800: 00x 00x 00x 00x 4294967292x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.800: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.800: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382,
total len= 76, msg len= 76, @28
*Jun 23 09:03:50.800: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.800: TX: Msg for opcode(91)...waiting for Response from Mailbox!
*Jun 23 09:03:50.944: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E002, total len= 76, msg len= 76, @618
*Jun 23 09:03:50.944: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 76 00x 02x 91x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.944: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.944: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.944: 00x 00x 00x 00x 4294967292x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.944: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:03:50.944: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1320C, len= 76
*Jun 23 09:03:50.944: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 76, 0x1DD131C0
*Jun 23 09:03:50.944: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=91
*Jun 23 09:03:50.944: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D33C opcode=91 to caller
*Jun 23 09:03:50.944: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 91
*Jun 23 09:03:50.944: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:03:50.944: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:03:50.944: TX: Call for opcode 91 Success!
*Jun 23 09:03:50.944: ipc VDSL 0: vdsl_send_watermark_command,
*Jun 23 09:03:50.944: vdsl_send_watermark_command: Successful Return !
*Jun 23 09:03:50.944: VDSL 0: VDSL PTM mode is activated
*Jun 23 09:03:50.944: vdsl_daemon_sm VDSL 0: during state running, got event 23(linkup)
*Jun 23 09:03:50.944: @@@ vdsl_daemon_sm VDSL 0: running -> running
*Jun 23 09:03:50.944: VDSL 0: api (sys if get) ret = 0
*Jun 23 09:03:52.492: %LINK-3-UPDOWN: Interface Ethernet0, changed state to up
*Jun 23 09:03:53.492: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0, changed state to up
*Jun 23 09:03:59.012: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:04:00.872: %DIALER-6-BIND: Interface Vi2 bound to profile Di0
*Jun 23 09:04:00.872: Vi2 Debug: Condition 1, interface Di0 triggered, count 1
*Jun 23 09:04:00.876: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
*Jun 23 09:04:00.876: Vi2 DDR: Dialer statechange to up
*Jun 23 09:04:00.876: Vi2 PPP: Authorization required
*Jun 23 09:04:00.876: Vi2 PPP: Using dialer call direction
*Jun 23 09:04:00.876: Vi2 PPP: Treating connection as a callout
*Jun 23 09:04:00.876: Vi2 PPP: Session handle[C100000B] Session id[11]
*Jun 23 09:04:00.876: Vi2 PPP LCP: negotiation authorized = 1, tacacs author = 0
*Jun 23 09:04:00.876: Vi2 PPP LCP: neg is authorized, processing CP UP event
*Jun 23 09:04:00.884: Vi2 PPP LCP: neg is authorized, processing incoming CONFREQ
*Jun 23 09:04:00.908: Vi2 PPP: No authorization without authentication
*Jun 23 09:04:00.908: Vi2 CHAP: I CHALLENGE id 1 len 30 from "MSR91GEN9"
*Jun 23 09:04:00.908: Vi2 PPP: Sent CHAP SENDAUTH Request
*Jun 23 09:04:00.908: Vi2 PPP: Received SENDAUTH Response FAIL
*Jun 23 09:04:00.908: Vi2 CHAP: Using hostname from interface CHAP
*Jun 23 09:04:00.908: Vi2 CHAP: Using password from interface CHAP
*Jun 23 09:04:00.908: Vi2 CHAP: O RESPONSE id 1 len 38 from "fd618575@proximus"
*Jun 23 09:04:01.072: Vi2 CHAP: I SUCCESS id 1 len 42 msg is "CHAP authentication success, unit 3389"
*Jun 23 09:04:01.076: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
*Jun 23 09:04:01.076: Vi2 PPP IPCP: negotiation authorized = 1, tacacs author = 0
*Jun 23 09:04:01.076: Vi2 PPP IPCP: neg is authorized, processing CP UP event
*Jun 23 09:04:01.084: Vi2 PPP IPCP: neg is authorized, processing incoming CONFREQ
*Jun 23 09:04:01.100: Vi2 DDR: dialer protocol up
*Jun 23 09:04:01.100: Di0 DDR: dialer protocol up
*Jun 23 09:04:08.892: VDSL 0: SM_LINE_DOWN boolean event
*Jun 23 09:04:08.892: %CONTROLLER-5-UPDOWN: Controller VDSL 0, changed state to down
*Jun 23 09:04:08.892: vdsl_daemon_sm VDSL 0: during state running, got event 24(linkdown)
*Jun 23 09:04:08.892: @@@ vdsl_daemon_sm VDSL 0: running -> training
*Jun 23 09:04:08.892: VDSL 0: VDSL PTM mode is de-activated
*Jun 23 09:04:08.892: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=70, seq = 0, len=64, tx buf @0x1DD155C0, rx buf @0x1DD155C0
*Jun 23 09:04:08.892: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 64 @0x1DD155C0, rx_len = 4160 @0x1DD155C0
*Jun 23 09:04:08.892: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:04:08.892: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 70x 01x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 23 09:04:08.892: 102x 105x 103x 32x 101x 116x 104x 49x 32x 100x 111x 119x 110x 00x 00x 00x
*Jun 23 09:04:08.892: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:04:08.892: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 16x 00x
*Jun 23 09:04:08.892: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382,
total len= 64, msg len= 64, @28
*Jun 23 09:04:08.892: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:04:08.892: TX: Msg for opcode(70)...waiting for Response from Mailbox!
*Jun 23 09:04:09.120: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 4160, msg len= 4160, @618
*Jun 23 09:04:09.120: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD155C0, len= 4160 00x 02x 70x 02x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 23 09:04:09.120: 102x 105x 103x 32x 101x 116x 104x 49x 32x 100x 111x 119x 110x 00x 00x 00x
*Jun 23 09:04:09.120: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:04:09.120: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 4294967191x
*Jun 23 09:04:09.120: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x
*Jun 23 09:04:09.120: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 00x 00x 00x 00x 00x 00x 26x 17x 00x
*Jun 23 09:04:09.124: 67x 05x 4294967232x
*Jun 23 09:04:09.124: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD16600, len= 4160
*Jun 23 09:04:09.124: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 4160, 0x1DD155C0
*Jun 23 09:04:09.124: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=70
*Jun 23 09:04:09.124: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D330 opcode=70 to caller
*Jun 23 09:04:09.124: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 70
*Jun 23 09:04:09.124: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:04:09.124: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:04:09.124: TX: Call for opcode 70 Success!
*Jun 23 09:04:09.124: ipc VDSL 0: vdsl_send_modem_command,
*Jun 23 09:04:09.124: vdsl_send_modem_command: Successful Return !
*Jun 23 09:04:09.124: vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
*Jun 23 09:04:09.124: @@@ vdsl_daemon_sm VDSL 0: training -> training
*Jun 23 09:04:09.164: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:04:09.892: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0, changed state to down
*Jun 23 09:04:11.124: %LINK-3-UPDOWN: Interface Ethernet0, changed state to down
*Jun 23 09:04:11.148: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 8
*Jun 23 09:04:11.148: VDSL 0: vdsl line state : discovery
*Jun 23 09:04:11.148: VDSL 0: SM_LINE_TRAIN boolean event
*Jun 23 09:04:11.148: vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
*Jun 23 09:04:11.148: @@@ vdsl_daemon_sm VDSL 0: training -> training
*Jun 23 09:04:19.164: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:04:29.164: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:04:39.152: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E004, total len= 28, msg len= 28, @618
*Jun 23 09:04:39.152: mbx VDSL 0: vdsl_msg_rcv_isr, Notification msg type 4, len= 28
*Jun 23 09:04:39.152: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1E936000, len= 28 00x 04x 11x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 42x
*Jun 23 09:04:39.152: 4294967242x 55x 16x 127x 4294967193x 28x 4294967288x 00x 00x 00x 00x
*Jun 23 09:04:39.152: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1E93601C, len= 28
*Jun 23 09:04:39.152: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 4 rx handler, err= 0, len= 28, 0x1E936000
*Jun 23 09:04:39.192: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:04:41.164: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 7
*Jun 23 09:04:41.164: VDSL 0: vdsl line state : fullinit
*Jun 23 09:04:49.192: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:04:59.188: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:05:01.164: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to down
*Jun 23 09:05:01.164: Vi2 PPP: Clearing AAA Unique Id = 17
*Jun 23 09:05:01.164: %DIALER-6-UNBIND: Interface Vi2 unbound from profile Di0
*Jun 23 09:05:01.164: Vi2 DDR: disconnecting call
*Jun 23 09:05:01.168: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to down
*Jun 23 09:05:01.168: Vi2 Debug: Condition 1, interface Di0 cleared, count 0
*Jun 23 09:05:09.188: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E004, total len= 28, msg len= 28, @618
*Jun 23 09:05:09.188: mbx VDSL 0: vdsl_msg_rcv_isr, Notification msg type 4, len= 28
*Jun 23 09:05:09.188: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1E936000, len= 28 00x 04x 11x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 42x
*Jun 23 09:05:09.188: 4294967242x 55x 16x 127x 4294967193x 28x 4294967288x 00x 00x 00x 00x
*Jun 23 09:05:09.188: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1E93601C, len= 28
*Jun 23 09:05:09.188: mbx VDSL 0: vdsl_msg_rcv_complete, debug interface dialer0call msg 4 rx handler, err= 0, len= 28, 0x1E936000
*Jun 23 09:05:09.216: ipc VDSL 0: vdsl_mbx_interrupt_handlercopy run start
*Jun 23 09:05:19.216: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:05:23.471: VDSL 0: SM_LINE_SHOWTIME boolean event
*Jun 23 09:05:23.471: VDSL 0: line state : showtime !
*Jun 23 09:05:24.471: vdsl_daemon_sm VDSL 0: during state training, got event 18(showtime)
*Jun 23 09:05:24.471: @@@ vdsl_daemon_sm VDSL 0: training -> ready
*Jun 23 09:05:24.471: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=14, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0
*Jun 23 09:05:24.471: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 36 @0x1DD131C0
*Jun 23 09:05:24.471: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:05:24.471: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 14x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.471: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.471: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 001E: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:05:24.471: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.471: TX: Msg for opcode(14)...waiting for Response from Mailbox!
*Jun 23 09:05:24.583: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E002, total len= 36, msg len= 36, @618
*Jun 23 09:05:24.583: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 36 00x 02x 14x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.583: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 02x 00x
*Jun 23 09:05:24.583: 00x 00x 00x
*Jun 23 09:05:24.583: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD131E4, len= 36
*Jun 23 09:05:24.583: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD131C0
*Jun 23 09:05:24.583: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=14
*Jun 23 09:05:24.583: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D33C opcode=14 to caller
*Jun 23 09:05:24.583: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 14
*Jun 23 09:05:24.583: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:05:24.583: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.583: TX: Call for opcode 14 Success!
*Jun 23 09:05:24.583: VDSL 0: selected tc = 0, sysif = -1
*Jun 23 09:05:24.583: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=17, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0
*Jun 23 09:05:24.583: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 36 @0x1DD131C0
*Jun 23 09:05:24.583: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:05:24.583: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 17x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.583: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.583: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:05:24.583: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.583: TX: Msg for opcode(17)...waiting for Response from Mailbox!
*Jun 23 09:05:24.687: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 36, msg len= 36, @618
*Jun 23 09:05:24.687: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 36 00x 02x 17x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.687: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.687: 00x 00x 01x
*Jun 23 09:05:24.687: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD131E4, len= 36
*Jun 23 09:05:24.687: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD131C0
*Jun 23 09:05:24.687: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=17
*Jun 23 09:05:24.687: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D330 opcode=17 to caller
*Jun 23 09:05:24.687: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 17
*Jun 23 09:05:24.687: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:05:24.687: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.687: TX: Call for opcode 17 Success!
*Jun 23 09:05:24.687: ipc VDSL 0: vdsl_g997_atu_systemenabling_status_get,
*Jun 23 09:05:24.687: vdsl_g997_atu_systemenabling_status_get: Successful Return !
*Jun 23 09:05:24.687: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD138C0, rx buf @0x1DD138C0
*Jun 23 09:05:24.687: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD138C0, rx_len = 140 @0x1DD138C0
*Jun 23 09:05:24.687: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:05:24.687: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 10x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.687: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.687: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:05:24.687: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.687: TX: Msg for opcode(10)...waiting for Response from Mailbox!
*Jun 23 09:05:24.811: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E002, total len= 140, msg len= 140, @618
*Jun 23 09:05:24.811: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD138C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.811: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.811: 00x 116x 23x 00x 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.811: 00x 12x 4294967168x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 23 09:05:24.811: 00x 00x 4294967193x 00x 00x 00x 06x 00x 00x 30x 123x 00x 00x 00x 4294967193x 00x
*Jun 23 09:05:24.811: 00x 00x 00x 00x 00x 00x 00x 00x 01x 17x 109x 00x 01x 17x 109x 00x
*Jun 23 09:05:24.811: 00x 00x 00x
*Jun 23 09:05:24.811: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1394C, len= 140
*Jun 23 09:05:24.811: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 140, 0x1DD138C0
*Jun 23 09:05:24.811: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 23 09:05:24.811: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D33C opcode=10 to caller
*Jun 23 09:05:24.811: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10
*Jun 23 09:05:24.811: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:05:24.811: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.811: TX: Call for opcode 10 Success!
*Jun 23 09:05:24.811: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 23 09:05:24.811: vdsl_g997_channel_status_get: Successful Return !
*Jun 23 09:05:24.811: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD138C0, rx buf @0x1DD138C0
*Jun 23 09:05:24.811: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD138C0, rx_len = 140 @0x1DD138C0
*Jun 23 09:05:24.811: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:05:24.811: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 10x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 01x 00x 00x 00x
*Jun 23 09:05:24.811: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.811: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:05:24.811: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.811: TX: Msg for opcode(10)...waiting for Response from Mailbox!
*Jun 23 09:05:24.935: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 140, msg len= 140, @618
*Jun 23 09:05:24.935: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD138C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 01x 00x 00x 00x
*Jun 23 09:05:24.935: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.935: 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.935: 00x 01x 4294967184x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 23 09:05:24.935: 00x 00x 32x 00x 00x 00x 16x 00x 00x 00x 16x 00x 00x 00x 32x 00x
*Jun 23 09:05:24.935: 00x 00x 01x 00x 00x 00x 00x 00x 01x 17x 109x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.935: 00x 00x 00x
*Jun 23 09:05:24.935: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1394C, len= 140
*Jun 23 09:05:24.935: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 140, 0x1DD138C0
*Jun 23 09:05:24.935: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 23 09:05:24.935: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D330 opcode=10 to caller
*Jun 23 09:05:24.935: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10
*Jun 23 09:05:24.935: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:05:24.935: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.935: TX: Call for opcode 10 Success!
*Jun 23 09:05:24.935: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 23 09:05:24.935: vdsl_g997_channel_status_get: Successful Return !
*Jun 23 09:05:24.935: %CONTROLLER-5-UPDOWN: Controller VDSL 0, changed state to up
*Jun 23 09:05:24.935: VDSL 0: api (sys if get) ret = 0
*Jun 23 09:05:24.935: vdsl_daemon_sm VDSL 0: during state ready, got event 20(conn_mode_chk)
*Jun 23 09:05:24.935: @@@ vdsl_daemon_sm VDSL 0: ready -> mode_pending
*Jun 23 09:05:24.935: vdsl_daemon_sm VDSL 0: idle during state mode_pending
*Jun 23 09:05:24.935: @@@ vdsl_daemon_sm VDSL 0: mode_pending -> ready
*Jun 23 09:05:24.935: VDSL 0: tc mode selected = 0
*Jun 23 09:05:24.935: vdsl_daemon_sm VDSL 0: during state ready, got event 22(if_state_chk)
*Jun 23 09:05:24.935: @@@ vdsl_daemon_sm VDSL 0: ready -> readyLink b/w CPUs is set to PTMActivating PTM FPGA mode
*Jun 23 09:05:24.935: vdsl_daemon_sm VDSL 0: during state ready, got event 21(if_wakeup)
*Jun 23 09:05:24.935: @@@ vdsl_daemon_sm VDSL 0: ready -> running
*Jun 23 09:05:24.935: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD138C0, rx buf @0x1DD138C0
*Jun 23 09:05:24.935: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD138C0, rx_len = 140 @0x1DD138C0
*Jun 23 09:05:24.935: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:05:24.935: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 10x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.935: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:24.935: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 001E: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 23 09:05:24.935: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:24.935: TX: Msg for opcode(10)...waiting for Response from Mailbox!
*Jun 23 09:05:25.059: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E002, total len= 140, msg leundebugn= 140, @618
*Jun 23 09:05:25.059: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD138C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.063: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.063: 00x 116x 23x 00x 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.063: 00x 12x 4294967168x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 23 09:05:25.063: 00x 00x 4294967193x 00x 00x 00x 06x 00x 00x 30x 123x 00x 00x 00x 4294967193x 00x
*Jun 23 09:05:25.063: 00x 00x 00x 00x 00x 00x 00x 00x 01x 17x 109x 00x 01x 17x 109x 00x
*Jun 23 09:05:25.063: 00x 00x 00x
*Jun 23 09:05:25.063: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1394C, len= 140
*Jun 23 09:05:25.063: mbx VDSL 0: vdsl_msg_rcv_comp all
Destination filename [startundebug]? lete, call msg 2 rx handler, err= 0, len= 140, 0x1DD138C0
*Jun 23 09:05:25.063: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 23 09:05:25.063: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D33C opcode=10 to caller
*Jun 23 09:05:25.063: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10
*Jun 23 09:05:25.063: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:05:25.063: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:25.063: TX: Call for opcode 10 Success!
*Jun 23 09:05:25.063: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 23 09:05:25.063: vdsl_g997_channel_status_get: Successful Return !
*Jun 23 09:05:25.063: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=70, seq = 0, len=64, tx buf @0x1DD155C0, rx buf @0x1DD155C0
*Jun 23 09:05:25.063: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 64 @0x1DD155C0, rx_len = 4160 @0x1DD155C0
*Jun 23 09:05:25.063: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:05:25.063: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 70x 01x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 23 09:05:25.063: 102x 105x 103x 32x 101x 116x 104x 49x 32x 117x 112x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.063: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.063: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 16x 00x
*Jun 23 09:05:25.063: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382,
total len= 64, msg len= 64, @28
*Jun 23 09:05:25.063: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:25.063: TX: Msg for opcode(70)...waiting for Response from Mailbox!
*Jun 23 09:05:25.267: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 4160, msg len= 4160, @618
*Jun 23 09:05:25.267: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD155C0, len= 4160 00x 02x 70x 02x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 23 09:05:25.267: 102x 105x 103x 32x 101x 116x 104x 49x 32x 117x 112x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.267: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.267: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 4294967191x
*Jun 23 09:05:25.267: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x
*Jun 23 09:05:25.271: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 00x 00x 00x 00x 00x 00x 26x 17x 00x
*Jun 23 09:05:25.271: 67x 05x 4294967232x
*Jun 23 09:05:25.271: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD16600, len= 4160
*Jun 23 09:05:25.271: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 4160, 0x1DD155C0
*Jun 23 09:05:25.271: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=70
*Jun 23 09:05:25.271: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D330 opcode=70 to caller
*Jun 23 09:05:25.271: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 70
*Jun 23 09:05:25.271: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:05:25.271: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:25.271: TX: Call for opcode 70 Success!
*Jun 23 09:05:25.271: ipc VDSL 0: vdsl_send_modem_command,
*Jun 23 09:05:25.271: vdsl_send_modem_command: Successful Return !
*Jun 23 09:05:25.371: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=91, seq = 0, len=76, tx buf @0x1DD131C0, rx buf @0x1DD131C0
*Jun 23 09:05:25.371: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 76 @0x1DD131C0, rx_len = 76 @0x1DD131C0
*Jun 23 09:05:25.371: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:05:25.371: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 91x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.371: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.371: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.371: 00x 00x 00x 00x 4294967292x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.371: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.371: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382,
total len= 76, msg len= 76, @28
*Jun 23 09:05:25.371: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:25.371: TX: Msg for opcode(91)...waiting for Response from Mailbox!
*Jun 23 09:05:25.511: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E002, total len= 76, msg len= 76, @618
*Jun 23 09:05:25.511: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 76 00x 02x 91x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.511: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.511: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.511: 00x 00x 00x 00x 4294967292x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.515: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:25.515: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1320C, len= 76
*Jun 23 09:05:25.515: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 76, 0x1DD131C0
*Jun 23 09:05:25.515: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=91
*Jun 23 09:05:25.515: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D33C opcode=91 to caller
*Jun 23 09:05:25.515: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 91
*Jun 23 09:05:25.515: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:05:25.515: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:25.515: TX: Call for opcode 91 Success!
*Jun 23 09:05:25.515: ipc VDSL 0: vdsl_send_watermark_command,
*Jun 23 09:05:25.515: vdsl_send_watermark_command: Successful Return !
*Jun 23 09:05:25.515: VDSL 0: VDSL PTM mode is activated
*Jun 23 09:05:25.515: vdsl_daemon_sm VDSL 0: during state running, got event 23(linkup)
*Jun 23 09:05:25.515: @@@ vdsl_daemon_sm VDSL 0: running -> running
*Jun 23 09:05:25.515: VDSL 0: api (sys if get) ret = 0
*Jun 23 09:05:27.063: %LINK-3-UPDOWN: Interface Ethernet0, changed state to up
*Jun 23 09:05:27.671: %DIALER-6-BIND: Interface Vi2 bound to profile Di0
*Jun 23 09:05:27.671: Vi2 Debug: Condition 1, interface Di0 triggered, count 1
*Jun 23 09:05:27.675: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
*Jun 23 09:05:27.675: Vi2 DDR: Dialer statechange to up
*Jun 23 09:05:27.675: Vi2 PPP: Authorization required
*Jun 23 09:05:27.675: Vi2 PPP: Using dialer call direction
*Jun 23 09:05:27.675: Vi2 PPP: Treating connection as a callout
*Jun 23 09:05:27.675: Vi2 PPP: Session handle[8600000C] Session id[12]
*Jun 23 09:05:27.675: Vi2 PPP LCP: negotiation authorized = 1, tacacs author = 0
*Jun 23 09:05:27.675: Vi2 PPP LCP: neg is authorized, processing CP UP event
*Jun 23 09:05:27.683: Vi2 PPP LCP: neg is authorized, processing incoming CONFREQ
*Jun 23 09:05:27.691: Vi2 PPP: No authorization without authentication
*Jun 23 09:05:27.695: Vi2 CHAP: I CHALLENGE id 1 len 30 from "MSR91GEN9"
*Jun 23 09:05:27.695: Vi2 PPP: Sent CHAP SENDAUTH Request
*Jun 23 09:05:27.695: Vi2 PPP: Received SENDAUTH Response FAIL
*Jun 23 09:05:27.695: Vi2 CHAP: Using hostname from interface CHAP
*Jun 23 09:05:27.695: Vi2 CHAP: Usin
g password from interface CHAP
*Jun 23 09:05:27.695: Vi2 CHAP: O RESPONSE id 1 len 38 from "fd618575@proximus"
*Jun 23 09:05:28.015: Vi2 CHAP: I SUCCESS id 1 len 42 msg is "CHAP authentication success, unit 4065"
*Jun 23 09:05:28.019: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
*Jun 23 09:05:28.019: Vi2 PPP IPCP: negotiation authorized = 1, tacacs author = 0
*Jun 23 09:05:28.019: Vi2 PPP IPCP: neg is authorized, processing CP UP event
*Jun 23 09:05:28.023: Vi2 PPP IPCP: neg is authorized, processing incoming CONFREQ
*Jun 23 09:05:28.043: Vi2 DDR: dialer protocol up
*Jun 23 09:05:28.043: Di0 DDR: dialer protocol up
*Jun 23 09:05:28.063: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0, changed state to up
*Jun 23 09:05:29.983: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:05:39.979: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 23 09:05:43.451: VDSL 0: SM_LINE_DOWN boolean event
*Jun 23 09:05:43.451: %CONTROLLER-5-UPDOWN: Controller VDSL 0, changed state to down
*Jun 23 09:05:43.451: vdsl_daemon_sm VDSL 0: during state running, got event 24(linkdown)
*Jun 23 09:05:43.451: @@@ vdsl_daemon_sm VDSL 0: running -> training
*Jun 23 09:05:43.455: VDSL 0: VDSL PTM mode is de-activated
*Jun 23 09:05:43.455: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=70, seq = 0, len=64, tx buf @0x1DD16600, rx buf @0x1DD16600
*Jun 23 09:05:43.455: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 64 @0x1DD16600, rx_len = 4160 @0x1DD16600
*Jun 23 09:05:43.455: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 23 09:05:43.455: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 0
58083 bytes copied in 1.652 secs (35159 bytes/sec)
OCWRTR01#u0x 02x 70x 01x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 23 09:05:43.455: 102x 105x 103x 32x 101x 116x 104x 49x 32x 100x 111x 119x 110x 00x 00x 00x
*Jun 23 09:05:43.455: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:43.455: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 16x 00x
*Jun 23 09:05:43.455: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382,
total len= 64, msg len= 64, @28
*Jun 23 09:05:43.455: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:43.455: TX: Msg for opcode(70)...waiting for Response from Mailbox!
*Jun 23 09:05:43.667: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 4160, msg len= 4160, @618
*Jun 23 09:05:43.667: mbx VDSL 0: vdsl_process_msg_rcv, First message (1nde) : addr= 0x618, dest= 0x0x1DD16600, len= 4160 00x 02x 70x 02x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 23 09:05:43.671: 102x 105x 103x 32x 101x 116x 104x 49x 32x 100x 111x 119x 110x 00x 00x 00x
*Jun 23 09:05:43.671: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 23 09:05:43.671: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 4294967191x
*Jun 23 09:05:43.671: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x
*Jun 23 09:05:43.671: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 00x 00x 00x 00x 00x 00x 26x 17x 00x
*Jun 23 09:05:43.671: 67x 05x 4294967232x
*Jun 23 09:05:43.671: mbx VDSL 0: vdsl_process_msg_rcv,bug Last message (2) : addr= 0x618, dest= 0x1DD17640, len= 4160
*Jun 23 09:05:43.671: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 4160, 0x1DD16600
*Jun 23 09:05:43.671: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=70
*Jun 23 09:05:43.671: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x195D330 opcode=70 to caller
*Jun 23 09:05:43.671: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 70
*Jun 23 09:05:43.671: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
*Jun 23 09:05:43.671: ipc VDSL 0: vdsl_ipc_send,
*Jun 23 09:05:43.671: TX: Call for opcode 70 Success!
*Jun 23 09:05:43.671: ipc VDSL 0: vdsl_send_modem_command,
*Jun 23 09:05:43.671: vdsl_send_modem_command: Successful Return !
*Jun 23 09:05:43.671: vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
*Jun 23 09:05:43.671: @@@ vdsl_daemon_sm VDSL 0: training -> training
*Jun 23 09:05:44.455: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0, changed state to down
*Jun 23 09:05:45.279: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 8
*Jun 23 09:05:45.279: VDSL 0: vdsl line state : discovery
*Jun 23 09:05:45.279: VDSL 0: SM_LINE_TRAIN boolean event
*Jun 23 09:05:45.279: vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
*Jun 23 09:05:45.279: @@@ vdsl_daemon_sm VDSL 0: training -> training
*Jun 23 09:05:45.671: %LINK-3-UPDOWN: Interface Ethernet0, changed state to down
*Jun 23 09:05:50.123: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE all
Solved! Go to Solution.
07-13-2018 12:39 AM
07-13-2018 12:46 AM
Jeroen,
check if you can configure 'crypto isakmp invalid-spi-recovery' globally on your router. Also, check if the access list on the ASA matches the access list on your router...
07-13-2018 01:02 AM
07-13-2018 01:14 AM
Hello,
the access lists look fine as far as I can tell. Can you post the latest running config of your router again, I am not sure what is in there as of now. Did you entre the spi recovery command ?
07-13-2018 01:18 AM
still getting messages
*Jul 13 07:59:11.253: %CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=109.135.19.130, prot=50, spi=0x1FDFC019(534757401), srcaddr=194.78.59.5, input interface=Dialer0
*Jul 13 07:59:11.281: %CRYPTO-4-IKMP_NO_SA: IKE message from 194.78.59.5 has no SA and is not an initialization offer
07-13-2018 01:21 AM
07-13-2018 01:30 AM
07-13-2018 01:37 AM
Hello,
there is probably a mismatch in the IPSec/ISAKMP parameters, can you post the config of the ASA ?
The MTU paramteres on your dialer look odd, can you use:
interface Dialer0
mtu 1400
ip address 109.135.19.130 255.255.255.0
ip nat outside
ip virtual-reassembly in
max-reassemblies 1024
ip virtual-reassembly out
max-reassemblies 1024
encapsulation ppp
ip tcp adjust-mss 1360
dialer pool 1
dialer-group 1
ppp authentication chap callin
ppp chap hostname ***********
ppp chap password 7 ***********
no cdp enable
crypto map SDM_CMAP_1
crypto ipsec df-bit clear !
07-13-2018 02:11 AM
07-13-2018 05:08 AM
Hello,
on your router, change your access list 100 to match the exact content of the network object GAD on your ASA. So it looks like this:
access-list 100 remark IPSec Rule
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.4.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.10.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.11.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.12.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.13.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.14.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.15.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.16.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.17.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.18.0 0.0.0.255
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.19.0 0.0.0.255
access-list 100 remark SDM_ACM Category=4
Also, I am not really sure why RIP is needed, the default route should be sufficient. Can you disable RIP ?
Also, make a small addition to your route map:
route-map SDM_RMAP_1 permit 1
match ip address 101
match interface Dialer0
07-17-2018 12:55 AM
I made all the adjustments and did a reload but no effect.
A traceroute shows that the traffic to the main site is going to the internet and not through the tunnel.
OCWRTR01#traceroute 10.0.12.32
Type escape sequence to abort.
Tracing the route to 10.0.12.32
VRF info: (vrf in name/id, vrf out name/id)
1 106.255-200-80.adsl-static.isp.belgacom.be (80.200.255.106) 80 msec 76 msec 76 msec
2 ae-77-101.iarstr3.isp.belgacom.be (91.183.241.30) 84 msec 72 msec 80 msec
3 ae-12-1000.ibrstr5.isp.belgacom.be (91.183.246.108) 84 msec 72 msec 80 msec
4 * * *
5 * *
07-17-2018 01:03 AM
Hello Jeroen,
post the current config again, after doing the suggested changes..
07-17-2018 01:21 AM
07-17-2018 01:38 AM
Hello Jeroen,
can you try the traceroute from a client in the 10.0.130.32 255.255.255.224 range ?
07-17-2018 01:42 AM
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide