[May 22 19:16:19][2.2.2.2 <-> 1.1.1.1]  Triggering the IKE negotiation ....
[May 22 19:16:19][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_callback called for Colo_VPN
[May 22 19:16:19][2.2.2.2 <-> 1.1.1.1]  Triggering negotiation for Colo_VPN config block
                    [May 22 19:16:19][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_callback: lookup peer entry for gateway gw_Colo_VPN, local_port=500, remote_port=500
[May 22 19:16:19][2.2.2.2 <-> 1.1.1.1]  iked_lookup_peer_entry: Peer entry 0xb73000 FOUND for local 2.2.2.2:500 and remote 1.1.1.1:500
[May 22 19:16:19][2.2.2.2 <-> 1.1.1.1]  Peer entry exist for local 2.2.2.2:500 and remote 1.1.1.1:500
[May 22 19:16:19][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_callback: FOUND peer entry for gateway gw_Colo_VPN
[May 22 19:16:19][2.2.2.2 <-> 1.1.1.1]  P1 SA 3597661 negotiation is still going on for gateway gw_Colo_VPN
[May 22 19:16:20][2.2.2.2 <-> 1.1.1.1]  ssh_set_debug_gw_info: ssh_set_debug_gw_info: set gw debug info - local 2.2.2.2 remote 1.1.1.1
[May 22 19:16:20][2.2.2.2 <-> 1.1.1.1]  ike_retransmit_callback: Start, retransmit SA = { be8eda9d 428b7342 - 4a61e1da d249c676}, nego = -1
[May 22 19:16:20][2.2.2.2 <-> 1.1.1.1]  ike_send_packet: Start, retransmit previous packet SA = { be8eda9d 428b7342 - 4a61e1da d249c676}, nego = -1, dst = 1.1.1.1:500 routing table id = 0
[May 22 19:16:20][2.2.2.2 <-> 1.1.1.1]  ike_send_packet: Inserting retransmission timer after 10.000000 seconds
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  *** Processing received packet from 1.1.1.1:500 to 2.2.2.2:0, VR 0, packet len: 196, on Interface: fe-0/0/0.0
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_st_input_start: [e40c00/0] Processing received
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Start, SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Found SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  Found IKEv1 SA
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_st_input_v1_get_sa: [e40c00/deadbeee] Packet to existing v1 SA
                                   [May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Packet from 1.1.1.1:500, use_natt=0 data[0..196] = be8eda9d 428b7342 4a61e1da d249c676 ...
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_get_sa: Start, SA = { be8eda9d 428b7342 - 4a61e1da d249c676 } / 00000000, remote = 1.1.1.1:500
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Start, SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Found SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Old negotiation message_id = 00000000, slot -1
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Other end retransmitted its packet
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Cannot resend our response, because we have just sent a packet to other end
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_destroy: [e40c00/deadbeee] Destructor
[May 22 19:16:23][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_free: [e40c00/deadbeee] Freeing
[May 22 19:16:24][2.2.2.2 <-> 1.1.1.1]  Triggering negotiation for Colo_VPN config block
[May 22 19:16:24][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_callback: lookup peer entry for gateway gw_Colo_VPN, local_port=500, remote_port=500
[May 22 19:16:24][2.2.2.2 <-> 1.1.1.1]  iked_lookup_peer_entry: Peer entry 0xb73000 FOUND for local 2.2.2.2:500 and remote 1.1.1.1:500
[May 22 19:16:24][2.2.2.2 <-> 1.1.1.1]  Peer entry exist for local 2.2.2.2:500 and remote 1.1.1.1:500
[May 22 19:16:24][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_callback: FOUND peer entry for gateway gw_Colo_VPN
[May 22 19:16:24][2.2.2.2 <-> 1.1.1.1]  P1 SA 3597661 negotiation is still going on for gateway gw_Colo_VPN
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  *** Processing received packet from 1.1.1.1:500 to 2.2.2.2:0, VR 0, packet len: 196, on Interface: fe-0/0/0.0
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_st_input_start: [e41000/0] Processing received
                                      [May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Start, SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Found SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  Found IKEv1 SA
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_st_input_v1_get_sa: [e41000/deadbeee] Packet to existing v1 SA
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Packet from 1.1.1.1:500, use_natt=0 data[0..196] = be8eda9d 428b7342 4a61e1da d249c676 ...
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_get_sa: Start, SA = { be8eda9d 428b7342 - 4a61e1da d249c676 } / 00000000, remote = 1.1.1.1:500
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Start, SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Found SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Old negotiation message_id = 00000000, slot -1
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Other end retransmitted its packet
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Cannot resend our response, because we have just sent a packet to other end
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_destroy: [e41000/deadbeee] Destructor
[May 22 19:16:27][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_free: [e41000/deadbeee] Freeing
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  P1 SA 3597661 timer expiry. ref cnt 2, timer reason Force delete timer expired (1), flags 0x30.
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_ha_check_ike_sa_activeness_by_rg_id:RG 0 is active on this chassiss
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Initiate IKE P1 SA 3597661 delete. curr ref count 2, del flags 0x3
                    [May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_sa_delete_done_cb: For p1 sa index 3597661, ref cnt 2, status: Error ok
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]   iked_vpnm_timer_callback: VPN Monitor timer kicked in
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Get rtbl_idx=0 for ifl idx 71
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  PING (1.1.1.1 via 1.1.1.1): 56 data bytes Tunnel-id:131073 outgoing intf 71, rtbl idx 0
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  VPNM send ping pkt (84/84) bytes for tunnel 131073, seq 28
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_set_debug_gw_info: ssh_set_debug_gw_info: set gw debug info - local 2.2.2.2 remote 1.1.1.1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_remove_callback: Start, delete SA = { be8eda9d 428b7342 - 4a61e1da d249c676}, nego = -1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  2.2.2.2:500 (Initiator) <-> 1.1.1.1:500 { be8eda9d 428b7342 - 4a61e1da d249c676 [-1] / 0x00000000 } IP; Connection timed out or error, calling callback
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_negotiation_done_isakmp: Entered IKE error code Timeout (8197), IKE SA ee1400 (neg ee5800)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_i_ike_negotiation_cb: Connect IKE done callback, status Timeout (neg ee5800)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fallback_negotiation_free: Fallback negotiation ee5800 has still 1 references
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_delete_negotiation: Start, SA = { be8eda9d 428b7342 - 4a61e1da d249c676}, nego = -1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_tunnel_table_entry_delete: Deleting tunnel_id: 0 from IKE tunnel table
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_tunnel_table_entry_delete: The tunnel id: 0 doesn't exist in IKE tunnel table
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_sa_delete: Start, SA = { be8eda9d 428b7342 - 4a61e1da d249c676 }
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_negotiation_isakmp: Start, nego = -1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_negotiation: Start, nego = -1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_packet: Start
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_packet: Start
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_packet: Start
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_packet: Start
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_packet: Start
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_sa_freed: Received notification from the ISAKMP library that the IKE SA ee1400 is freed
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_sa_freed: Clearing p1_info from fallback negotiation ee5800
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_id_payload: Start, id type = 1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_free_sa: Start
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_i_p1_negotiation_result: Phase I negotiation result
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_i_p1_negotiation_result: FB; Calling v2 policy function ike_sa_done
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_sa_done: UNUSABLE p1_sa 3597661
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]    IKEv1 Error : Timeout
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_i_p1_negotiation_result: Phase I negotiation failed, error unknown (neg ee5800)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  IPSec SA done callback. ed b77028. status: Timed out
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Detach ed b77028 from P1 SA 3597661, slot 0.
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_free_exchange_data: Freeing exchange data from SA ee1400, ED b77028 (2)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  IPSec Rekey for SPI 0x0 failed
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  IPSec SA done callback called for sa-cfg Colo_VPN local:2.2.2.2, remote:1.1.1.1 IKEv1 with status Timed out
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_i_p1_negotiation_result: FB; Calling v2 policy function ike_sa_delete
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  IKE SA delete called for p1 sa 3597661 (ref cnt 2) local:2.2.2.2, remote:1.1.1.1, IKEv1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  P1 SA 3597661 stop timer. timer duration 30, reason 0.
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Freeing reference to P1 SA 3597661 to ref count 1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  P1 SA 3597661 reference count is not zero (1). Delaying deletion of SA
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_p1_negotiation_destructor: Freeing fallback negotiation context
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fallback_negotiation_free: Freeing fallback negotiation ee5800
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_free_exchange_data: Freeing exchange data from SA ee1400, ED b77028 (1)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_free_exchange_data_ipsec: Freeing IPsec exchange data from SA ee1400
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ts_free: ts 0xe6fa20, ref_cnt 1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ts_free: ts 0xe6fa40, ref_cnt 1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_free_exchange_data_ipsec: Successfully freed IPsec exchange data from SA ee1400
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_free_exchange_data_ike: Freeing IKE exchange data from SA ee1400
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_free_exchange_data_ike: Successfully freed IKE exchange data from SA ee1400
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_free_exchange_data: Calling exchange_data_free
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Freeing P2 Ed for sa-cfg Colo_VPN
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_unset_sa_cfg_p2_ed unset_sa_cfg_p2_ed,  sa_cfg=Colo_VPN
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_exchange_data_free: Successfully removed pm_ed ee3800 from list for sa_cfg N/A
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_free_exchange_data: Successfully freed exchange data from SA ee1400
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ike_sa_free: Calling ike_sa_free_ref
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Freeing reference to P1 SA 3597661 to ref count 0
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  No more references to IKE SA 3597661 and waiting for delete. Deleting IKE SA
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_p1_sa_destroy:  p1 sa 3597661 (ref cnt 0), waiting_for_del 0xe6fa60
                    [May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_peer_remove_p1sa_entry: Remove p1 sa 3597661 from peer entry 0xb73000
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_delete_peer_entry: Requested for peer-entry 0xb73000 deletion for local 2.2.2.2:500 and remote 1.1.1.1:500
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_dist_table_entry_update : Dist table entry creation not needed

[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_peer_entry_patricia_delete:Peer entry 0xb73000 deleted for local 2.2.2.2:500 and remote 1.1.1.1:500
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Deleting p1 sa (3597661) node from IKE p1 SA P-tree
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  The tunnel id: 3597661 doesn't exist in P1 SA P-tree
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_udp_window_uninit: Freeing transmission windows for SA ee1400
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Received IKE Trigger message with local_gw_addr = 2.2.2.2 remote_gw_addr = 1.1.1.1

[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  In iked_async_ike_trigger_msg_handler; Tunnel = 131073

[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Triggering the IKE negotiation ....
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_callback called for Colo_VPN
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Triggering negotiation for Colo_VPN config block
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_callback: lookup peer entry for gateway gw_Colo_VPN, local_port=500, remote_port=500
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_lookup_peer_entry: Peer entry 0x0 Not FOUND for local 2.2.2.2:500 and remote 1.1.1.1:500
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_create_peer_entry: Created peer entry 0xb73000 for local 2.2.2.2:500 remote 1.1.1.1:500
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_fetch_or_create_peer_entry: Create peer entry 0xb73000 for local 2.2.2.2:500 remote 1.1.1.1:500. gw gw_Colo_VPN, VR id 0
                    [May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_dist_table_entry_update : Dist table entry creation not needed

[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_callback: FOUND peer entry for gateway gw_Colo_VPN
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Initiating new P1 SA for gateway gw_Colo_VPN
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ike_sa_allocate: Allocating IKE SA 1.1.1.1;500/4500
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  chassis 0 fpc 0 pic 0 kmd-instance 0
current tunnel id 3597661
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Allocated IKE SA index 3597662, ref cnt 0
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  P1 SA 3597662 start timer. timer duration 30, reason 1.
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_ike_sa_alloc_cb: Allocated IKE SA ee1400 I51a46716 d5222ec1 (1.1.1.1;500/4500)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_udp_window_init: Allocating transmission windows for SA ee1400
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_allocate_exchange_data: Calling exchange_data_alloc
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_exchange_data_alloc: Successfully inserted pm_ed ee3800 into list for sa_cfg N/A
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Exchange data allocated for IKE SA 3597662. VR 65535
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_allocate_exchange_data: Successfully allocated exchange data for SA ee1400
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ipsec_create_sa: State = IKE_INIT_SA
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_allocate_exchange_data_ike: Allocating IKE exchange data for SA ee1400 ED b77028
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_allocate_exchange_data_ike: Successfully allocated IKE exchange data for SA ee1400 ED b77028
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_allocate_exchange_data_ipsec: Allocating IPsec exchange data for SA ee1400 ED b77028
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_allocate_exchange_data_ipsec: Successfully allocated IPsec exchange data for SA ee1400 ED b77028
                    [May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ike_sa_take_ref: Calling ike_sa_take_ref
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Taking reference to P1 SA 3597662 to ref count 1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_negotiation Set p2_ed in sa_cfg=Colo_VPN
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_peer_insert_p1sa_entry: Insert p1 sa 3597662 in peer entry 0xb73000
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_trigger_negotiation Convert traffic selectors from V1 format to V2 format for narrowing/matching selectors

[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ts_allocate: Allocated ts 0xe6fa20, ref_cnt 1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ts_allocate: Allocated ts 0xe6fa40, ref_cnt 1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fallback_negotiation_alloc: Taking reference to fallback negotiation ee5800 (now 1 references)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fallback_negotiation_alloc: Allocated fallback negotiation ee5800
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ike_sa_take_ref: Calling ike_sa_take_ref
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Taking reference to P1 SA 3597662 to ref count 2
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_set_thread_debug_info: ikev2_fb_initiate_ipsec_sa: set thread debug info - local 2.2.2.2 remote 1.1.1.1 neg 0xee5800 neg->ike_sa 0xee1400 ike_sa 0x0
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Attach ed b77028 to P1 SA 3597662, slot 0. op handle b772a0
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_reference_exchange_data: Taking reference to exchange data b77028 (to 2)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ts_free: ts 0xe6fa20, ref_cnt 2
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ikev2_ts_free: ts 0xe6fa40, ref_cnt 2
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_i_p1_negotiation_start: Taking reference to fallback negotiation ee5800 (now 2 references)
                    [May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_set_thread_debug_info: ikev2_fb_i_p1_negotiation_start: set thread debug info - local 2.2.2.2 remote 1.1.1.1 neg 0xee5800 neg->ike_sa 0xee1400 ike_sa 0x0
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_st_i_ike_local_address_request: FB; Calling v2 policy function get_local_address_list
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_st_i_ike_id_request: FB; Calling v2 policy function id
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_id_request_cb: Local id payload is ID(type = ipv4 (1), len = 4, value = 2.2.2.2)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_idv2_to_idv1: Converting the IKEv2 payload ID ID(type = ipv4 (1), len = 4, value = 2.2.2.2) to IKEv1 ID
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_idv2_to_idv1: IKEv2 payload ID converted to IKEv1 payload ID ipv4(any:0,[0..3]=2.2.2.2)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_st_i_ike_notify_request: FB; Calling v2 policy function notify_request
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Parsing notification payload for local:2.2.2.2, remote:1.1.1.1 IKEv1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_spd_notify_request: Sending Initial contact
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_st_i_ike_psk_request: FB; Calling v2 policy function shared_key
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_pre_shared_key Start...
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  iked_pm_id_validate NO remote ID, skip validation.
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_find_pre_shared_key_cb: Found preshared key
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_st_i_ike_sa_request: FB; Calling v2 policy function fill_ike_sa
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  IKE SA fill called for negotiation of local:2.2.2.2, remote:1.1.1.1 IKEv1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  Initiator's proposing IKE SA payload SA()
                                           [May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_st_i_conf_request: FB; Calling v2 policy function conf_request
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fallback_negotiation_free: Fallback negotiation ee5800 has still 1 references
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_i_p1_negotiation_negotiate: Sending Initial Contact notification
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_i_p1_negotiation_negotiate: Taking reference to fallback negotiation ee5800 (now 2 references)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_connect: Start, remote_name = 1.1.1.1:500, xchg = 2, flags = 00090000
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_sa_allocate_half: Start
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_sa_allocate: Start, SA = { 51a46716 d5222ec1 - 00000000 00000000 }
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ike_init_isakmp_sa: Start, remote = 1.1.1.1:500, initiator = 1
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 1 (0x0001), value = 5 (0x00000005), len = 2 (0x0002)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 4 (0x0004), value = 2 (0x00000002), len = 2 (0x0002)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 2 (0x0002), value = 2 (0x00000002), len = 2 (0x0002)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 11 (0x000b), value = 1 (0x00000001), len = 2 (0x0002)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 12 (0x000c), value = 28800 (0x00007080), len = 4 (0x0004)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 3 (0x0003), value = 1 (0x00000001), len = 2 (0x0002)
[May 22 19:16:29][2.2.2.2 <-> 1.1.1.1]  ssh_ike_connect: SA = { 51a46716 d5222ec1 - 00000000 00000000}, nego = -1
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 3, fields = 0000 / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 0, fields = 0000 / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matched state = Start sa negotiation I (1)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling output function[0] = ike_st_o_sa_proposal
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_o_sa_proposal: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling output function[1] = ike_st_o_vids
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_request_vendor_ids: Request vendor ID's policy call entered, IKE SA ee1400 (neg ee5800)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_request_vendor_ids: FB; Calling v2 policy function vendor_id_request
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_vid_request_cb: Got a VID of length 16 (neg ee5800)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_request_vendor_id: Sending VID RFC 3706 (Dead Peer Detection)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_vid_request_cb: Got a VID of length 28 (neg ee5800)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_request_vendor_id: Sending VID NetScreen Technologies
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_vid_request_cb: No more VIDs
             [May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_policy_reply_isakmp_vendor_ids: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling output function[2] = ike_st_o_private
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_o_private: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_private_p_1_out: Phase-I output: packet_number 1 ike_sa ee1400 (neg ee5800)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_phase1_pending_natt_operations: Processing pending NAT-T operations
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_private_p_1_out: NAT traversal disabled by policy
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_private_p_1_out: FB; Calling v2 policy function private_payload_request
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_policy_reply_private_payload_out: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: All done, new state = MM SA I (3)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Start, SA = { 0x51a46716 d5222ec1 - 00000000 00000000 } / 00000000, nego = -1
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_encode_data_attribute: encode B: type = 1 (0x0001), len = 2, value = 0005
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_encode_data_attribute: encode B: type = 4 (0x0004), len = 2, value = 0002
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_encode_data_attribute: encode B: type = 2 (0x0002), len = 2, value = 0002
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_encode_data_attribute: encode B: type = 11 (0x000b), len = 2, value = 0001
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_encode_data_attribute: encode V: type = 12 (0x000c), len = 4 (0x0004), value = 00007080 ...
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_encode_data_attribute: encode B: type = 3 (0x0003), len = 2, value = 0001
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Payload length = 64
          [May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Payload length = 20
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Payload length = 32
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Packet length = 144
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Final length = 144
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_send_packet: Start, send SA = { 51a46716 d5222ec1 - 00000000 00000000}, nego = -1, dst = 1.1.1.1:500,  routing table id = 0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_send_packet: Inserting retransmission timer after 10.000000 seconds
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  *** Processing received packet from 1.1.1.1:500 to 2.2.2.2:0, VR 0, packet len: 156, on Interface: fe-0/0/0.0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_st_input_start: [e41400/0] Processing received
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Start, SA = { 51a46716 d5222ec1 - ea3e8b79 7f2e7648 }
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Not found SA = { 51a46716 d5222ec1 - ea3e8b79 7f2e7648 }
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  Failed to find IKEv1 SA for given spi
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_st_input_v1_create_sa: [e41400/0] No IKE SA for packet; requesting permission to create one.
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_rate_limit: Soft limit for p1 negotiation 100.Current active p1 negotiations 0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  New connection from 1.1.1.1:500 allowed
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_st_connect_decision: [e41400/0] Pad allows connection
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Packet from 1.1.1.1:500, use_natt=0 data[0..156] = 51a46716 d5222ec1 ea3e8b79 7f2e7648 ...
                    [May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_get_sa: Start, SA = { 51a46716 d5222ec1 - ea3e8b79 7f2e7648 } / 00000000, remote = 1.1.1.1:500
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Start, SA = { 51a46716 d5222ec1 - ea3e8b79 7f2e7648 }
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_sa_find: Not found SA = { 51a46716 d5222ec1 - ea3e8b79 7f2e7648 }
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_sa_find_half: Start, SA = { 51a46716 d5222ec1 - 00000000 00000000 }
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_sa_find_half: Found half SA = { 51a46716 d5222ec1 - 00000000 00000000 }
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_get_sa: We are intiator, first response packet
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_sa_upgrade: Start, SA = { 51a46716 d5222ec1 - 00000000 00000000 } -> { ... - ea3e8b79 7f2e7648 }
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_udp_callback_common: Old negotiation message_id = 00000000, slot -1
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_packet: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_packet: Start, SA = { 51a46716 d5222ec1 - ea3e8b79 7f2e7648} / 00000000, nego = -1
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_packet: first_payload_type:1.
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_packet: next_payload_type:13.
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_packet: next_payload_type:13.
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_packet: next_payload_type:13.
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_packet: next_payload_type:0.
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_payload_sa: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_payload_sa: Found 1 proposals
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_decode_payload_t: Start, # trans = 1
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute_size: decode_size B: type = 1 (0x0001), value = 5 (0x0005), size = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute_size: decode_size B: type = 2 (0x0002), value = 2 (0x0002), size = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute_size: decode_size B: type = 4 (0x0004), value = 2 (0x0002), size = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute_size: decode_size B: type = 3 (0x0003), value = 1 (0x0001), size = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute_size: decode_size B: type = 11 (0x000b), value = 1 (0x0001), size = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute_size: decode_size B: type = 12 (0x000c), value = 28800 (0x7080), size = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute: decode B: type = 1 (0x0001), value = 5 (0x0005), len = 2, used_bytes = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute: decode B: type = 2 (0x0002), value = 2 (0x0002), len = 2, used_bytes = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute: decode B: type = 4 (0x0004), value = 2 (0x0002), len = 2, used_bytes = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute: decode B: type = 3 (0x0003), value = 1 (0x0001), len = 2, used_bytes = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute: decode B: type = 11 (0x000b), value = 1 (0x0001), len = 2, used_bytes = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_decode_data_attribute: decode B: type = 12 (0x000c), value = 28800 (0x7080), len = 2, used_bytes = 4
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Current state = MM SA I (3)/-1, exchange = 2, auth_method = pre shared key, Initiator
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 3, fields = 0000 / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 0, fields = 0000 / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 3, fields = 0000 / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 2, fields = 0000 / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 4, fields = 0000 / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM final R (8), xchg = 2, auth = 0, fields = ffff / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM done I (9), xchg = 2, auth = 0, fields = ffff / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = AM final I (12), xchg = 4, auth = 0, fields = ffff / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = AM done R (13), xchg = 4, auth = 0, fields = ffff / 0000
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 2, fields = 0001 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM SA R (4), xchg = 2, auth = 2, fields = 0012 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM KE I (5), xchg = 2, auth = 2, fields = 0012 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM KE R (6), xchg = 2, auth = 2, fields = 000c / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM final I (7), xchg = 2, auth = 2, fields = 000c / 0680
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = AM SA I (10), xchg = 4, auth = 2, fields = 001f / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 2, fields = 0008 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 3, fields = 0001 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM SA R (4), xchg = 2, auth = 3, fields = 0016 / 06e0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM KE I (5), xchg = 2, auth = 3, fields = 0016 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM KE R (6), xchg = 2, auth = 3, fields = 0020 / 0680
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM final I (7), xchg = 2, auth = 3, fields = 0020 / 0680
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = AM SA I (10), xchg = 4, auth = 3, fields = 0037 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 3, fields = 0020 / 0680
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 4, fields = 0001 / 06c0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Matched state = MM SA I (3)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling input function[0] = ike_st_i_sa_value
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_i_sa_value: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 1 (0x0001), value = 5 (0x00000005), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 4 (0x0004), value = 2 (0x00000002), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 2 (0x0002), value = 2 (0x00000002), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 11 (0x000b), value = 1 (0x00000001), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 12 (0x000c), value = 28800 (0x00007080), len = 4 (0x0004)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 3 (0x0003), value = 1 (0x00000001), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 1 (0x0001), value = 5 (0x00000005), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 2 (0x0002), value = 2 (0x00000002), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 4 (0x0004), value = 2 (0x00000002), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 3 (0x0003), value = 1 (0x00000001), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 11 (0x000b), value = 1 (0x00000001), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 12 (0x000c), value = 28800 (0x00007080), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 1 (0x0001), value = 5 (0x00000005), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 2 (0x0002), value = 2 (0x00000002), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 4 (0x0004), value = 2 (0x00000002), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 3 (0x0003), value = 1 (0x00000001), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 11 (0x000b), value = 1 (0x00000001), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ssh_ike_get_data_attribute_int: get_int: type = 12 (0x000c), value = 28800 (0x00007080), len = 2 (0x0002)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling input function[1] = ike_st_i_cr
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_i_cr: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling input function[2] = ike_st_i_cert
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_i_cert: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling input function[3] = ike_st_i_status_n
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling input function[4] = ike_st_i_vid
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_i_vid: VID[0..28] = 9436e8d6 7174ef9a ...
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_vendor_id: Received vendor ID, length 28, IKE SA ee1400 (neg ee5800)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_check_natt_vendor_id: Start ike_sa ee1400
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id
                    [May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_received_vendor_id: Received vendor-id for NetScreen Technologies
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_i_vid: VID[0..16] = afcad713 68a1f1c9 ...
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_vendor_id: Received vendor ID, length 16, IKE SA ee1400 (neg ee5800)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_check_natt_vendor_id: Start ike_sa ee1400
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_pm_ike_received_vendor_id: Received vendor-id for RFC 3706 (Dead Peer Detection)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_i_vid: VID[0..20] = 48656172 74426561 ...
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_vendor_id: Received vendor ID, length 20, IKE SA ee1400 (neg ee5800)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_check_natt_vendor_id: Start ike_sa ee1400
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling input function[5] = ike_st_i_private
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_i_private: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling output function[0] = ike_st_o_ke
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_o_ke: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_dh_get_group: DH Group type dl-modp
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_dh_get_group: DH Group size 1024
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_dh_get_group: DH Group 2
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_dh_generate_sync: Requested DH group 2
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  iked_dh_generate: Generated DH keys using hardware for DH group 2
                    [May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  juniper_dlp_diffie_hellman_generate_async: DH Generate Secs [0] USecs [6251]
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  juniper_dlp_diffie_hellman_generate_async: Generated DH using hardware
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling output function[1] = ike_st_o_nonce
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_o_nonce: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_isakmp_nonce_data_len: Entered
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_policy_reply_isakmp_nonce_data_len: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: Calling output function[2] = ike_st_o_private
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_st_o_private: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_private_p_1_out: Phase-I output: packet_number 3 ike_sa ee1400 (neg ee5800)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_phase1_pending_natt_operations: Processing pending NAT-T operations
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_private_p_1_out: NAT traversal disabled by policy
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_fb_private_p_1_out: FB; Calling v2 policy function private_payload_request
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_policy_reply_private_payload_out: Start
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_state_step: All done, new state = MM KE I (5)
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Start, SA = { 0x51a46716 d5222ec1 - ea3e8b79 7f2e7648 } / 00000000, nego = -1
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Payload length = 132
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Payload length = 20
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Packet length = 180
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_encode_packet: Final length = 180
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_send_packet: Start, send SA = { 51a46716 d5222ec1 - ea3e8b79 7f2e7648}, nego = -1, dst = 1.1.1.1:500,  routing table id = 0
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ike_send_packet: Inserting retransmission timer after 10.000000 seconds
               [May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_destroy: [e41400/0] Destructor
[May 22 19:16:30][2.2.2.2 <-> 1.1.1.1]  ikev2_packet_free: [e41400/0] Freeing

mavtech@Dallas_SRX>