2015-02-16 13:22:47 handle_control_packet()-551: 
2015-02-16 13:22:47 check_control_hdr()-173: check_control_hdr: control, peer_call_id = 1, Ns = 4, Nr = 10
2015-02-16 13:22:47 check_control_hdr()-185: Updated control rec seqno. Value is now 5
2015-02-16 13:22:47 __avp_assigned_call()-381: close call id 1
2015-02-16 13:22:47 run_ctrl_state_machine()-91: run_ctrl_state_machine: message type is (14).  Tunnel is 2, call is 1.
2015-02-16 13:22:47 run_ctrl_state_machine()-333: ** run_ctrl_state_machine - CDN **
2015-02-16 13:22:47 run_ctrl_state_machine()-374: Connection closed to TEST_HOST_IP, serial 0 ()
2015-02-16 13:22:47 handle_network_packet()-274: Sending a ZLB to acknowledge last message
2015-02-16 13:22:47 send_zlb()-73: ** send_zlb **
2015-02-16 13:22:47 l2tp_handle_calls()-312: closing The master call
2015-02-16 13:22:47 close_call()-410: ** close_call **
2015-02-16 13:22:47 close_call()-425: Closing call 1238
2015-02-16 13:22:47 free_call()-211: ** free_call **
2015-02-16 13:22:47 l2tp_vdbind_msg_handler()-87: del_vdbind message:vd=root 0 devindex=302 ppp4
2015-02-16 13:22:47 l2tp_handle_calls()-299: closing down tunnel 1237
2015-02-16 13:22:47 close_tunnel()-446: ** close_tunnel **
2015-02-16 13:22:47 close_tunnel()-459: Closing and destroying tunnel 1237
2015-02-16 13:22:47 L2TPD 26: 461:Client TEST_HOST_IP control connection (id 1237) finished
2015-02-16 13:22:47 close_calls_for_tunnel()-100: 
2015-02-16 13:22:47 free_call()-211: ** free_call **
2015-02-16 13:22:47 free_tunnel()-117: Done close_calls_for_tunnel 
2015-02-16 13:22:47 find_tunnel_call()-183: can't find tunnel 1237
2015-02-16 13:22:47 handle_network_packet()-199: L2TP: invalid tunnel 1237 for incoming packet (call=0).
2015-02-16 13:22:54 find_tunnel_call()-183: can't find tunnel 1237
2015-02-16 13:22:54 handle_network_packet()-199: L2TP: invalid tunnel 1237 for incoming packet (call=0).
2015-02-16 13:23:02 find_tunnel_call()-183: can't find tunnel 1237
2015-02-16 13:23:02 handle_network_packet()-199: L2TP: invalid tunnel 1237 for incoming packet (call=0).
2015-02-16 13:23:03 create_new_tunnel()-91: Allocated new Tunnel id=1243, total count = 140 
2015-02-16 13:23:03 handle_control_packet()-551: 
2015-02-16 13:23:03 check_control_hdr()-173: check_control_hdr: control, peer_call_id = 0, Ns = 0, Nr = 0
2015-02-16 13:23:03 check_control_hdr()-185: Updated control rec seqno. Value is now 1
2015-02-16 13:23:03 __avp_protocol_version()-233: peer is using version 8, revision 128.
2015-02-16 13:23:03 __avp_framing_caps()-248: supported peer framing:  
2015-02-16 13:23:03 __avp_bearer_caps()-264: supported peer bearers:
2015-02-16 13:23:03 __avp_firmware_rev()-279: peer's firmware version 2048
2015-02-16 13:23:03 _avp_hostname()-295: Peer's hostname is 'TEST_HOST_HOSTNAME'
2015-02-16 13:23:03 __avp_vendor()-310: peer's vendor 'Microsoft'
2015-02-16 13:23:03 __avp_assigned_tunnel()-339: peer's tunnel 3
2015-02-16 13:23:03 avp_receive_window_size()-359: peer's RWS 8.
2015-02-16 13:23:03 run_ctrl_state_machine()-91: run_ctrl_state_machine: message type is (1).  Tunnel is 3, call is 0.
2015-02-16 13:23:03 run_ctrl_state_machine()-97: ** run_ctrl_state_machine - SCCRQ **
2015-02-16 13:23:03 run_ctrl_state_machine()-108: Rule TEST_HOST_IP to TEST_HOST_IP
2015-02-16 13:23:03 avp_put_hostname()-84: Sent the host name = 1.127 
2015-02-16 13:23:03 run_ctrl_state_machine()-166: Sending SCCRP
2015-02-16 13:23:03 schedule_event()-94: 
2015-02-16 13:23:03 schedule_event()-100: Message due 111446950, now = 111446850
2015-02-16 13:23:03 handle_control_packet()-551: 
2015-02-16 13:23:03 check_control_hdr()-173: check_control_hdr: control, peer_call_id = 0, Ns = 1, Nr = 1
2015-02-16 13:23:03 check_control_hdr()-185: Updated control rec seqno. Value is now 2
2015-02-16 13:23:03 run_ctrl_state_machine()-91: run_ctrl_state_machine: message type is (3).  Tunnel is 3, call is 0.
2015-02-16 13:23:03 run_ctrl_state_machine()-175: ** run_ctrl_state_machine - SCCCN **
2015-02-16 13:23:03 L2TPD 97: 180:Connection established to TEST_HOST_IP, 1701.  Local: 1243, Remote: 3.
2015-02-16 13:23:03 start_hello_timer()-59: L2TP: starting Hello timer for tunnel 3, next in 60 seconds.
2015-02-16 13:23:03 schedule_event()-94: 
2015-02-16 13:23:03 schedule_event()-100: Message due 111452873, now = 111446873
2015-02-16 13:23:03 handle_network_packet()-274: Sending a ZLB to acknowledge last message
2015-02-16 13:23:03 send_zlb()-73: ** send_zlb **
2015-02-16 13:23:03 handle_control_packet()-551: 
2015-02-16 13:23:03 check_control_hdr()-173: check_control_hdr: control, peer_call_id = 0, Ns = 2, Nr = 1
2015-02-16 13:23:03 check_control_hdr()-185: Updated control rec seqno. Value is now 3
2015-02-16 13:23:03 __avp_assigned_call()-392: Parsed new call id of 2
2015-02-16 13:23:03 __avp_call_serno()-418: serial number is 0
2015-02-16 13:23:03 __avp_bearer_type()-445: peer's bears anamylog
2015-02-16 13:23:03 avp_handler()-723: AVP 1 was ignored 
2015-02-16 13:23:03 run_ctrl_state_machine()-91: run_ctrl_state_machine: message type is (10).  Tunnel is 3, call is 2.
2015-02-16 13:23:03 run_ctrl_state_machine()-225: ** run_ctrl_state_machine - ICRQ **
2015-02-16 13:23:03 run_ctrl_state_machine()-235: New call was created for tunnel 3, call id = 2
2015-02-16 13:23:03 run_ctrl_state_machine()-291: This call is the master_call, its peer_call_id = 1244 
2015-02-16 13:23:03 run_ctrl_state_machine()-299: run_ctrl_state_machine: sending ICRP
2015-02-16 13:23:03 schedule_event()-94: 
2015-02-16 13:23:03 schedule_event()-100: Message due 111446974, now = 111446874
2015-02-16 13:23:03 handle_control_packet()-551: 
2015-02-16 13:23:03 check_control_hdr()-173: check_control_hdr: control, peer_call_id = 2, Ns = 3, Nr = 2
2015-02-16 13:23:03 check_control_hdr()-185: Updated control rec seqno. Value is now 4
2015-02-16 13:23:03 __avp_tx_speed()-495: TX is 144000000
2015-02-16 13:23:03 __avp_frame_type()-474: peer's framing sync
2015-02-16 13:23:03 avp_handler()-723: AVP 29 was ignored 
2015-02-16 13:23:03 run_ctrl_state_machine()-91: run_ctrl_state_machine: message type is (12).  Tunnel is 3, call is 2.
2015-02-16 13:23:03 run_ctrl_state_machine()-308: ** run_ctrl_state_machine - ICCN **
2015-02-16 13:23:03 start_pppd()-165: Starting pppd
2015-02-16 13:23:03 L2TPD 29: 166:Starting call (launching pppd, opening GRE)
2015-02-16 13:23:03 run_ctrl_state_machine()-328: Call established with TEST_HOST_IP, Local: 1244, Remote: 2, Serial: 0
2015-02-16 13:23:03 handle_network_packet()-274: Sending a ZLB to acknowledge last message
2015-02-16 13:23:03 send_zlb()-73: ** send_zlb **
2015-02-16 13:23:03 L2TPD 25: 334:Client TEST_HOST_IP control connection started (id 1243), assigned ip 10.136.16.54
2015-02-16 13:23:03 start_pppd()-347: /bin/pppd 
2015-02-16 13:23:03 start_pppd()-347: 0 
2015-02-16 13:23:03 start_pppd()-347: l2tp 
2015-02-16 13:23:03 start_pppd()-347: wan1 
2015-02-16 13:23:03 start_pppd()-347: local 
2015-02-16 13:23:03 start_pppd()-347: file 
2015-02-16 13:23:03 start_pppd()-347: /etc/ppp/options 
2015-02-16 13:23:03 start_pppd()-347: 115200 
2015-02-16 13:23:03 start_pppd()-347: 10.136.16.50:10.136.16.54 
2015-02-16 13:23:03 start_pppd()-347: +pap 
2015-02-16 13:23:03 start_pppd()-347: +chap 
2015-02-16 13:23:03 start_pppd()-347: peer-remote 
2015-02-16 13:23:03 start_pppd()-347: TEST_HOST_IP 
2015-02-16 13:23:03 start_pppd()-347: lcp-echo-interval 
2015-02-16 13:23:03 start_pppd()-347: 5 
2015-02-16 13:23:03 start_pppd()-347: lcp-echo-failure 
2015-02-16 13:23:03 start_pppd()-347: 3 
2015-02-16 13:23:03 start_pppd()-347: dns-addr 
2015-02-16 13:23:03 start_pppd()-347: HOST_DNS_IP 
2015-02-16 13:23:03 start_pppd()-347: dns-addr 
2015-02-16 13:23:03 start_pppd()-347: HOST_DNS_IP 
2015-02-16 13:23:03 start_pppd()-349: 
2015-02-16 13:23:05 monitor_ctrl_pkt_xmit()-94: 
2015-02-16 13:23:05 monitor_ctrl_pkt_xmit()-116: L2TP: Peer ack'ed control packet.
2015-02-16 13:23:05 monitor_ctrl_pkt_xmit()-94: 
2015-02-16 13:23:05 monitor_ctrl_pkt_xmit()-116: L2TP: Peer ack'ed control packet.
2015-02-16 13:23:10 find_tunnel_call()-183: can't find tunnel 1237
2015-02-16 13:23:10 handle_network_packet()-199: L2TP: invalid tunnel 1237 for incoming packet (call=0).
2015-02-16 13:23:15 send_hello()-33: L2TP: send Hello for tunnel 1 
2015-02-16 13:23:15 schedule_event()-94: 
2015-02-16 13:23:15 schedule_event()-100: Message due 111448163, now = 111448063
2015-02-16 13:23:15 start_hello_timer()-59: L2TP: starting Hello timer for tunnel 1, next in 60 seconds.
2015-02-16 13:23:15 schedule_event()-94: 
2015-02-16 13:23:15 schedule_event()-100: Message due 111454063, now = 111448063
2015-02-16 13:23:15 handle_control_packet()-551: 
2015-02-16 13:23:15 handle_control_packet()-580: L2TP received control ZLB.
2015-02-16 13:23:16 monitor_ctrl_pkt_xmit()-94: 
2015-02-16 13:23:16 monitor_ctrl_pkt_xmit()-116: L2TP: Peer ack'ed control packet.
2015-02-16 13:23:18 find_tunnel_call()-183: can't find tunnel 1237
2015-02-16 13:23:18 handle_network_packet()-199: L2TP: invalid tunnel 1237 for incoming packet (call=0).
2015-02-16 13:23:25 send_hello()-33: L2TP: send Hello for tunnel 3 
2015-02-16 13:23:25 schedule_event()-94: 
2015-02-16 13:23:25 schedule_event()-100: Message due 111449188, now = 111449088
2015-02-16 13:23:25 start_hello_timer()-59: L2TP: starting Hello timer for tunnel 3, next in 60 seconds.
2015-02-16 13:23:25 schedule_event()-94: 
2015-02-16 13:23:25 schedule_event()-100: Message due 111455088, now = 111449088
2015-02-16 13:23:25 send_hello()-33: L2TP: send Hello for tunnel 1 
2015-02-16 13:23:25 schedule_event()-94: 
2015-02-16 13:23:25 schedule_event()-100: Message due 111449188, now = 111449088
2015-02-16 13:23:25 start_hello_timer()-59: L2TP: starting Hello timer for tunnel 1, next in 60 seconds.
2015-02-16 13:23:25 schedule_event()-94: 
2015-02-16 13:23:25 schedule_event()-100: Message due 111455088, now = 111449088
2015-02-16 13:23:25 send_hello()-33: L2TP: send Hello for tunnel 2 
2015-02-16 13:23:25 schedule_event()-94: 
2015-02-16 13:23:25 schedule_event()-100: Message due 111449188, now = 111449088
2015-02-16 13:23:25 start_hello_timer()-59: L2TP: starting Hello timer for tunnel 2, next in 60 seconds.
2015-02-16 13:23:25 schedule_event()-94: 
2015-02-16 13:23:25 schedule_event()-100: Message due 111455088, now = 111449088
2015-02-16 13:23:25 handle_control_packet()-551: 
2015-02-16 13:23:25 handle_control_packet()-580: L2TP received control ZLB.
2015-02-16 13:23:25 handle_control_packet()-551: 
2015-02-16 13:23:25 handle_control_packet()-580: L2TP received control ZLB.
2015-02-16 13:23:25 handle_control_packet()-551: 
2015-02-16 13:23:25 handle_control_packet()-580: L2TP received control ZLB.
2015-02-16 13:23:26 find_tunnel_call()-183: can't find tunnel 1237
2015-02-16 13:23:26 handle_network_packet()-199: L2TP: invalid tunnel 1237 for incoming packet (call=0).