topic Re: problem with VDSL on 887 in Routing and SD-WAN

problem with VDSL on 887

Jeroen Janssens — Tue, 05 Mar 2019 18:39:18 GMT

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

Re: problem with VDSL on 887

Georg Pauwen — Mon, 25 Jun 2018 07:26:41 GMT

Hello,

try 'operating mode auto' under the controller:

887#conf t

887(config)#controller vdsl 0

887(config-controller)#operating mode auto

Re: problem with VDSL on 887

Georg Pauwen — Mon, 25 Jun 2018 07:43:35 GMT

Also post the full config of your router...

Who is your ISP ?

Re: problem with VDSL on 887

Jeroen Janssens — Mon, 25 Jun 2018 07:44:51 GMT

Proximus (Belgium)

Re: problem with VDSL on 887

Georg Pauwen — Mon, 25 Jun 2018 07:59:18 GMT

Hello,

which firmware are you running on the controller ?

E.g.:

controller VDSL 0
firmware filename flash:VA_A_39d_B_38h3_24h_1.bin

Also, under the controller you should have various modem options:

887#conf t

887(config)#controller vdsl 0

887(config-controller)#modem ?

Which are those ?

Re: problem with VDSL on 887

Jeroen Janssens — Mon, 25 Jun 2018 08:16:01 GMT

This is the current config:

OCWRTR01#show run
Building configuration...

!
no ip dhcp use vrf connected
!
ip dhcp pool sdm-pool
import all
network 10.0.130.32 255.255.255.224
default-router 10.0.130.33
dns-server 10.0.12.32 10.0.12.16
lease 0 2
!
!
!
ip name-server 195.238.2.21
ip name-server 195.238.2.22
ip cef
no ipv6 cef
!
!
!
!
!
multilink bundle-name authenticated
!
!
!
!
!
!
!
license udi pid C887VAM-K9 sn FCZ222012JM
!
!
username janssens.j privilege 15 secret ******************
!
!
!
!
!
controller VDSL 0
no cdp run
!
!
!
crypto isakmp policy 1
encr 3des
authentication pre-share
group 2
crypto isakmp key ****************** address ******************
crypto isakmp fragmentation
!
!
crypto ipsec transform-set ESP-3DES-SHA esp-3des esp-sha-hmac
mode tunnel
!
!
!
crypto map SDM_CMAP_1 1 ipsec-isakmp
description Tunnel to ******************
set peer ******************
set transform-set ESP-3DES-SHA
match address 100
!
!
!
!
!
!
interface ATM0
no ip address
shutdown
no atm ilmi-keepalive
!
interface Ethernet0
no ip address
!
interface Ethernet0.10
encapsulation dot1Q 10
ip nat outside
ip virtual-reassembly in
pppoe enable group global
pppoe-client dial-pool-number 1
!
interface FastEthernet0
description trunk OCWL2SW01
switchport mode trunk
no ip address
!
interface FastEthernet1
no ip address
shutdown
!
interface FastEthernet2
no ip address
shutdown
!
interface FastEthernet3
no ip address
shutdown
!
interface Vlan1
ip address 10.0.130.33 255.255.255.224
ip nat inside
ip rip send version 2
ip rip receive version 2
ip virtual-reassembly in
ip tcp adjust-mss 1412
!
interface Dialer0
mtu 1200
ip address ****************** 255.255.255.0
ip nat outside
ip virtual-reassembly in
encapsulation ppp
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
!
router rip
version 2
redistribute static
network 10.0.0.0
default-information originate
no auto-summary
!
ip forward-protocol nd
no ip http server
ip http access-class 23
ip http authentication local
ip http secure-server
ip http timeout-policy idle 60 life 8640 requests 10000
!
!
ip nat inside source route-map SDM_RMAP_1 interface Dialer0 overload
ip route 0.0.0.0 0.0.0.0 Dialer0 permanent
!
dialer-list 1 protocol ip permit
!
route-map SDM_RMAP_1 permit 1
match ip address 101
!
snmp-server community public RO
access-list 1 remark SDM_ACL Category=2
access-list 1 permit 10.10.10.0 0.0.0.7
access-list 2 remark SDM_ACM Category=2
access-list 2 permit 10.0.130.32 0.0.0.31
access-list 23 permit 10.0.130.32 0.0.0.31
access-list 100 remark IPSec Rule
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255
access-list 100 remark SDM_ACM Category=4
access-list 101 remark IPSec Rule
access-list 101 remark SDM_ACM Category=2
access-list 101 deny ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255
access-list 101 permit ip 10.0.130.32 0.0.0.31 any
!
control-plane
!
!
!
mgcp behavior rsip-range tgcp-only
mgcp behavior comedia-role none
mgcp behavior comedia-check-media-src disable
mgcp behavior comedia-sdp-force disable
!
mgcp profile default
!
!
!
!
!
!
!
line con 0
exec-timeout 5 30
password 7 ******************
login
no modem enable
line aux 0
line vty 0 4
privilege level 15
password 7 ******************
login
transport input telnet ssh
!
scheduler max-task-time 5000
scheduler allocate 20000 1000
!
end

Re: problem with VDSL on 887

Jeroen Janssens — Mon, 25 Jun 2018 08:18:05 GMT

OCWRTR01#conf t
Enter configuration commands, one per line. End with CNTL/Z.
OCWRTR01(config)#controller vdsl 0
OCWRTR01(config-controller)#modem ?
LINE command line string

Re: problem with VDSL on 887

Jeroen Janssens — Mon, 25 Jun 2018 08:19:38 GMT

OCWRTR01#show ver
Cisco IOS Software, C800 Software (C800-UNIVERSALK9-M), Version 15.5(3)M5, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2017 by Cisco Systems, Inc.
Compiled Wed 25-Jan-17 04:11 by prod_rel_team

ROM: System Bootstrap, Version 15.4(1r)T1, RELEASE SOFTWARE (fc1)

OCWRTR01 uptime is 1 day, 23 hours, 39 minutes
System returned to ROM by power-on
System image file is "flash:c800-universalk9-mz.SPA.155-3.M5.bin"
Last reload type: Normal Reload
Last reload reason: power-on

This product contains cryptographic features and is subject to United
States and local country laws governing import, export, transfer and
use. Delivery of Cisco cryptographic products does not imply
third-party authority to import, export, distribute or use encryption.
Importers, exporters, distributors and users are responsible for
compliance with U.S. and local country laws. By using this product you
agree to comply with applicable laws and regulations. If you are unable
to comply with U.S. and local laws, return this product immediately.

A summary of U.S. laws governing Cisco cryptographic products may be found at:
http://www.cisco.com/wwl/export/crypto/tool/stqrg.html

If you require further assistance please contact us by sending email to
export@cisco.com.

Cisco C887VAM-K9 (revision 1.0) with 488524K/35763K bytes of memory.
Processor board ID FCZ222012JM
1 DSL controller
1 Ethernet interface
4 FastEthernet interfaces
1 ATM interface
1 Virtual Private Network (VPN) Module
DRAM configuration is 32 bits wide
255K bytes of non-volatile configuration memory.
250880K bytes of ATA System CompactFlash (Read/Write)

License Info:

License UDI:

-------------------------------------------------
Device# PID SN
-------------------------------------------------
*1 C887VAM-K9 FCZ222012JM

License Information for 'c800'
License Level: advipservices Type: Default. No valid license found.
Next reboot license Level: advipservices

Configuration register is 0x2102

Re: problem with VDSL on 887

Georg Pauwen — Mon, 25 Jun 2018 08:35:54 GMT

Hello,

I made some minor changes to your config (marked in bold).

On the dialer, you have a static IP address, typically this is set to 'negotiated', you might want to check that...

OCWRTR01#show run
Building configuration...

Current configuration : 5520 bytes
!
! Last configuration change at 09:07:30 pctime Mon Jun 25 2018
!
version 15.5
no service pad
service timestamps debug datetime msec
service timestamps log datetime msec
service password-encryption
!
hostname OCWRTR01
!
boot-start-marker
boot-end-marker
!
aqm-register-fnf
!
enable secret ******************
enable password ******************
!
no aaa new-model
clock timezone pctime 1 0
clock summer-time pctime date Mar 30 2003 2:00 Oct 26 2003 3:00
!
crypto pki trustpoint TP-self-signed-372889659
enrollment selfsigned
subject-name cn=IOS-Self-Signed-Certificate-372889659
revocation-check none
rsakeypair TP-self-signed-372889659
!
!
crypto pki certificate chain TP-self-signed-372889659
certificate self-signed 01
30820229 30820192 A0030201 02020101 300D0609 2A864886 F70D0101 05050030
30312E30 2C060355 04031325 494F532D 53656C66 2D536967 6E65642D 43657274
69666963 6174652D 33373238 38393635 39301E17 0D313531 32303331 32353430
335A170D 32303031 30313030 30303030 5A303031 2E302C06 03550403 1325494F
532D5365 6C662D53 69676E65 642D4365 72746966 69636174 652D3337 32383839
36353930 819F300D 06092A86 4886F70D 01010105 0003818D 00308189 02818100
AE294AF5 4B3E652D 48B86C3E 8C55D813 0A77BCD7 FC443B6A F36562D3 2FE47AE8
C6FE44CC 45794852 07D468A0 0565092B 28D1C523 76A7ADD4 116C43EC DF14197E
298E8325 28A205D2 BF337E5C C34BA2D9 E3002988 A5B0577D B1AC6AA6 98F5CB6D
04FA3C1D 28AC01FA 96A86A2D E2499661 F30B1557 E1AC389C B35CA150 5683ED9B
02030100 01A35330 51300F06 03551D13 0101FF04 05300301 01FF301F 0603551D
23041830 16801419 13E44CE2 D16FB24C FF626FD0 1B5FDF0A 84468F30 1D060355
1D0E0416 04141913 E44CE2D1 6FB24CFF 626FD01B 5FDF0A84 468F300D 06092A86
4886F70D 01010505 00038181 008181CD 80376437 DB3B6DF0 2F75F47D A280C0A2
90E9FEB5 D59651BA 5D54CECE B16082DB B53DA7F7 2C40EF4B 7ACD7A42 4DA65F41
8C3680AB A5EC820D 07FD6C91 5CBC62B0 4E3E8F5C A5445FFC 2ABAE60E 56D24EBA
C5A2974C EA63DBB9 F567BC9E 843CAB45 203E0955 53B3B475 673D5589 987013EF
5E19E7CD AEEF039C 1FAB582B 36
quit
!
no ip dhcp use vrf connected
ip dhcp excluded-address 10.0.130.33
!
ip dhcp pool sdm-pool
import all
network 10.0.130.32 255.255.255.224
default-router 10.0.130.33
dns-server 10.0.12.32 10.0.12.16
lease 0 2
!
!
!
ip name-server 195.238.2.21
ip name-server 195.238.2.22
ip cef
no ipv6 cef
!
multilink bundle-name authenticated
!
license udi pid C887VAM-K9 sn FCZ222012JM
!
username janssens.j privilege 15 secret ******************
!
controller VDSL 0
modem co5
!
no cdp run
!
crypto isakmp policy 1
encr 3des
authentication pre-share
group 2
crypto isakmp key ****************** address ******************
crypto isakmp fragmentation
!
crypto ipsec transform-set ESP-3DES-SHA esp-3des esp-sha-hmac
mode tunnel
!
crypto map SDM_CMAP_1 1 ipsec-isakmp
description Tunnel to ******************
set peer ******************
set transform-set ESP-3DES-SHA
match address 100
!
interface ATM0
no ip address
shutdown
no atm ilmi-keepalive
!
interface Ethernet0
no ip address
!
interface Ethernet0.10
encapsulation dot1Q 10
ip nat outside
ip virtual-reassembly in
pppoe enable group global
pppoe-client dial-pool-number 1
!
interface FastEthernet0
description trunk OCWL2SW01
switchport mode trunk
no ip address
!
interface FastEthernet1
no ip address
shutdown
!
interface FastEthernet2
no ip address
shutdown
!
interface FastEthernet3
no ip address
shutdown
!
interface Vlan1
ip address 10.0.130.33 255.255.255.224
ip nat inside
ip rip send version 2
ip rip receive version 2
ip virtual-reassembly in
ip tcp adjust-mss 1412
!
interface Dialer0
mtu 1492
--> ip address negotiated
no ip redirects
no ip unreachables
ip nat outside
ip virtual-reassembly in
encapsulation ppp
dialer pool 1
dialer-group 1
ppp authentication chap callin
ppp chap hostname ******************
ppp chap password 7 ******************
ppp direction callout
ppp ipcp header-compression ack
ppp ipcp dns request accept
ppp ipcp address accept
no cdp enable
crypto map SDM_CMAP_1
crypto ipsec df-bit clear
!
router rip
version 2
redistribute static
network 10.0.0.0
default-information originate
no auto-summary
!
ip forward-protocol nd
no ip http server
ip http access-class 23
ip http authentication local
ip http secure-server
ip http timeout-policy idle 60 life 8640 requests 10000
!
ip nat inside source route-map SDM_RMAP_1 interface Dialer0 overload
ip route 0.0.0.0 0.0.0.0 Dialer0 permanent
!
dialer-list 1 protocol ip permit
!
route-map SDM_RMAP_1 permit 1
match ip address 101
match interface Dialer0
!
snmp-server community public RO
access-list 1 remark SDM_ACL Category=2
access-list 1 permit 10.10.10.0 0.0.0.7
access-list 2 remark SDM_ACM Category=2
access-list 2 permit 10.0.130.32 0.0.0.31
access-list 23 permit 10.0.130.32 0.0.0.31
access-list 100 remark IPSec Rule
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255
access-list 100 remark SDM_ACM Category=4
access-list 101 remark IPSec Rule
access-list 101 remark SDM_ACM Category=2
access-list 101 deny ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255
access-list 101 permit ip 10.0.130.32 0.0.0.31 any
!
control-plane
!
mgcp behavior rsip-range tgcp-only
mgcp behavior comedia-role none
mgcp behavior comedia-check-media-src disable
mgcp behavior comedia-sdp-force disable
!
mgcp profile default
!
line con 0
exec-timeout 5 30
password 7 ******************
login
no modem enable
line aux 0
line vty 0 4
privilege level 15
password 7 ******************
login
transport input telnet ssh
!
scheduler max-task-time 5000
scheduler allocate 20000 1000
!
end

Re: problem with VDSL on 887

Jeroen Janssens — Mon, 25 Jun 2018 08:55:01 GMT

I implemented the changes but doesn't seem to have any effect.

*Jun 25 08:50:21.222: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=67, seq = 0, len=16, tx buf @0x1DD131C0, rx buf @0x1DD131C0

*Jun 25 08:50:21.222: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 16 @0x1DD131C0, rx_len = 16 @0x1DD131C0
*Jun 25 08:50:21.222: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:50:21.222: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 67x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:50:21.222: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382,
total len= 16, msg len= 16, @28
*Jun 25 08:50:21.222: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:50:21.222: TX: Msg for opcode(67)...waiting for Response from Mailbox!

*Jun 25 08:50:21.322: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 16, msg len= 16, @618
*Jun 25 08:50:21.322: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 16 00x 02x 67x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:50:21.322: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD131D0, len= 16
*Jun 25 08:50:21.322: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 16, 0x1DD131C0
*Jun 25 08:50:21.322: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=67
*Jun 25 08:50:21.322: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB30 opcode=67 to caller

*Jun 25 08:50:21.322: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 67

*Jun 25 08:50:21.322: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:50:21.322: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:50:21.322: TX: Call for opcode 67 Success!

*Jun 25 08:50:21.322: ipc VDSL 0: vdsl_diag_start,
*Jun 25 08:50:21.322: vdsl_diag_start: Successful Return !

*Jun 25 08:50:25.221: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 25 08:50:35.221: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 25 08:50:45.217: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 25 08:50:51.353: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E004, total len= 28, msg len= 28, @618
*Jun 25 08:50:51.353: mbx VDSL 0: vdsl_msg_rcv_isr, Notification msg type 4, len= 28
*Jun 25 08:50:51.353: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1E933800, len= 28 00x 04x 11x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 42x
*Jun 25 08:50:51.353: 4294967242x 55x 16x 127x 4294967244x 4294967292x 4294967288x 00x 00x 00x 00x
*Jun 25 08:50:51.353: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1E93381C, len= 28
*Jun 25 08:50:51.353: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 4 rx handler, err= 0, len= 28, 0x1E933800
*Jun 25 08:50:55.249: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 25 08:50:59.725: VDSL 0: SM_LINE_SHOWTIME boolean event
*Jun 25 08:50:59.725: VDSL 0: line state : showtime !
*Jun 25 08:51:00.725: vdsl_daemon_sm VDSL 0: during state training, got event 18(showtime)
*Jun 25 08:51:00.725: @@@ vdsl_daemon_sm VDSL 0: training -> ready
*Jun 25 08:51:00.725: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=14, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0

*Jun 25 08:51:00.725: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 36 @0x1DD131C0
*Jun 25 08:51:00.725: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:51:00.725: 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 25 08:51:00.725: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:00.725: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 25 08:51:00.725: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:00.725: TX: Msg for opcode(14)...waiting for Response from Mailbox!

*Jun 25 08:51:00.833: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 36, msg len= 36, @618
*Jun 25 08:51:00.833: 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 25 08:51:00.837: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 02x 00x
*Jun 25 08:51:00.837: 00x 00x 00x
*Jun 25 08:51:00.837: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD131E4, len= 36
*Jun 25 08:51:00.837: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD131C0
*Jun 25 08:51:00.837: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=14
*Jun 25 08:51:00.837: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB3C opcode=14 to caller

*Jun 25 08:51:00.837: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 14

*Jun 25 08:51:00.837: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:51:00.837: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:00.837: TX: Call for opcode 14 Success!

*Jun 25 08:51:00.837: VDSL 0: selected tc = 0, sysif = -1
*Jun 25 08:51:00.837: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=17, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0

*Jun 25 08:51:00.837: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 36 @0x1DD131C0
*Jun 25 08:51:00.837: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:51:00.837: 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 25 08:51:00.837: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:00.837: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 25 08:51:00.837: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:00.837: TX: Msg for opcode(17)...waiting for Response from Mailbox!

*Jun 25 08:51:00.933: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E002, total len= 36, msg len= 36, @618
*Jun 25 08:51:00.933: 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 25 08:51:00.933: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:00.933: 00x 00x 01x
*Jun 25 08:51:00.933: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD131E4, len= 36
*Jun 25 08:51:00.933: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD131C0
*Jun 25 08:51:00.933: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=17
*Jun 25 08:51:00.933: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB30 opcode=17 to caller

*Jun 25 08:51:00.933: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 17

*Jun 25 08:51:00.933: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:51:00.933: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:00.933: TX: Call for opcode 17 Success!

*Jun 25 08:51:00.933: ipc VDSL 0: vdsl_g997_atu_systemenabling_status_get,
*Jun 25 08:51:00.933: vdsl_g997_atu_systemenabling_status_get: Successful Return !

*Jun 25 08:51:00.933: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0

*Jun 25 08:51:00.933: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 140 @0x1DD131C0
*Jun 25 08:51:00.933: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:51:00.933: 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 25 08:51:00.933: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:00.933: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 001E: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 25 08:51:00.933: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:00.933: TX: Msg for opcode(10)...waiting for Response from Mailbox!

*Jun 25 08:51:01.061: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 140, msg len= 140, @618
*Jun 25 08:51:01.061: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.061: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.061: 00x 116x 23x 00x 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.061: 00x 12x 4294967168x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 25 08:51:01.061: 00x 00x 4294967193x 00x 00x 00x 06x 00x 00x 30x 123x 00x 00x 00x 4294967193x 00x
*Jun 25 08:51:01.061: 00x 00x 00x 00x 00x 00x 00x 00x 01x 119x 4294967189x 00x 01x 119x 4294967189x 00x
*Jun 25 08:51:01.061: 00x 00x 00x
*Jun 25 08:51:01.061: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1324C, len= 140
*Jun 25 08:51:01.061: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 140, 0x1DD131C0
*Jun 25 08:51:01.061: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 25 08:51:01.061: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB3C opcode=10 to caller

*Jun 25 08:51:01.061: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10

*Jun 25 08:51:01.061: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:51:01.061: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.061: TX: Call for opcode 10 Success!

*Jun 25 08:51:01.061: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 25 08:51:01.061: vdsl_g997_channel_status_get: Successful Return !

*Jun 25 08:51:01.061: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0

*Jun 25 08:51:01.061: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 140 @0x1DD131C0
*Jun 25 08:51:01.061: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:51:01.061: 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 25 08:51:01.061: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.061: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 25 08:51:01.061: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.061: TX: Msg for opcode(10)...waiting for Response from Mailbox!

*Jun 25 08:51:01.185: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E002, total len= 140, msg len= 140, @618
*Jun 25 08:51:01.185: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 01x 00x 00x 00x
*Jun 25 08:51:01.185: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.185: 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.185: 00x 01x 4294967184x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 25 08:51:01.185: 00x 00x 32x 00x 00x 00x 16x 00x 00x 00x 16x 00x 00x 00x 32x 00x
*Jun 25 08:51:01.185: 00x 00x 01x 00x 00x 00x 00x 00x 01x 119x 4294967189x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.185: 00x 00x 00x
*Jun 25 08:51:01.185: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1324C, len= 140
*Jun 25 08:51:01.185: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 140, 0x1DD131C0
*Jun 25 08:51:01.185: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 25 08:51:01.185: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB30 opcode=10 to caller

*Jun 25 08:51:01.185: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10

*Jun 25 08:51:01.185: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:51:01.185: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.185: TX: Call for opcode 10 Success!

*Jun 25 08:51:01.185: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 25 08:51:01.185: vdsl_g997_channel_status_get: Successful Return !

*Jun 25 08:51:01.185: %CONTROLLER-5-UPDOWN: Controller VDSL 0, changed state to up
*Jun 25 08:51:01.185: VDSL 0: api (sys if get) ret = 0
*Jun 25 08:51:01.185: vdsl_daemon_sm VDSL 0: during state ready, got event 20(conn_mode_chk)
*Jun 25 08:51:01.185: @@@ vdsl_daemon_sm VDSL 0: ready -> mode_pending
*Jun 25 08:51:01.185: vdsl_daemon_sm VDSL 0: idle during state mode_pending
*Jun 25 08:51:01.185: @@@ vdsl_daemon_sm VDSL 0: mode_pending -> ready
*Jun 25 08:51:01.185: VDSL 0: tc mode selected = 0
*Jun 25 08:51:01.185: vdsl_daemon_sm VDSL 0: during state ready, got event 22(if_state_chk)
*Jun 25 08:51:01.185: @@@ vdsl_daemon_sm VDSL 0: ready -> readyLink b/w CPUs is set to PTMActivating PTM FPGA mode
*Jun 25 08:51:01.185: vdsl_daemon_sm VDSL 0: during state ready, got event 21(if_wakeup)
*Jun 25 08:51:01.185: @@@ vdsl_daemon_sm VDSL 0: ready -> running
*Jun 25 08:51:01.185: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=10, seq = 0, len=28, tx buf @0x1DD131C0, rx buf @0x1DD131C0

*Jun 25 08:51:01.185: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD131C0, rx_len = 140 @0x1DD131C0
*Jun 25 08:51:01.185: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:51:01.185: 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 25 08:51:01.185: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.185: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382,
total len= 28, msg len= 28, @28
*Jun 25 08:51:01.185: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.185: TX: Msg for opcode(10)...waiting for Response from Mailbox!

*Jun 25 08:51:01.313: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 140, msg len= 140, @618
*Jun 25 08:51:01.313: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 140 00x 02x 10x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.313: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.313: 00x 116x 23x 00x 00x 116x 23x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.313: 00x 12x 4294967168x 00x 00x 00x 01x 00x 00x 00x 00x 00x 00x 00x 01x 00x
*Jun 25 08:51:01.313: 00x 00x 4294967193x 00x 00x 00x 06x 00x 00x 30x 123x 00x 00x 00x 4294967193x 00x
*Jun 25 08:51:01.313: 00x 00x 00x 00x 00x 00x 00x 00x 01x 119x 4294967189x 00x 01x 119x 4294967189x 00x
*Jun 25 08:51:01.313: 00x 00x 00x
*Jun 25 08:51:01.313: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1324C, len= 140
*Jun 25 08:51:01.313: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 140, 0x1DD131C0
*Jun 25 08:51:01.313: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=10
*Jun 25 08:51:01.313: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB3C opcode=10 to caller

*Jun 25 08:51:01.313: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 10

*Jun 25 08:51:01.313: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:51:01.313: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.313: TX: Call for opcode 10 Success!

*Jun 25 08:51:01.313: ipc VDSL 0: vdsl_g997_channel_status_get,
*Jun 25 08:51:01.313: vdsl_g997_channel_status_get: Successful Return !

*Jun 25 08:51:01.313: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=70, seq = 0, len=64, tx buf @0x1DD131C0, rx buf @0x1DD131C0

*Jun 25 08:51:01.313: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 64 @0x1DD131C0, rx_len = 4160 @0x1DD131C0
*Jun 25 08:51:01.313: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:51:01.313: 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 25 08:51:01.313: 102x 105x 103x 32x 101x 116x 104x 49x 32x 117x 112x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.313: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.313: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 16x 00x
*Jun 25 08:51:01.313: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382,
total len= 64, msg len= 64, @28
*Jun 25 08:51:01.313: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.313: TX: Msg for opcode(70)...waiting for Response from Mailbox!

*Jun 25 08:51:01.517: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E002, total len= 4160, msg len= 4160, @618
*Jun 25 08:51:01.517: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD131C0, len= 4160 00x 02x 70x 02x 00x 00x 00x 00x 00x 00x 00x 00x 105x 102x 99x 111x 110x
*Jun 25 08:51:01.517: 102x 105x 103x 32x 101x 116x 104x 49x 32x 117x 112x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.521: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.521: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 4294967191x
*Jun 25 08:51:01.521: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x
*Jun 25 08:51:01.521: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 00x 00x 00x 00x 00x 00x 26x 17x 00x
*Jun 25 08:51:01.521: 67x 05x 4294967232x
*Jun 25 08:51:01.521: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD14200, len= 4160
*Jun 25 08:51:01.521: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 4160, 0x1DD131C0
*Jun 25 08:51:01.521: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=70
*Jun 25 08:51:01.521: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB30 opcode=70 to caller

*Jun 25 08:51:01.521: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 70

*Jun 25 08:51:01.521: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:51:01.521: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.521: TX: Call for opcode 70 Success!

*Jun 25 08:51:01.521: ipc VDSL 0: vdsl_send_modem_command,
*Jun 25 08:51:01.521: vdsl_send_modem_command: Successful Return !

*Jun 25 08:51:01.621: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=91, seq = 0, len=76, tx buf @0x1DD131C0, rx buf @0x1DD131C0

*Jun 25 08:51:01.621: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 76 @0x1DD131C0, rx_len = 76 @0x1DD131C0
*Jun 25 08:51:01.621: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:51:01.621: 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 25 08:51:01.621: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.621: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.621: 00x 00x 00x 00x 4294967292x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.621: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.621: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 001E: hdr= E382,
total len= 76, msg len= 76, @28
*Jun 25 08:51:01.621: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.621: TX: Msg for opcode(91)...waiting for Response from Mailbox!

*Jun 25 08:51:01.765: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 76, msg len= 76, @618
*Jun 25 08:51:01.765: 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 25 08:51:01.765: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.765: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.765: 00x 00x 00x 00x 4294967292x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.765: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:01.765: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD1320C, len= 76
*Jun 25 08:51:01.765: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 76, 0x1DD131C0
*Jun 25 08:51:01.765: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=91
*Jun 25 08:51:01.765: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB3C opcode=91 to caller

*Jun 25 08:51:01.765: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 91

*Jun 25 08:51:01.765: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:51:01.765: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:01.765: TX: Call for opcode 91 Success!

*Jun 25 08:51:01.765: ipc VDSL 0: vdsl_send_watermark_command,
*Jun 25 08:51:01.765: vdsl_send_watermark_command: Successful Return !

*Jun 25 08:51:01.765: VDSL 0: VDSL PTM mode is activated
*Jun 25 08:51:01.765: vdsl_daemon_sm VDSL 0: during state running, got event 23(linkup)
*Jun 25 08:51:01.765: @@@ vdsl_daemon_sm VDSL 0: running -> running
*Jun 25 08:51:01.765: VDSL 0: api (sys if get) ret = 0
*Jun 25 08:51:03.313: %LINK-3-UPDOWN: Interface Ethernet0, changed state to up
*Jun 25 08:51:04.313: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0, changed state to up
*Jun 25 08:51:06.013: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 25 08:51:16.009: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
*Jun 25 08:51:19.709: VDSL 0: SM_LINE_DOWN boolean event
*Jun 25 08:51:19.709: %CONTROLLER-5-UPDOWN: Controller VDSL 0, changed state to down
*Jun 25 08:51:19.709: vdsl_daemon_sm VDSL 0: during state running, got event 24(linkdown)
*Jun 25 08:51:19.709: @@@ vdsl_daemon_sm VDSL 0: running -> training
*Jun 25 08:51:19.709: VDSL 0: VDSL PTM mode is de-activated
*Jun 25 08:51:19.709: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=70, seq = 0, len=64, tx buf @0x1DD155C0, rx buf @0x1DD155C0

*Jun 25 08:51:19.709: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 64 @0x1DD155C0, rx_len = 4160 @0x1DD155C0
*Jun 25 08:51:19.709: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
*Jun 25 08:51:19.709: 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 25 08:51:19.709: 102x 105x 103x 32x 101x 116x 104x 49x 32x 100x 111x 119x 110x 00x 00x 00x
*Jun 25 08:51:19.709: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:19.709: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 16x 00x
*Jun 25 08:51:19.709: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382,
total len= 64, msg len= 64, @28
*Jun 25 08:51:19.709: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:19.709: TX: Msg for opcode(70)...waiting for Response from Mailbox!

*Jun 25 08:51:19.917: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E002, total len= 4160, msg len= 4160, @618
*Jun 25 08:51:19.917: 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 25 08:51:19.917: 102x 105x 103x 32x 101x 116x 104x 49x 32x 100x 111x 119x 110x 00x 00x 00x
*Jun 25 08:51:19.917: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
*Jun 25 08:51:19.917: 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 4294967191x
*Jun 25 08:51:19.917: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x
*Jun 25 08:51:19.917: 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 4294967191x 00x 00x 00x 00x 00x 00x 26x 17x 00x
*Jun 25 08:51:19.917: 67x 05x 4294967232x
*Jun 25 08:51:19.917: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD16600, len= 4160
*Jun 25 08:51:19.917: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 4160, 0x1DD155C0
*Jun 25 08:51:19.917: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=70
*Jun 25 08:51:19.917: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x18EAB30 opcode=70 to caller

*Jun 25 08:51:19.917: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 70

*Jun 25 08:51:19.917: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler

*Jun 25 08:51:19.917: ipc VDSL 0: vdsl_ipc_send,
*Jun 25 08:51:19.917: TX: Call for opcode 70 Success!

*Jun 25 08:51:19.917: ipc VDSL 0: vdsl_send_modem_command,
*Jun 25 08:51:19.917: vdsl_send_modem_command: Successful Return !

*Jun 25 08:51:19.917: vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
*Jun 25 08:51:19.917: @@@ vdsl_daemon_sm VDSL 0: training -> training
*Jun 25 08:51:20.709: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0, changed state to down
*Jun 25 08:51:21.917: %LINK-3-UPDOWN: Interface Ethernet0, changed state to down
*Jun 25 08:51:21.973: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 8

*Jun 25 08:51:21.973: VDSL 0: vdsl line state : discovery
*Jun 25 08:51:21.973: VDSL 0: SM_LINE_TRAIN boolean event
*Jun 25 08:51:21.973: vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
*Jun 25 08:51:21.973: @@@ vdsl_daemon_sm VDSL 0: training -> training
*Jun 25 08:51:26.161: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE

Re: problem with VDSL on 887

Jeroen Janssens — Mon, 25 Jun 2018 08:56:35 GMT

I used the IP address because this connection has a fixed ip address so I can set up a site-to-site vpn.

Re: problem with VDSL on 887

Georg Pauwen — Mon, 25 Jun 2018 13:54:06 GMT

Hello Jeroen,

can you debug ppp negotiation and post the output ?

Re: problem with VDSL on 887

Jeroen Janssens — Mon, 25 Jun 2018 14:43:05 GMT

I updated the firmware and now the connection seems to remain up. There are still issues with VPN but I will look into those tomorrow.

Re: problem with VDSL on 887

Georg Pauwen — Mon, 25 Jun 2018 15:02:52 GMT

Hello Jeroen,

for reference purposes can you post the working configuration ?

And what VPN issues are you experiencing ?

Re: problem with VDSL on 887

Jeroen Janssens — Tue, 26 Jun 2018 07:53:08 GMT

This is the current config. With this, the VDSL/PPP stays up (although I cannot surf the internet when I connect my laptop).

OCWRTR01#show run
Building configuration...

!
no ip dhcp use vrf connected
ip dhcp excluded-address 10.0.130.33
!
ip dhcp pool sdm-pool
import all
network 10.0.130.32 255.255.255.224
default-router 10.0.130.33
dns-server 10.0.12.32 10.0.12.16
lease 0 2
!
!
!
ip name-server 195.238.2.21
ip name-server 195.238.2.22
ip cef
no ipv6 cef
!
!
!
!
!
multilink bundle-name authenticated
!
!
!
!
!
!
!
license udi pid C887VAM-K9 sn FCZ222012JM
!
!
username janssens.j privilege 15 secret 5 **********************
!
!
!
!
!
controller VDSL 0
firmware filename flash:VA_A_39d_B_38h3_24h.bin
no cdp run
!
!
!
crypto isakmp policy 1
encr 3des
authentication pre-share
group 2
crypto isakmp key **********************address 194.78.59.5
crypto isakmp fragmentation
!
!
crypto ipsec transform-set ESP-3DES-SHA esp-3des esp-sha-hmac
mode tunnel
!
!
!
crypto map SDM_CMAP_1 1 ipsec-isakmp
description Tunnel to 194.78.59.5
set peer 194.78.59.5
set transform-set ESP-3DES-SHA
match address 100
!
!
!
!
!
!
interface ATM0
no ip address
shutdown
no atm ilmi-keepalive
!
interface Ethernet0
no ip address
!
interface Ethernet0.10
encapsulation dot1Q 10
ip nat outside
ip virtual-reassembly in
pppoe enable group global
pppoe-client dial-pool-number 1
!
interface FastEthernet0
description trunk OCWL2SW01
switchport mode trunk
no ip address
!
interface FastEthernet1
switchport access vlan 60
no ip address
!
interface FastEthernet2
no ip address
shutdown
!
interface FastEthernet3
no ip address
shutdown
!
interface Vlan1
ip address 10.0.130.33 255.255.255.224
ip nat inside
ip rip send version 2
ip rip receive version 2
ip virtual-reassembly in
ip tcp adjust-mss 1412
!
interface Dialer0
mtu 1200
ip address 109.135.19.130 255.255.255.0
ip nat outside
ip virtual-reassembly in
encapsulation ppp
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
!
router rip
version 2
redistribute static
network 10.0.0.0
default-information originate
no auto-summary
!
ip forward-protocol nd
no ip http server
ip http access-class 23
ip http authentication local
ip http secure-server
ip http timeout-policy idle 60 life 8640 requests 10000
!
!
ip nat inside source route-map SDM_RMAP_1 interface Dialer0 overload
ip route 0.0.0.0 0.0.0.0 Dialer0 permanent
!
dialer-list 1 protocol ip permit
!
route-map SDM_RMAP_1 permit 1
match ip address 101
match interface Dialer0
!
snmp-server community public RO
access-list 1 remark SDM_ACL Category=2
access-list 1 permit 10.10.10.0 0.0.0.7
access-list 2 remark SDM_ACM Category=2
access-list 2 permit 10.0.130.32 0.0.0.31
access-list 23 permit 10.0.130.32 0.0.0.31
access-list 100 remark IPSec Rule
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255
access-list 100 remark SDM_ACM Category=4
access-list 101 remark IPSec Rule
access-list 101 remark SDM_ACM Category=2
access-list 101 deny ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255
access-list 101 permit ip 10.0.130.32 0.0.0.31 any
!
control-plane
!
!
!
mgcp behavior rsip-range tgcp-only
mgcp behavior comedia-role none
mgcp behavior comedia-check-media-src disable
mgcp behavior comedia-sdp-force disable
!
mgcp profile default
!
!
!
!
!
!
!
line con 0
exec-timeout 5 30
password 7 **********************
login
no modem enable
line aux 0
line vty 0 4
privilege level 15
password 7 **********************
login
transport input telnet ssh
!
scheduler max-task-time 5000
scheduler allocate 20000 1000
!
end

Re: problem with VDSL on 887

Jeroen Janssens — Tue, 26 Jun 2018 07:56:27 GMT

The VPN doesn't come up. I checked the configuration on both ends.

What are some usefull debug commands ?

OCWRTR01#debug crypto ipsec
Crypto IPSEC debugging is on
OCWRTR01#
*Jun 26 07:37:18.080: IPSEC:(SESSION ID = 1) (key_engine) request timer fired: c ount = 2,
(identity) local= 109.135.19.130:0, remote= 194.78.59.5:0,
local_proxy= 10.0.130.32/255.255.255.224/256/0,
remote_proxy= 10.0.0.0/255.255.0.0/256/0
*Jun 26 07:37:18.168: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 109.135.19.130:500, remote= 194.78.59.5:500,
local_proxy= 10.0.130.32/255.255.255.224/256/0,
remote_proxy= 10.0.0.0/255.255.0.0/256/0,
protocol= ESP, transform= esp-3des esp-sha-hmac (Tunnel),
lifedur= 3600s and 4608000kb,
spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
*Jun 26 07:37:18.523: IPSEC(key_engine): got a queue event with 1 KMI message(s)
*Jun 26 07:37:48.167: IPSEC:(SESSION ID = 1) (key_engine) request timer fired: c ount = 1,
(identity) local= 109.135.19.130:0, remote= 194.78.59.5:0,
local_proxy= 10.0.130.32/255.255.255.224/256/0,
remote_proxy= 10.0.0.0/255.255.0.0/256/0
*Jun 26 07:37:48.167: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 109.135.19.130:500, remote= 194.78.59.5:500,
local_proxy= 10.0.130.32/255.255.255.224/256/0,
remote_proxy= 10.0.0.0/255.255.0.0/256/0,
protocol= ESP, transform= esp-3des esp-sha-hmac (Tunnel),
lifedur= 3600s and 4608000kb,
spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
*Jun 26 07:37:48.299: IPSEC(key_engine): got a queue event with 1 KMI message(s)
*Jun 26 07:38:18.167: IPSEC:(SESSION ID = 1) (key_engine) request timer fired: c ount = 2,
(identity) local= 109.135.19.130:0, remote= 194.78.59.5:0,
local_proxy= 10.0.130.32/255.255.255.224/256/0,
remote_proxy= 10.0.0.0/255.255.0.0/256/0
*Jun 26 07:38:18.867: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 109.135.19.130:500, remote= 194.78.59.5:500,
local_proxy= 10.0.130.32/255.255.255.224/256/0,
remote_proxy= 10.0.0.0/255.255.0.0/256/0,
protocol= ESP, transform= esp-3des esp-sha-hmac (Tunnel),
lifedur= 3600s and 4608000kb,
spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
*Jun 26 07:38:18.995: IPSEC(key_engine): got a queue event with 1 KMI message(s)

Re: problem with VDSL on 887

Jeroen Janssens — Tue, 26 Jun 2018 08:08:26 GMT

OCWRTR01#debug crypto isakmp
*Jun 26 08:03:43.808: IPSEC:(SESSION ID = 1) (key_engine) request timer fired: count = 1,
(identity) local= 109.135.19.130:0, remote= 194.78.59.5:0,
local_proxy= 10.0.130.32/255.255.255.224/256/0,
remote_proxy= 10.0.0.0/255.255.0.0/256/0
*Jun 26 08:03:43.808: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 109.135.19.130:500, remote= 194.78.59.5:500,
local_proxy= 10.0.130.32/255.255.255.224/256/0,
remote_proxy= 10.0.0.0/255.255.0.0/256/0,
protocol= ESP, transform= esp-3des esp-sha-hmac (Tunnel),
lifedur= 3600s and 4608000kb,
spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
*Jun 26 08:03:43.808: ISAKMP: (0):SA request profile is (NULL)
*Jun 26 08:03:43.808: ISAKMP: (0):Created a peer struct for 194.78.59.5, peer port 500
*Jun 26 08:03:43.808: ISAKMP: (0):New peer created peer = 0x12AB1650 peer_handle = 0x80000012
*Jun 26 08:03:43.808: ISAKMP: (0):Locking peer struct 0x12AB1650, refcount 1 for isakmp_initiator
*Jun 26 08:03:43.808: ISAKMP: (0):local port 500, remote port 500
*Jun 26 08:03:43.808: ISAKMP: (0):set new node 0 to QM_IDLE
*Jun 26 08:03:43.808: ISAKMP: (0):Find a dup sa in the avl tree during calling isadb_insert sa = 39D9440
*Jun 26 08:03:43.808: ISAKMP: (0):Can not start Aggressive mode, trying Main mode.
*Jun 26 08:03:43.808: ISAKMP: (0):found peer pre-shared key matching 194.78.59.5
*Jun 26 08:03:43.808: ISAKMP: (0):constructed NAT-T vendor-rfc3947 ID
*Jun 26 08:03:43.808: ISAKMP: (0):constructed NAT-T vendor-07 ID
*Jun 26 08:03:43.808: ISAKMP: (0):constructed NAT-T vendor-03 ID
*Jun 26 08:03:43.808: ISAKMP: (0):constructed NAT-T vendor-02 ID
*Jun 26 08:03:43.808: ISAKMP: (0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
*Jun 26 08:03:43.808: ISAKMP: (0):Old State = IKE_READY New State = IKE_I_MM1

*Jun 26 08:03:43.808: ISAKMP: (0):beginning Main Mode exchange
*Jun 26 08:03:43.808: ISAKMP-PAK: (0):sending packet to 194.78.59.5 my_port 500 peer_port 500 (I) MM_NO_STATE
*Jun 26 08:03:43.808: ISAKMP: (0):Sending an IKE IPv4 Packet.
*Jun 26 08:03:43.836: ISAKMP-PAK: (0):received packet from 194.78.59.5 dport 500 sport 500 Global (I) MM_NO_STATE
*Jun 26 08:03:43.836: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Jun 26 08:03:43.840: ISAKMP: (0):Old State = IKE_I_MM1 New State = IKE_I_MM2

*Jun 26 08:03:43.840: ISAKMP: (0):processing SA payload. message ID = 0
*Jun 26 08:03:43.840: ISAKMP: (0):processing vendor id payload
*Jun 26 08:03:43.840: ISAKMP: (0):vendor ID seems Unity/DPD but major 123 mismatch
*Jun 26 08:03:43.840: ISAKMP: (0):vendor ID is NAT-T v2
*Jun 26 08:03:43.840: ISAKMP: (0):processing vendor id payload
*Jun 26 08:03:43.840: ISAKMP: (0):processing IKE frag vendor id payload
*Jun 26 08:03:43.840: ISAKMP: (0):Support for IKE Fragmentation not enabled
*Jun 26 08:03:43.840: ISAKMP: (0):found peer pre-shared key matching 194.78.59.5
*Jun 26 08:03:43.840: ISAKMP: (0):local preshared key found
*Jun 26 08:03:43.840: ISAKMP: (0):Scanning profiles for xauth ...
*Jun 26 08:03:43.840: ISAKMP: (0):Checking ISAKMP transform 1 against priority 1 policy
*Jun 26 08:03:43.840: ISAKMP: (0): encryption 3DES-CBC
*Jun 26 08:03:43.840: ISAKMP: (0): hash SHA
*Jun 26 08:03:43.840: ISAKMP: (0): default group 2
*Jun 26 08:03:43.840: ISAKMP: (0): auth pre-share
*Jun 26 08:03:43.840: ISAKMP: (0): life type in seconds
*Jun 26 08:03:43.840: ISAKMP: life duration (VPI) of 0x0 0x1 0x51 0x80
*Jun 26 08:03:43.840: ISAKMP: (0):atts are acceptable. Next payload is 0
*Jun 26 08:03:43.840: ISAKMP: (0):Acceptable atts:actual life: 0
*Jun 26 08:03:43.840: ISAKMP: (0):Acceptable atts:life: 0
*Jun 26 08:03:43.840: ISAKMP: (0):Fill atts in sa vpi_length:4
*Jun 26 08:03:43.840: ISAKMP: (0):Fill atts in sa life_in_seconds:86400
*Jun 26 08:03:43.840: ISAKMP: (0):Returning Actual lifetime: 86400
*Jun 26 08:03:43.840: ISAKMP: (0):Started lifetime timer: 86400.

*Jun 26 08:03:43.840: ISAKMP: (0):processing vendor id payload
*Jun 26 08:03:43.840: ISAKMP: (0):vendor ID seems Unity/DPD but major 123 mismatch
*Jun 26 08:03:43.840: ISAKMP: (0):vendor ID is NAT-T v2
*Jun 26 08:03:43.840: ISAKMP: (0):processing vendor id payload
*Jun 26 08:03:43.840: ISAKMP: (0):processing IKE frag vendor id payload
*Jun 26 08:03:43.840: ISAKMP: (0):Support for IKE Fragmentation not enabled
*Jun 26 08:03:43.840: ISAKMP: (0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Jun 26 08:03:43.840: ISAKMP: (0):Old State = IKE_I_MM2 New State = IKE_I_MM2

*Jun 26 08:03:43.840: ISAKMP-PAK: (0):sending packet to 194.78.59.5 my_port 500 peer_port 500 (I) MM_SA_SETUP
*Jun 26 08:03:43.840: ISAKMP: (0):Sending an IKE IPv4 Packet.
*Jun 26 08:03:43.840: ISAKMP: (0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Jun 26 08:03:43.840: ISAKMP: (0):Old State = IKE_I_MM2 New State = IKE_I_MM3

*Jun 26 08:03:43.876: ISAKMP-PAK: (0):received packet from 194.78.59.5 dport 500 sport 500 Global (I) MM_SA_SETUP
*Jun 26 08:03:43.876: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Jun 26 08:03:43.876: ISAKMP: (0):Old State = IKE_I_MM3 New State = IKE_I_MM4

*Jun 26 08:03:43.876: ISAKMP: (0):processing KE payload. message ID = 0
*Jun 26 08:03:43.876: ISAKMP: (0):processing NONCE payload. message ID = 0
*Jun 26 08:03:43.876: ISAKMP: (0):found peer pre-shared key matching 194.78.59.5
*Jun 26 08:03:43.876: ISAKMP: (2015):processing vendor id payload
*Jun 26 08:03:43.876: ISAKMP: (2015):vendor ID is Unity
*Jun 26 08:03:43.880: ISAKMP: (2015):processing vendor id payload
*Jun 26 08:03:43.880: ISAKMP: (2015):vendor ID seems Unity/DPD but major 93 mismatch
*Jun 26 08:03:43.880: ISAKMP: (2015):vendor ID is XAUTH
*Jun 26 08:03:43.880: ISAKMP: (2015):processing vendor id payload
*Jun 26 08:03:43.880: ISAKMP: (2015):speaking to another IOS box!
*Jun 26 08:03:43.880: ISAKMP: (2015):processing vendor id payload
*Jun 26 08:03:43.880: ISAKMP: (2015):vendor ID seems Unity/DPD but hash mismatch
*Jun 26 08:03:43.880: ISAKMP: (2015):received payload type 20
*Jun 26 08:03:43.880: ISAKMP: (2015):His hash no match - this node outside NAT
*Jun 26 08:03:43.880: ISAKMP: (2015):received payload type 20
*Jun 26 08:03:43.880: ISAKMP: (2015):His hash no match - this node outside NAT
*Jun 26 08:03:43.880: ISAKMP: (2015):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Jun 26 08:03:43.880: ISAKMP: (2015):Old State = IKE_I_MM4 New State = IKE_I_MM4

*Jun 26 08:03:43.880: ISAKMP: (2015):Send initial contact
*Jun 26 08:03:43.880: ISAKMP: (2015):SA is doing
*Jun 26 08:03:43.880: ISAKMP: (2015):pre-shared key authentication using id type ID_IPV4_ADDR
*Jun 26 08:03:43.880: ISAKMP: (2015):ID payload
next-payload : 8
type : 1
*Jun 26 08:03:43.880: ISAKMP: (2015): address : 109.135.19.130
*Jun 26 08:03:43.880: ISAKMP: (2015): protocol : 17
port : 0
length : 12
*Jun 26 08:03:43.880: ISAKMP: (2015):Total payload length: 12
*Jun 26 08:03:43.880: ISAKMP-PAK: (2015):sending packet to 194.78.59.5 my_port 4500 peer_port 4500 (I) MM_KEY_EXCH
*Jun 26 08:03:43.880: ISAKMP: (2015):Sending an IKE IPv4 Packet.
*Jun 26 08:03:43.880: ISAKMP: (2015):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Jun 26 08:03:43.880: ISAKMP: (2015):Old State = IKE_I_MM4 New State = IKE_I_MM5

*Jun 26 08:03:43.908: ISAKMP-PAK: (2015):received packet from 194.78.59.5 dport 4500 sport 4500 Global (I) MM_KEY_EXCH
*Jun 26 08:03:43.908: ISAKMP: (2015):processing ID payload. message ID = 0
*Jun 26 08:03:43.908: ISAKMP: (2015):ID payload
next-payload : 8
type : 2
*Jun 26 08:03:43.908: ISAKMP: (2015): FQDN name : GADFRWL01.lede.local
*Jun 26 08:03:43.908: ISAKMP: (2015): protocol : 0
port : 0
length : 28
*Jun 26 08:03:43.908: ISAKMP: (0):peer matches *none* of the profiles
*Jun 26 08:03:43.908: ISAKMP: (2015):processing HASH payload. message ID = 0
*Jun 26 08:03:43.908: ISAKMP: (2015):received payload type 17
*Jun 26 08:03:43.908: ISAKMP: (2015):processing vendor id payload
*Jun 26 08:03:43.908: ISAKMP: (2015):vendor ID is DPD
*Jun 26 08:03:43.908: ISAKMP: (2015):SA authentication status:
authenticated
*Jun 26 08:03:43.908: ISAKMP: (2015):SA has been authenticated with 194.78.59.5
*Jun 26 08:03:43.908: ISAKMP: (0):Trying to insert a peer 109.135.19.130/194.78.59.5/4500/,
*Jun 26 08:03:43.908: ISAKMP: (0): and inserted successfully 12AB1650.
*Jun 26 08:03:43.908: ISAKMP: (2015):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Jun 26 08:03:43.908: ISAKMP: (2015):Old State = IKE_I_MM5 New State = IKE_I_MM6

*Jun 26 08:03:43.912: ISAKMP: (2015):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Jun 26 08:03:43.912: ISAKMP: (2015):Old State = IKE_I_MM6 New State = IKE_I_MM6

*Jun 26 08:03:43.912: ISAKMP: (2015):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Jun 26 08:03:43.912: ISAKMP: (2015):Old State = IKE_I_MM6 New State = IKE_P1_COMPLETE

*Jun 26 08:03:43.912: ISAKMP: (2015):beginning Quick Mode exchange, M-ID of 3793647221
*Jun 26 08:03:43.912: ISAKMP: (2015):QM Initiator gets spi
*Jun 26 08:03:43.912: ISAKMP-PAK: (2015):sending packet to 194.78.59.5 my_port 4500 peer_port 4500 (I) QM_IDLE
*Jun 26 08:03:43.912: ISAKMP: (2015):Sending an IKE IPv4 Packet.
*Jun 26 08:03:43.912: ISAKMP: (2015):Node 3793647221, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
*Jun 26 08:03:43.912: ISAKMP: (2015):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
*Jun 26 08:03:43.912: ISAKMP: (2015):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
*Jun 26 08:03:43.912: ISAKMP: (2015):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

*Jun 26 08:03:43.944: ISAKMP-PAK: (2015):received packet from 194.78.59.5 dport 4500 sport 4500 Global (I) QM_IDLE
*Jun 26 08:03:43.944: ISAKMP: (2015):set new node 808138225 to QM_IDLE
*Jun 26 08:03:43.944: ISAKMP: (2015):processing HASH payload. message ID = 808138225
*Jun 26 08:03:43.944: ISAKMP: (2015):processing NOTIFY PROPOSAL_NOT_CHOSEN protocol 3
spi 0, message ID = 808138225, sa = 0x39D9440
*Jun 26 08:03:43.944: ISAKMP: (2015):deleting node 808138225 error FALSE reason "Informational (in) state 1"
*Jun 26 08:03:43.944: ISAKMP: (2015):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY
*Jun 26 08:03:43.944: ISAKMP: (2015):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

*Jun 26 08:03:43.944: ISAKMP-PAK: (2015):received packet from 194.78.59.5 dport 4500 sport 4500 Global (I) QM_IDLE
*Jun 26 08:03:43.944: ISAKMP: (2015):set new node 529175476 to QM_IDLE
*Jun 26 08:03:43.944: ISAKMP: (2015):processing HASH payload. message ID = 529175476
*Jun 26 08:03:43.944: ISAKMP: (2015):processing DELETE payload. message ID = 529175476
*Jun 26 08:03:43.944: ISAKMP: (2015):peer does not do paranoid keepalives.
*Jun 26 08:03:43.944: ISAKMP: (2015):deleting SA reason "No reason" state (I) QM_IDLE (peer 194.78.59.5)
*Jun 26 08:03:43.944: ISAKMP: (2015):deleting node 529175476 error FALSE reason "Informational (in) state 1"
*Jun 26 08:03:43.944: ISAKMP: (2015):set new node -1685401866 to QM_IDLE
*Jun 26 08:03:43.944: ISAKMP-PAK: (2015):sending packet to 194.78.59.5 my_port 4500 peer_port 4500 (I) QM_IDLE
*Jun 26 08:03:43.944: ISAKMP: (2015):Sending an IKE IPv4 Packet.
*Jun 26 08:03:43.944: ISAKMP: (2015):purging node -1685401866
*Jun 26 08:03:43.944: ISAKMP: (2015):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
*Jun 26 08:03:43.944: ISAKMP: (2015):Old State = IKE_P1_COMPLETE New State = IKE_DEST_SA

*Jun 26 08:03:43.944: ISAKMP: (2015):deleting SA reason "No reason" state (I) QM_IDLE (peer 194.78.59.5)
*Jun 26 08:03:43.944: ISAKMP: (0):Unlocking peer struct 0x12AB1650 for isadb_mark_sa_deleted(), count 0
*Jun 26 08:03:43.944: ISAKMP: (0):Deleting peer node by peer_reap for 194.78.59.5: 12AB1650
*Jun 26 08:03:43.944: ISAKMP: (2015):deleting node -501320075 error FALSE reason "IKE deleted"
*Jun 26 08:03:43.944: ISAKMP: (2015):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Jun 26 08:03:43.944: ISAKMP: (2015):Old State = IKE_DEST_SA New State = IKE_DEST_SA

*Jun 26 08:03:43.944: IPSEC(key_engine): got a queue event with 1 KMI message(s)

Re: problem with VDSL on 887

Georg Pauwen — Tue, 26 Jun 2018 08:12:21 GMT

Hello Jeroen,

I have made some minor changes to your config (marked in bold), check if this gets your clients to browse the Internet (renew the DHCP leases to test):

OCWRTR01#show run
Building configuration...

Current configuration : 5599 bytes
!
version 15.5
no service pad
service timestamps debug datetime msec
service timestamps log datetime msec
service password-encryption
!
hostname OCWRTR01
!
boot-start-marker
boot-end-marker
!
aqm-register-fnf
!
enable secret 5 **********************
enable password 7 **********************
!
no aaa new-model
ethernet lmi ce
clock timezone pctime 1 0
clock summer-time pctime date Mar 30 2003 2:00 Oct 26 2003 3:00
!
crypto pki trustpoint TP-self-signed-372889659
enrollment selfsigned
subject-name cn=IOS-Self-Signed-Certificate-372889659
revocation-check none
rsakeypair TP-self-signed-372889659
!
!
crypto pki certificate chain TP-self-signed-372889659
certificate self-signed 01
30820229 30820192 A0030201 02020101 300D0609 2A864886 F70D0101 05050030
30312E30 2C060355 04031325 494F532D 53656C66 2D536967 6E65642D 43657274
69666963 6174652D 33373238 38393635 39301E17 0D313531 32303331 32353430
335A170D 32303031 30313030 30303030 5A303031 2E302C06 03550403 1325494F
532D5365 6C662D53 69676E65 642D4365 72746966 69636174 652D3337 32383839
36353930 819F300D 06092A86 4886F70D 01010105 0003818D 00308189 02818100
AE294AF5 4B3E652D 48B86C3E 8C55D813 0A77BCD7 FC443B6A F36562D3 2FE47AE8
C6FE44CC 45794852 07D468A0 0565092B 28D1C523 76A7ADD4 116C43EC DF14197E
298E8325 28A205D2 BF337E5C C34BA2D9 E3002988 A5B0577D B1AC6AA6 98F5CB6D
04FA3C1D 28AC01FA 96A86A2D E2499661 F30B1557 E1AC389C B35CA150 5683ED9B
02030100 01A35330 51300F06 03551D13 0101FF04 05300301 01FF301F 0603551D
23041830 16801419 13E44CE2 D16FB24C FF626FD0 1B5FDF0A 84468F30 1D060355
1D0E0416 04141913 E44CE2D1 6FB24CFF 626FD01B 5FDF0A84 468F300D 06092A86
4886F70D 01010505 00038181 008181CD 80376437 DB3B6DF0 2F75F47D A280C0A2
90E9FEB5 D59651BA 5D54CECE B16082DB B53DA7F7 2C40EF4B 7ACD7A42 4DA65F41
8C3680AB A5EC820D 07FD6C91 5CBC62B0 4E3E8F5C A5445FFC 2ABAE60E 56D24EBA
C5A2974C EA63DBB9 F567BC9E 843CAB45 203E0955 53B3B475 673D5589 987013EF
5E19E7CD AEEF039C 1FAB582B 36
quit
!
no ip dhcp use vrf connected
ip dhcp excluded-address 10.0.130.33
!
ip dhcp pool sdm-pool
import all
network 10.0.130.32 255.255.255.224
default-router 10.0.130.33
dns-server 8.8.8.8 8.8.4.4
lease 0 2
!
ip name-server 195.238.2.21
ip name-server 195.238.2.22
ip cef
no ipv6 cef
!
multilink bundle-name authenticated
!
license udi pid C887VAM-K9 sn FCZ222012JM
!
username janssens.j privilege 15 secret 5 **********************
!
controller VDSL 0
firmware filename flash:VA_A_39d_B_38h3_24h.bin
no cdp run
!
crypto isakmp policy 1
encr 3des
authentication pre-share
group 2
crypto isakmp key **********************address 194.78.59.5
crypto isakmp fragmentation
!
crypto ipsec transform-set ESP-3DES-SHA esp-3des esp-sha-hmac
mode tunnel
!
crypto map SDM_CMAP_1 1 ipsec-isakmp
description Tunnel to 194.78.59.5
set peer 194.78.59.5
set transform-set ESP-3DES-SHA
match address 100
!
interface ATM0
no ip address
shutdown
no atm ilmi-keepalive
!
interface Ethernet0
no ip address
!
interface Ethernet0.10
encapsulation dot1Q 10
ip nat outside
ip virtual-reassembly in
pppoe enable group global
pppoe-client dial-pool-number 1
!
interface FastEthernet0
description trunk OCWL2SW01
switchport mode trunk
no ip address
!
interface FastEthernet1
switchport access vlan 60
no ip address
!
interface FastEthernet2
no ip address
shutdown
!
interface FastEthernet3
no ip address
shutdown
!
interface Vlan1
ip address 10.0.130.33 255.255.255.224
ip nat inside
ip rip send version 2
ip rip receive version 2
ip virtual-reassembly in
--> no ip tcp adjust-mss 1412
!
interface Dialer0
mtu 1492
ip address 109.135.19.130 255.255.255.0
ip nat outside
ip virtual-reassembly in
encapsulation ppp
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
!
router rip
version 2
redistribute static
network 10.0.0.0
default-information originate
no auto-summary
!
ip forward-protocol nd
no ip http server
ip http access-class 23
ip http authentication local
ip http secure-server
ip http timeout-policy idle 60 life 8640 requests 10000
!
ip nat inside source route-map SDM_RMAP_1 interface Dialer0 overload
ip route 0.0.0.0 0.0.0.0 Dialer0 permanent
!
dialer-list 1 protocol ip permit
!
route-map SDM_RMAP_1 permit 1
match ip address 101
match interface Dialer0
!
snmp-server community public RO
access-list 1 remark SDM_ACL Category=2
access-list 1 permit 10.10.10.0 0.0.0.7
access-list 2 remark SDM_ACM Category=2
access-list 2 permit 10.0.130.32 0.0.0.31
access-list 23 permit 10.0.130.32 0.0.0.31
access-list 100 remark IPSec Rule
access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255
access-list 100 remark SDM_ACM Category=4
access-list 101 remark IPSec Rule
access-list 101 remark SDM_ACM Category=2
access-list 101 deny ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255
access-list 101 permit ip 10.0.130.32 0.0.0.31 any
!
control-plane
!
mgcp behavior rsip-range tgcp-only
mgcp behavior comedia-role none
mgcp behavior comedia-check-media-src disable
mgcp behavior comedia-sdp-force disable
!
mgcp profile default
!
line con 0
exec-timeout 5 30
password 7 **********************
login
no modem enable
line aux 0
line vty 0 4
privilege level 15
password 7 **********************
login
transport input telnet ssh
!
scheduler max-task-time 5000
scheduler allocate 20000 1000
!
end

Re: problem with VDSL on 887

Jeroen Janssens — Tue, 26 Jun 2018 12:15:20 GMT

After making the config changes, I now have internet access. But still no VPN.

Re: problem with VDSL on 887

Georg Pauwen — Tue, 26 Jun 2018 14:33:30 GMT

Jeroen,

what is on the other side of the VPN ? Can you post the configuration of that device ? From the debug output it looks like phase 2 is not completing. We need to check if the parameters match...