Solved: Re: problem with VDSL on 887 - Page 2

Jeroen Janssens · ‎06-25-2018

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

Jeroen Janssens · ‎06-26-2018

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)

Jeroen Janssens · ‎06-26-2018

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)

Georg Pauwen · ‎06-26-2018

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

Jeroen Janssens · ‎06-26-2018

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

Georg Pauwen · ‎06-26-2018

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

Jeroen Janssens · ‎06-26-2018

I have a cisco ASA 5510 on the other side. I have several other site-to-site VPNs that work so the general settings should be correct.
These should be the relevant sections of the config:

access-list Inside_nat0_outbound extended permit ip object-group GAD object-group SPH
access-list Inside_nat0_outbound extended permit ip object-group GAD object-group BKO
access-list Inside_nat0_outbound extended permit ip object-group GAD 10.0.149.8 255.255.255.248
access-list Inside_nat0_outbound extended permit ip object-group GAD 10.0.139.8 255.255.255.248
access-list Inside_nat0_outbound extended permit ip any 10.0.19.32 255.255.255.224
access-list Inside_nat0_outbound extended permit ip object-group GAD 10.0.130.0 255.255.255.0

access-list Outside_120_cryptomap extended permit ip object-group GAD 10.0.130.0 255.255.255.0
access-list Outside_cryptomap_120 extended permit ip object-group GAD 10.0.130.0 255.255.255.0

crypto ipsec transform-set ESP-DES-SHA esp-des esp-sha-hmac
crypto ipsec transform-set ESP-3DES-SHA esp-3des esp-sha-hmac
crypto dynamic-map Outside_dyn_map 15 match address Outside_15_cryptomap
crypto dynamic-map Outside_dyn_map 15 set pfs
crypto dynamic-map Outside_dyn_map 15 set transform-set ESP-3DES-SHA
crypto dynamic-map Outside_dyn_map 15 set reverse-route
crypto dynamic-map Outside_dyn_map 20 match address Outside_20_cryptomap
crypto dynamic-map Outside_dyn_map 20 set pfs
crypto dynamic-map Outside_dyn_map 20 set transform-set ESP-3DES-SHA
crypto dynamic-map Outside_dyn_map 20 set reverse-route
crypto dynamic-map Outside_dyn_map 60 set pfs
crypto dynamic-map Outside_dyn_map 60 set transform-set ESP-3DES-SHA
crypto map Outside_map 40 match address Outside_40_cryptomap
crypto map Outside_map 40 set pfs
crypto map Outside_map 40 set peer 87.66.7.232
crypto map Outside_map 40 set transform-set ESP-3DES-SHA
crypto map Outside_map 80 match address Outside_80_cryptomap
crypto map Outside_map 80 set pfs
crypto map Outside_map 80 set peer 87.66.7.234
crypto map Outside_map 80 set transform-set ESP-3DES-SHA
crypto map Outside_map 100 match address Outside_100_cryptomap
crypto map Outside_map 100 set pfs
crypto map Outside_map 100 set peer 87.66.7.231
crypto map Outside_map 100 set transform-set ESP-3DES-SHA
crypto map Outside_map 120 match address Outside_cryptomap_120
crypto map Outside_map 120 set pfs
crypto map Outside_map 120 set peer 109.135.19.130
crypto map Outside_map 120 set transform-set ESP-3DES-SHA
crypto map Outside_map 65535 ipsec-isakmp dynamic Outside_dyn_map
crypto map Outside_map interface Outside
crypto isakmp identity hostname
crypto isakmp enable Outside
crypto isakmp enable Telenet
crypto isakmp policy 10
authentication pre-share
encryption 3des
hash sha
group 2
lifetime 86400
crypto isakmp nat-traversal 20
tunnel-group DefaultL2LGroup ipsec-attributes
pre-shared-key ************
tunnel-group GADVPN type ipsec-ra
tunnel-group GADVPN general-attributes
address-pool VPN_GAD
authentication-server-group group1
default-group-policy GADVPN
tunnel-group GADVPN ipsec-attributes
pre-shared-key ************
tunnel-group 87.66.7.232 type ipsec-l2l
tunnel-group 87.66.7.232 ipsec-attributes
pre-shared-key ************
tunnel-group 87.66.7.231 type ipsec-l2l
tunnel-group 87.66.7.231 ipsec-attributes
pre-shared-key ************
tunnel-group 87.66.7.234 type ipsec-l2l
tunnel-group 87.66.7.234 ipsec-attributes
pre-shared-key ************
tunnel-group 109.135.19.130 type ipsec-l2l
tunnel-group 109.135.19.130 ipsec-attributes
pre-shared-key ************

Georg Pauwen · ‎06-26-2018

Hello Jeroen,

the ASA looks good.

Try and change the parameters marked in bold on your 887:

crypto isakmp policy 1
encr 3des
authentication pre-share
group 2
crypto isakmp key **********************address 194.78.59.5
--> no crypto isakmp fragmentation
!
crypto ipsec transform-set ESP-3DES-SHA esp-3des esp-sha-hmac
--> mode transport
!
interface Dialer0
mtu 1492
ip address 109.135.19.130 255.255.255.0
ip nat outside
ip virtual-reassembly in
encapsulation ppp

ip tcp adjust-mss 1452
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
--> no crypto ipsec df-bit clear

Jeroen Janssens · ‎06-27-2018

These changes don't seem to have any effect ...

Are there any debug or show commands that could help find out what the issues is?

Jeroen Janssens · ‎06-27-2018

OCWRTR01#sh crypto isakmp sa detail
Codes: C - IKE configuration mode, D - Dead Peer Detection
K - Keepalives, N - NAT-traversal
T - cTCP encapsulation, X - IKE Extended Authentication
psk - Preshared key, rsig - RSA signature
renc - RSA encryption
IPv4 Crypto ISAKMP SA

C-id Local Remote I-VRF Status Encr Hash Auth DH Lifetime Cap.

2017 109.135.19.130 194.78.59.5 ACTIVE 3des sha psk 2 0 N
Engine-id:Conn-id = ???
(deleted)

2016 109.135.19.130 194.78.59.5 ACTIVE 3des sha psk 2 0 N
Engine-id:Conn-id = ???
(deleted)

IPv6 Crypto ISAKMP SA

OCWRTR01#sh crypto ipsec sa

interface: Dialer0
Crypto map tag: SDM_CMAP_1, local addr 109.135.19.130

protected vrf: (none)
local ident (addr/mask/prot/port): (10.0.130.32/255.255.255.224/0/0)
remote ident (addr/mask/prot/port): (10.0.0.0/255.255.0.0/0/0)
current_peer 194.78.59.5 port 500
PERMIT, flags={origin_is_acl,}
#pkts encaps: 0, #pkts encrypt: 0, #pkts digest: 0
#pkts decaps: 0, #pkts decrypt: 0, #pkts verify: 0
#pkts compressed: 0, #pkts decompressed: 0
#pkts not compressed: 0, #pkts compr. failed: 0
#pkts not decompressed: 0, #pkts decompress failed: 0
#send errors 171, #recv errors 0

local crypto endpt.: 109.135.19.130, remote crypto endpt.: 194.78.59.5
plaintext mtu 1492, path mtu 1492, ip mtu 1492, ip mtu idb Dialer0
current outbound spi: 0x0(0)
PFS (Y/N): N, DH group: none

inbound esp sas:

inbound ah sas:

inbound pcp sas:

outbound esp sas:

outbound ah sas:

outbound pcp sas:

Jeroen Janssens · ‎06-27-2018

OCWRTR01#
*Jun 27 08:33:42.353: IPSEC:(SESSION ID = 1) (key_engine) request timer fired: count = 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 27 08:33:42.353: 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 27 08:33:42.353: ISAKMP: (0):SA request profile is (NULL)
*Jun 27 08:33:42.353: ISAKMP: (0):Created a peer struct for 194.78.59.5, peer port 500
*Jun 27 08:33:42.353: ISAKMP: (0):New peer created peer = 0x116AEA48 peer_handle = 0x8000001F
*Jun 27 08:33:42.353: ISAKMP: (0):Locking peer struct 0x116AEA48, refcount 1 for isakmp_initiator
*Jun 27 08:33:42.353: ISAKMP: (0):local port 500, remote port 500
*Jun 27 08:33:42.353: ISAKMP: (0):set new node 0 to QM_IDLE
*Jun 27 08:33:42.353: ISAKMP: (0):Find a dup sa in the avl tree during calling isadb_insert sa = 3976C88
*Jun 27 08:33:42.353: ISAKMP: (0):Can not start Aggressive mode, trying Main mode.
*Jun 27 08:33:42.353: ISAKMP: (0):found peer pre-shared key matching 194.78.59.5
*Jun 27 08:33:42.353: ISAKMP: (0):constructed NAT-T vendor-rfc3947 ID
*Jun 27 08:33:42.353: ISAKMP: (0):constructed NAT-T vendor-07 ID
*Jun 27 08:33:42.353: ISAKMP: (0):constructed NAT-T vendor-03 ID
*Jun 27 08:33:42.353: ISAKMP: (0):constructed NAT-T vendor-02 ID
*Jun 27 08:33:42.357: ISAKMP: (0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
*Jun 27 08:33:42.357: ISAKMP: (0):Old State = IKE_READY New State = IKE_I_MM1

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

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

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

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

*Jun 27 08:33:42.481: ISAKMP: (2027):purging SA., sa=384538C, delme=384538C
*Jun 27 08:33:42.521: ISAKMP-PAK: (0):received packet from 194.78.59.5 dport 500 sport 500 Global (I) MM_SA_SETUP
*Jun 27 08:33:42.521: ISAKMP: (0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Jun 27 08:33:42.521: ISAKMP: (0):Old State = IKE_I_MM3 New State = IKE_I_MM4

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

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

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

*Jun 27 08:33:42.597: ISAKMP: (2029):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Jun 27 08:33:42.597: ISAKMP: (2029):Old State = IKE_I_MM6 New State = IKE_I_MM6

*Jun 27 08:33:42.597: ISAKMP: (2029):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Jun 27 08:33:42.597: ISAKMP: (2029):Old State = IKE_I_MM6 New State = IKE_P1_COMPLETE

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

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

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

*Jun 27 08:33:42.633: ISAKMP: (2029):deleting SA reason "No reason" state (I) QM_IDLE (peer 194.78.59.5)
*Jun 27 08:33:42.633: ISAKMP: (0):Unlocking peer struct 0x116AEA48 for isadb_mark_sa_deleted(), count 0
*Jun 27 08:33:42.633: ISAKMP: (0):Deleting peer node by peer_reap for 194.78.59.5: 116AEA48
*Jun 27 08:33:42.633: ISAKMP: (2029):deleting node -1116185718 error FALSE reason "IKE deleted"
*Jun 27 08:33:42.633: ISAKMP: (2029):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Jun 27 08:33:42.633: ISAKMP: (2029):Old State = IKE_DEST_SA New State = IKE_DEST_SA

*Jun 27 08:33:42.633: IPSEC(key_engine): got a queue event with 1 KMI message(s)+
*Jun 27 08:34:02.513: ISAKMP: (2028):purging node 1751142920
*Jun 27 08:34:02.517: ISAKMP: (2028):purging node -1056660595
*Jun 27 08:34:02.517: ISAKMP: (2028):purging node -789538391

Georg Pauwen · ‎06-27-2018

Hello,

I am not sure if the pfs group has to be specified. Try and add 'set pfs group2' to your crypto map:

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

set pfs group2
match address 100

Jeroen Janssens · ‎06-27-2018

The VPN led has gone up. But I cannot ping from my laptop on the remote site to a server on the site with the ASA.

OCWRTR01#sh crypto isakmp sa detail
Codes: C - IKE configuration mode, D - Dead Peer Detection
K - Keepalives, N - NAT-traversal
T - cTCP encapsulation, X - IKE Extended Authentication
psk - Preshared key, rsig - RSA signature
renc - RSA encryption
IPv4 Crypto ISAKMP SA

C-id Local Remote I-VRF Status Encr Hash Auth DH Lifetime Cap.

2001 109.135.19.130 194.78.59.5 ACTIVE 3des sha psk 2 23:57:14 N
Engine-id:Conn-id = SW:1

IPv6 Crypto ISAKMP SA

OCWRTR01#sh crypto ipsec sa

interface: Dialer0
Crypto map tag: SDM_CMAP_1, local addr 109.135.19.130

protected vrf: (none)
local ident (addr/mask/prot/port): (10.0.130.32/255.255.255.224/0/0)
remote ident (addr/mask/prot/port): (10.0.0.0/255.255.0.0/0/0)
current_peer 194.78.59.5 port 4500
PERMIT, flags={origin_is_acl,}
#pkts encaps: 72, #pkts encrypt: 72, #pkts digest: 72
#pkts decaps: 0, #pkts decrypt: 0, #pkts verify: 0
#pkts compressed: 0, #pkts decompressed: 0
#pkts not compressed: 0, #pkts compr. failed: 0
#pkts not decompressed: 0, #pkts decompress failed: 0
#send errors 0, #recv errors 0

local crypto endpt.: 109.135.19.130, remote crypto endpt.: 194.78.59.5
plaintext mtu 1430, path mtu 1492, ip mtu 1492, ip mtu idb Dialer0
current outbound spi: 0x2EDAE470(786097264)
PFS (Y/N): Y, DH group: group2

inbound esp sas:
spi: 0x928DC26A(2458763882)
transform: esp-3des esp-sha-hmac ,
in use settings ={Tunnel UDP-Encaps, }
conn id: 1, flow_id: Onboard VPN:1, sibling_flags 80004040, crypto map: SDM_CMAP_1
sa timing: remaining key lifetime (k/sec): (4329955/3387)
IV size: 8 bytes
replay detection support: Y
Status: ACTIVE(ACTIVE)

inbound ah sas:

inbound pcp sas:

outbound esp sas:
spi: 0x2EDAE470(786097264)
transform: esp-3des esp-sha-hmac ,
in use settings ={Tunnel UDP-Encaps, }
conn id: 2, flow_id: Onboard VPN:2, sibling_flags 80004040, crypto map: SDM_CMAP_1
sa timing: remaining key lifetime (k/sec): (4329947/3387)
IV size: 8 bytes
replay detection support: Y
Status: ACTIVE(ACTIVE)

outbound ah sas:

outbound pcp sas:

Jeroen Janssens · ‎06-27-2018

the current config :

!
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 ipsec transform-set ESP-3DES-SHA esp-3des esp-sha-hmac
mode transport
!
!
!
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
set pfs group2
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
!
interface Dialer0
mtu 1492
ip address 109.135.19.130 255.255.255.0
ip nat outside
ip virtual-reassembly in
encapsulation ppp
ip tcp adjust-mss 1452
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
!
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

Georg Pauwen · ‎06-27-2018

Hello Jeroen,

--> access-list 100 permit ip 10.0.130.32 0.0.0.31 10.0.0.0 0.0.255.255

What is the actual subnet on the other side ? Is it 10.0.0.0/16 ?

Jeroen Janssens · ‎06-27-2018

There are multiple subnets and they are all part of the 10.0.0.0 range. Most are 10.0.x.x ...