#run show log IKE-TRACE [Sep 16 17:32:25][ <-> ] ike_decode_packet: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4} / 00000000, nego = -1 [Sep 16 17:32:25][ <-> ] ike_decode_packet: first_payload_type:1. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:4. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:10. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:5. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:0. [Sep 16 17:32:25][ <-> ] ike_decode_payload_sa: Start [Sep 16 17:32:25][ <-> ] ike_decode_payload_sa: Found 1 proposals [Sep 16 17:32:25][ <-> ] ike_decode_payload_t: Start, # trans = 1 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 1 (0x0001), value = 7 (0x0007), size = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 14 (0x000e), value = 128 (0x0080), size = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 2 (0x0002), value = 2 (0x0002), size = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 3 (0x0003), value = 65001 (0xfde9), size = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 4 (0x0004), value = 2 (0x0002), size = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 11 (0x000b), value = 1 (0x0001), size = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 12 (0x000c), value = 28740 (0x7044), size = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 1 (0x0001), value = 7 (0x0007), len = 2, used_bytes = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 14 (0x000e), value = 128 (0x0080), len = 2, used_bytes = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 2 (0x0002), value = 2 (0x0002), len = 2, used_bytes = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 3 (0x0003), value = 65001 (0xfde9), len = 2, used_bytes = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 4 (0x0004), value = 2 (0x0002), len = 2, used_bytes = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 11 (0x000b), value = 1 (0x0001), len = 2, used_bytes = 4 [Sep 16 17:32:25][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 12 (0x000c), value = 28740 (0x7044), len = 2, used_bytes = 4 [Sep 16 17:32:25][ <-> ] IKEv1 packet R(:500 <- :500): len= 400, mID=00000000, HDR, SA, Vid, Vid, Vid, Vid, KE, Nonce, ID, Vid [Sep 16 17:32:25][ <-> ] ike_state_step: Current state = Start sa negotiation R (2)/-1, exchange = 4, auth_method = any, Responder [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matched state = Start sa negotiation R (2) [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[0] = ike_st_i_vid [Sep 16 17:32:25][ <-> ] ike_st_i_vid: VID[0..16] = afcad713 68a1f1c9 ... [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 16, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:25][ <-> ] iked_pm_ike_received_vendor_id: Received vendor-id for RFC 3706 (Dead Peer Detection) [Sep 16 17:32:25][ <-> ] ike_st_i_vid: VID[0..8] = 09002689 dfd6b712 ... [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 8, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:25][ <-> ] ike_st_i_vid: VID[0..16] = 7d9419a6 5310ca6f ... [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 16, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:25][ <-> ] ikev2_fb_check_natt_vendor_id: NAT-T vendor id [draft-ietf-ipsec-nat-t-ike-03] [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:25][ <-> ] iked_pm_ike_received_vendor_id: Received vendor-id for draft-ietf-ipsec-nat-t-ike-03 [Sep 16 17:32:25][ <-> ] ike_st_i_vid: VID[0..16] = 90cb8091 3ebb696e ... [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 16, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:25][ <-> ] ikev2_fb_check_natt_vendor_id: NAT-T vendor id [draft-ietf-ipsec-nat-t-ike-02] [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:25][ <-> ] iked_pm_ike_received_vendor_id: Received vendor-id for draft-ietf-ipsec-nat-t-ike-02 [Sep 16 17:32:25][ <-> ] ike_st_i_vid: VID[0..17] = 4a4e5052 20495053 ... [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 17, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:25][ <-> ] iked_pm_ike_received_vendor_id: Received vendor-id for JNPR IPSec Client [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[1] = ike_st_i_id [Sep 16 17:32:25][ <-> ] ike_st_i_id: Start [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[2] = ike_st_i_sa_proposal [Sep 16 17:32:25][ <-> ] ike_st_i_sa_proposal: Start [Sep 16 17:32:25][ <-> ] ike_free_id_payload: Start, id type = 2 [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_select_sa: Select IKE SA policy call entered, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_select_sa: Taking reference to fallback negotiation 1275800 (now 2 references) [Sep 16 17:32:25][ <-> ] ssh_set_thread_debug_info: ikev2_fb_isakmp_select_sa: set thread debug info - local 0x8f3bcac4 remote 0x28575b94neg 0x1275800 neg->ike_sa 0x1277000 ike_sa 0x0 [Sep 16 17:32:25][ <-> ] ike_state_step: Input function[2] = ike_st_i_sa_proposal asked retry later [Sep 16 17:32:25][ <-> ] ike_process_packet: No output packet, returning [Sep 16 17:32:25][ <-> ] ikev2_fb_st_select_ike_sa: FSM_SET_NEXT:ikev2_fb_st_select_ike_sa_finish [Sep 16 17:32:25][ <-> ] ikev2_fb_st_select_ike_sa: FB; Calling v2 policy function select_ike_sa [Sep 16 17:32:25][ <-> ] Parsing notification payload for local:, remote: IKEv1 [Sep 16 17:32:25][ <-> ] Search for a tunnel matching the IKE peers, local:, remote: IKEv1 [Sep 16 17:32:25][ <-> ] iked_pm_phase1_sa_cfg_lookup_by_addr: Address based phase 1 SA-CFG lookup failed for local:, remote: IKEv1 [Sep 16 17:32:25][ <-> ] iked_pm_phase1_sa_cfg_lookup_by_id called with id type 2 [Sep 16 17:32:25][ <-> ] ikev2_fb_idv2_to_idv1: Converting the IKEv2 payload ID IDa(type = fqdn (2), len = 15, value = dynvpn) to IKEv1 ID [Sep 16 17:32:25][ <-> ] ikev2_fb_idv2_to_idv1: IKEv2 payload ID converted to IKEv1 payload ID fqdn(any:0,[0..14]=dynvpn) [Sep 16 17:32:25][ <-> ] iked_pm_sa_cfg_lookup_by_id partial match type 2 [Sep 16 17:32:25][ <-> ] iked_pm_dynamic_gw_local_addr_based_lookup: called with local ip: [Sep 16 17:32:25][ <-> ] Not doing MM check since initiator=FALSE and exch_type=4 [Sep 16 17:32:25][ <-> ] dynamic gateway match unsuccessful: [Sep 16 17:32:25][ <-> ] iked_pm_ike_spd_select_ike_sa: Setting tunnel-event IKE gateway configuration lookup failed during negotiation for P1-SA 7353743 [Sep 16 17:32:25][ <-> ] iked_pm_ike_spd_select_ike_sa failed. rc 1, error_code: No proposal chosen [Sep 16 17:32:25][ <-> ] ikev2_fb_spd_select_sa_cb: IKEv2 SA select failed with error No proposal chosen (neg 1275800) [Sep 16 17:32:25][ <-> ] ike_isakmp_sa_reply: Start [Sep 16 17:32:25][ <-> ] ikev2_fallback_negotiation_free: Fallback negotiation 1275800 has still 1 references [Sep 16 17:32:25][ <-> ] ssh_set_debug_gw_info: ssh_set_debug_gw_info: set gw debug info - local remote [Sep 16 17:32:25][ <-> ] ike_state_restart_packet: Start, restart packet SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4}, nego = -1 [Sep 16 17:32:25][ <-> ] ike_state_step: Current state = Start sa negotiation R (2)/2, exchange = 4, auth_method = any, Responder [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matched state = Start sa negotiation R (2) [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[2] = ike_st_i_sa_proposal [Sep 16 17:32:25][ <-> ] ike_st_i_sa_proposal: Start [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[3] = ike_st_i_nonce [Sep 16 17:32:25][ <-> ] ike_st_i_nonce: Start, nonce[0..64] = 4c1ac409 8be42e67 ... [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[4] = ike_st_i_cert [Sep 16 17:32:25][ <-> ] ike_st_i_cert: Start [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[5] = ike_st_i_hash_key [Sep 16 17:32:25][ <-> ] ike_st_i_hash_key: Start, no key_hash [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[6] = ike_st_i_ke [Sep 16 17:32:25][ <-> ] ike_st_i_ke: Ke[0..128] = fe9499f6 ca973ad2 ... [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[7] = ike_st_i_cr [Sep 16 17:32:25][ <-> ] ike_st_i_cr: Start [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[8] = ike_st_i_status_n [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[9] = ike_st_i_private [Sep 16 17:32:25][ <-> ] ike_st_i_private: Start [Sep 16 17:32:25][ <-> ] ike_state_step: Calling output function[0] = ike_st_o_sa_values [Sep 16 17:32:25][ <-> ] ike_st_o_sa_values: Start [Sep 16 17:32:25][ <-> ] ike_state_step: Output function[0] = ike_st_o_sa_values failed [Sep 16 17:32:25][ <-> ] ike_packet_free: Start [Sep 16 17:32:25][ <-> ] ike_state_restart_packet: Error, send notify [Sep 16 17:32:25][ <-> ] ikev2_fb_negotiation_done_isakmp: Entered IKE error code No proposal chosen (14), IKE SA 1277000 (neg 1275800) [Sep 16 17:32:25][ <-> ] :500 (Responder) <-> :49778 { 56cf4979 c9a7b420 - 90baaf9f c11657c4 [-1] / 0x00000000 } Aggr; Error = No proposal chosen (14) [Sep 16 17:32:25][ <-> ] ike_alloc_negotiation: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4} [Sep 16 17:32:25][ <-> ] ike_alloc_negotiation: Found slot 0, max 1 [Sep 16 17:32:25][ <-> ] ike_init_info_exchange: New informational negotiation message_id = 3eee12e4 initialized using slot 0 [Sep 16 17:32:25][ <-> ] ike_init_info_exchange: Created random message id = 3eee12e4 [Sep 16 17:32:25][ <-> ] ike_init_info_exchange: No phase 1 done, use only N or D payload [Sep 16 17:32:25][ <-> ] ssh_ike_encode_data_attribute: encode B: type = 12 (0x000c), len = 2, value = 0001 [Sep 16 17:32:25][ <-> ] ssh_ike_encode_data_attribute: encode V: type = 6 (0x0006), len = 34 (0x0022), value = 436f756c ... [Sep 16 17:32:25][ <-> ] ssh_ike_encode_data_attribute: encode B: type = 8 (0x0008), len = 2, value = 0000 [Sep 16 17:32:25][ <-> ] ike_encode_packet: Start, SA = { 0x56cf4979 c9a7b420 - 90baaf9f c11657c4 } / 3eee12e4, nego = 0 [Sep 16 17:32:25][ <-> ] ike_encode_packet: Payload length = 74 [Sep 16 17:32:25][ <-> ] ike_encode_packet: Payload length = 102 [Sep 16 17:32:25][ <-> ] IKEv1 packet S(:500 -> :500): len= 102, mID=3eee12e4, HDR, N(NO_PROPOSAL_CHOSEN) [Sep 16 17:32:25][ <-> ] ike_encode_packet: Final length = 102 [Sep 16 17:32:25][ <-> ] ike_send_notify: Sending notification to :49778 [Sep 16 17:32:25][ <-> ] ike_send_packet: Start, send SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4}, nego = 0, dst = :49778 [Sep 16 17:32:25][ <-> ] ike_packet_free: Start [Sep 16 17:32:25][ <-> ] ike_delete_negotiation: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4}, nego = 0 [Sep 16 17:32:25][ <-> ] ike_free_negotiation_info: Start, nego = 0 [Sep 16 17:32:25][ <-> ] ike_free_negotiation: Start, nego = 0 [Sep 16 17:32:25][ <-> ] ikev2_fb_phase_ii_sa_freed: Phase-II free Entered [Sep 16 17:32:25][ <-> ] ikev2_fb_p1_negotiation_wait_sa_done: Phase-I negotiation is now done (neg 1275800) [Sep 16 17:32:25][ <-> ] ikev2_fb_p1_negotiation_wait_sa_done: FB; Calling v2 policy function ike_sa_done [Sep 16 17:32:25][ <-> ] IKE negotiation fail for local:, remote: IKEv1 with status: No proposal chosen [Sep 16 17:32:25][ <-> ] iked_delete_slot_table_entry Slot released msg_id<0> cookie<56cf4979c9a7b420> [Sep 16 17:32:25][ <-> ] iked_tunnel_event_add_event_in_gw: tunnel-event IKE gateway configuration lookup failed during negotiation count incremented to 395 [Sep 16 17:32:25][ <-> ] IKEv1 Error : No proposal chosen [Sep 16 17:32:25][ <-> ] ikev2_fb_p1_negotiation_destructor: Freeing fallback negotiation context [Sep 16 17:32:25][ <-> ] ikev2_fallback_negotiation_free: Freeing fallback negotiation 1275800 [Sep 16 17:32:25][ <-> ] ikev2_free_exchange_data: Freeing exchange data from SA 1277000, ED 1279028 (1) [Sep 16 17:32:25][ <-> ] ikev2_free_exchange_data_ipsec: Freeing IPsec exchange data from SA 1277000 [Sep 16 17:32:25][ <-> ] ikev2_free_exchange_data_ipsec: Successfully freed IPsec exchange data from SA 1277000 [Sep 16 17:32:25][ <-> ] ikev2_free_exchange_data_ike: Freeing IKE exchange data from SA 1277000 [Sep 16 17:32:25][ <-> ] ikev2_free_exchange_data_ike: Successfully freed IKE exchange data from SA 1277000 [Sep 16 17:32:25][ <-> ] ikev2_free_exchange_data: Notify call: exchange_data_free [Sep 16 17:32:25][ <-> ] Freeing P2 Ed for sa-cfg N/A [Sep 16 17:32:25][ <-> ] P2_ED doesn't have p1_sa pointer or peer-entry. Not calling iked_pm_reset_p2_ed_in_peer_entry_sacfgs [Sep 16 17:32:25][ <-> ] iked_pm_ike_exchange_data_free: Successfully removed pm_ed 1273a00 from list for sa_cfg N/A [Sep 16 17:32:25][ <-> ] ikev2_free_exchange_data: Successfully freed exchange data from SA 1277000 [Sep 16 17:32:25][ <-> ] ikev2_fallback_negotiation_free: Freeing reference to IKE SA 1277000 to ref count 1 [Sep 16 17:32:25][ <-> ] ssh_ikev2_ike_sa_free: Notify call: ike_sa_free_ref [Sep 16 17:32:25][ <-> ] Freeing reference to P1 SA 7353743 to ref count 1 [Sep 16 17:32:25][ <-> ] *** Processing received packet from :49778 to :0, VR 0, packet len: 40, on Interface: ge-0/0/0.0 [Sep 16 17:32:25][ <-> ] ---------> Received from :49778 to :0, VR 0, length 40 on IF ge-0/0/0.0 [Sep 16 17:32:25][ <-> ] ikev2_packet_st_input_start: [11dd400/0] ******** Processing received ************ [Sep 16 17:32:25][ <-> ] ikev2_packet_st_input_start: FSM_SET_NEXT:ikev2_packet_st_input_v1_get_sa [Sep 16 17:32:25][ <-> ] ike_sa_find: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4 } [Sep 16 17:32:25][ <-> ] ike_sa_find: Found SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4 } [Sep 16 17:32:25][ <-> ] Found IKEv1 SA [Sep 16 17:32:25][ <-> ] ikev2_packet_st_input_v1_get_sa: [11dd400/deadbeee] Packet to existing v1 SA [Sep 16 17:32:25][ <-> ] ikev2_packet_st_input_v1_get_sa: FSM_SET_NEXT:ikev2_packet_v1_start [Sep 16 17:32:25][ <-> ] ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library [Sep 16 17:32:25][ <-> ] ike_udp_callback_common: Packet from :49778, use_natt=0 data[0..40] = 56cf4979 c9a7b420 90baaf9f c11657c4 ... [Sep 16 17:32:25][ <-> ] ike_get_sa: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4 } / a2589be1, remote = :49778 [Sep 16 17:32:25][ <-> ] ike_sa_find: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4 } [Sep 16 17:32:25][ <-> ] ike_sa_find: Found SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4 } [Sep 16 17:32:25][ <-> ] ike_alloc_negotiation: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4} [Sep 16 17:32:25][ <-> ] ike_alloc_negotiation: Found slot 0, max 1 [Sep 16 17:32:25][ <-> ] ike_udp_callback_common: New informational negotiation message_id = a2589be1 initialized using slot 0 [Sep 16 17:32:25][ <-> ] ike_udp_callback_common: Old negotiation message_id = a2589be1, slot 0 [Sep 16 17:32:25][ <-> ] ike_decode_packet: Start [Sep 16 17:32:25][ <-> ] ike_decode_packet: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4} / a2589be1, nego = 0 [Sep 16 17:32:25][ <-> ] ike_decode_packet: first_payload_type:11. [Sep 16 17:32:25][ <-> ] ike_decode_packet: next_payload_type:0. [Sep 16 17:32:25][ <-> ] IKEv1 packet R(:500 <- :500): len= 40, mID=a2589be1, HDR, N(NO_PROPOSAL_CHOSEN) [Sep 16 17:32:25][ <-> ] ike_state_step: Current state = Done (53)/-1, exchange = 5, auth_method = any, Responder [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 3, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 0, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 3, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 2, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 4, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM final R (8), xchg = 2, auth = 0, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM done I (9), xchg = 2, auth = 0, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM final I (12), xchg = 4, auth = 0, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM done R (13), xchg = 4, auth = 0, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 2, fields = 0001 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM SA R (4), xchg = 2, auth = 2, fields = 0012 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM KE I (5), xchg = 2, auth = 2, fields = 0012 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM KE R (6), xchg = 2, auth = 2, fields = 000c / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM final I (7), xchg = 2, auth = 2, fields = 000c / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM SA I (10), xchg = 4, auth = 2, fields = 001f / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 2, fields = 0008 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 2, fields = 0020 / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 3, fields = 0001 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM SA R (4), xchg = 2, auth = 3, fields = 0016 / 06e0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM KE I (5), xchg = 2, auth = 3, fields = 0016 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM KE R (6), xchg = 2, auth = 3, fields = 0020 / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM final I (7), xchg = 2, auth = 3, fields = 0020 / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM SA I (10), xchg = 4, auth = 3, fields = 0037 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 3, fields = 0020 / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 4, fields = 0001 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM SA R (4), xchg = 2, auth = 4, fields = 0012 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM KE I (5), xchg = 2, auth = 4, fields = 0012 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM KE R (6), xchg = 2, auth = 4, fields = 0024 / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM final I (7), xchg = 2, auth = 4, fields = 0024 / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM SA I (10), xchg = 4, auth = 4, fields = 0037 / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 4, fields = 0020 / 0680 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 0, fields = 0001 / 06c0 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start QM I (14), xchg = 32, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start QM R (15), xchg = 32, auth = 1, fields = 0031 / 0206 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = QM HASH SA I (16), xchg = 32, auth = 1, fields = 0031 / 0206 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = QM HASH SA R (17), xchg = 32, auth = 1, fields = 0020 / 0200 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = QM HASH I (18), xchg = 32, auth = 1, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = QM done R (19), xchg = 32, auth = 1, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start NGM I (20), xchg = 33, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start NGM R (21), xchg = 33, auth = 1, fields = 0021 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = NGM HASH SA I (22), xchg = 33, auth = 1, fields = 0021 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = NGM HASH SA R (23), xchg = 33, auth = 1, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = NGM done I (24), xchg = 33, auth = 1, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start CFG I (25), xchg = 6, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start CFG R (26), xchg = 6, auth = 1, fields = 0820 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR I (27), xchg = 6, auth = 1, fields = 0820 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR SA R (28), xchg = 6, auth = 1, fields = 0820 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR SA R (28), xchg = 6, auth = 1, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = CFG done I (29), xchg = 6, auth = 1, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start CFG I (25), xchg = 6, auth = 0, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start CFG R (26), xchg = 6, auth = 0, fields = 0800 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR I (27), xchg = 6, auth = 0, fields = 0800 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR SA R (28), xchg = 6, auth = 0, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = CFG done I (29), xchg = 6, auth = 0, fields = ffff / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start GDOI I (30), xchg = 32, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Start GDOI R (31), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = GDOI ID I (32), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = GDOI SA R (33), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = GDOI HASH3 I (34), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = GDOI KD R (35), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = GDOI DONE I (36), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (37), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (38), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (39), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (40), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (41), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (42), xchg = 240, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (43), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (44), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (45), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (46), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (47), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (48), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (49), xchg = 241, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (50), xchg = 241, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (51), xchg = 241, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = unknown (52), xchg = 241, auth = 1, fields = ffff / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Any (0), xchg = 256, auth = 1, fields = 0220 / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Done (53), xchg = 256, auth = 1, fields = 0120 / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matching with state = Any (0), xchg = 256, auth = 0, fields = 0200 / ffff [Sep 16 17:32:25][ <-> ] ike_state_step: Matched state = Any (0) [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[0] = ike_st_i_n [Sep 16 17:32:25][ <-> ] ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..0] = 00000000 00000000 ..., data[0..0] = 00000000 00000000 ... [Sep 16 17:32:25][ <-> ] :500 (Responder) <-> :49778 { 56cf4979 c9a7b420 - 90baaf9f c11657c4 [0] / 0xa2589be1 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it [Sep 16 17:32:25][ <-> ] ike_state_step: Calling input function[1] = ike_st_i_private [Sep 16 17:32:25][ <-> ] ike_st_i_private: Start [Sep 16 17:32:25][ <-> ] ike_state_step: Calling output function[0] = ike_st_o_n_done [Sep 16 17:32:25][ <-> ] ike_packet_free: Start [Sep 16 17:32:25][ <-> ] ike_state_step: All done, new state = Done (53) [Sep 16 17:32:25][ <-> ] ike_process_packet: Connected, sending notify [Sep 16 17:32:25][ <-> ] ike_send_notify: Connected, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4}, nego = 0 [Sep 16 17:32:25][ <-> ] ike_delete_negotiation: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4}, nego = 0 [Sep 16 17:32:25][ <-> ] ike_free_negotiation_info: Start, nego = 0 [Sep 16 17:32:25][ <-> ] ike_free_negotiation: Start, nego = 0 [Sep 16 17:32:25][ <-> ] ike_packet_free: Start [Sep 16 17:32:25][ <-> ] ikev2_fb_phase_ii_sa_freed: Phase-II free Entered [Sep 16 17:32:25][ <-> ] ikev2_packet_destroy: [11dd400/deadbeee] Destructor [Sep 16 17:32:25][ <-> ] ikev2_packet_free: [11dd400/deadbeee] Freeing [Sep 16 17:32:25][ <-> ] ssh_set_debug_gw_info: ssh_set_debug_gw_info: set gw debug info - local remote [Sep 16 17:32:25][ <-> ] ike_remove_callback: Start, delete SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4}, nego = -1 [Sep 16 17:32:25][ <-> ] ike_delete_negotiation: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4}, nego = -1 [Sep 16 17:32:25][ <-> ] ssh_ike_tunnel_table_entry_delete: Deleting tunnel_id: 0 from IKE tunnel table [Sep 16 17:32:25][ <-> ] ssh_ike_tunnel_table_entry_delete: The tunnel id: 0 doesn't exist in IKE tunnel table [Sep 16 17:32:25][ <-> ] ike_sa_delete: Start, SA = { 56cf4979 c9a7b420 - 90baaf9f c11657c4 } [Sep 16 17:32:25][ <-> ] ike_free_negotiation_isakmp: Start, nego = -1 [Sep 16 17:32:25][ <-> ] ike_free_negotiation: Start, nego = -1 [Sep 16 17:32:25][ <-> ] ike_packet_free: Start [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_sa_freed: Received notification from the ISAKMP library that the IKE SA 1277000 is freed [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_sa_freed: FB; Calling v2 policy function ike_sa_delete [Sep 16 17:32:25][ <-> ] ikev2_fb_isakmp_sa_freed: Notify call: ike_sa_delete [Sep 16 17:32:25][ <-> ] IKE SA delete called for p1 sa 7353743 (ref cnt 1) local:, remote:, IKEv1 [Sep 16 17:32:25][ <-> ] P1 SA 7353743 stop timer. timer duration 30, reason 1. [Sep 16 17:32:25][ <-> ] Freeing reference to P1 SA 7353743 to ref count 0 [Sep 16 17:32:25][ <-> ] iked_pm_p1_sa_destroy: Decremented active p1 negotiations.Current active p1 negotiations 0 [Sep 16 17:32:25][ <-> ] iked_pm_p1_sa_destroy: p1 sa 7353743 (ref cnt 0), waiting_for_del 0x0 [Sep 16 17:32:25][ <-> ] Deleting p1 sa (7353743) node from IKE p1 SA P-tree [Sep 16 17:32:25][ <-> ] The tunnel id: 7353743 doesn't exist in P1 SA P-tree [Sep 16 17:32:25][ <-> ] ikev2_transmit_window_uninit: Uninitialising transmit window 1277180 [Sep 16 17:32:25][ <-> ] ikev2_transmit_window_flush: Transmit window 1277180: Flushing. [Sep 16 17:32:25][ <-> ] ikev2_receive_window_uninit: Uninitialising receive window 1277190 [Sep 16 17:32:25][ <-> ] ike_free_id_payload: Start, id type = 2 [Sep 16 17:32:25][ <-> ] ike_free_sa: Start [Sep 16 17:32:31][ <-> ] *** Processing received packet from :49778 to :0, VR 0, packet len: 400, on Interface: ge-0/0/0.0 [Sep 16 17:32:31][ <-> ] ---------> Received from :49778 to :0, VR 0, length 400 on IF ge-0/0/0.0 [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_start: [11dd800/0] ******** Processing received ************ [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_start: FSM_SET_NEXT:ikev2_packet_st_input_v1_get_sa [Sep 16 17:32:31][ <-> ] Failed to find IKEv1 SA for given spi [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_v1_get_sa: FSM_SET_NEXT:ikev2_packet_st_input_v1_create_sa [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_v1_create_sa: [11dd800/0] No IKE SA for packet; requesting permission to create one. [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_v1_create_sa: FSM_SET_NEXT:ikev2_packet_st_connect_decision [Sep 16 17:32:31][ <-> ] iked_pm_ike_rate_limit: Soft limit for p1 negotiation 100.Current active p1 negotiations 0 [Sep 16 17:32:31][ <-> ] New connection from :49778 allowed [Sep 16 17:32:31][ <-> ] ikev2_packet_st_connect_decision: [11dd800/0] Pad allows connection [Sep 16 17:32:31][ <-> ] ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library [Sep 16 17:32:31][ <-> ] ike_udp_callback_common: Packet from :49778, use_natt=0 data[0..400] = c22e9dda 912ae90f 00000000 00000000 ... [Sep 16 17:32:31][ <-> ] ike_get_sa: Start, SA = { c22e9dda 912ae90f - 00000000 00000000 } / 00000000, remote = :49778 [Sep 16 17:32:31][ <-> ] ike_get_sa: We are responder and this is initiators first packet [Sep 16 17:32:31][ <-> ] ike_cookie_create: Cookie create [Sep 16 17:32:31][ <-> ] 00000000: a2ca 4fac 3ddb 61f3 ..O.=.a. [Sep 16 17:32:31][ <-> ] ike_sa_allocate: Start, SA = { c22e9dda 912ae90f - a2ca4fac 3ddb61f3 } [Sep 16 17:32:31][ <-> ] ike_udp_callback_common: New SA [Sep 16 17:32:31][ <-> ] ike_init_isakmp_sa: Start, remote = :49778, initiator = 0 [Sep 16 17:32:31][ <-> ] ikev2_fb_new_connection: New ISAKMP connection from remote address /49778 [Sep 16 17:32:31][ <-> ] ikev2_fallback_negotiation_alloc: Taking reference to fallback negotiation 1275800 (now 1 references) [Sep 16 17:32:31][ <-> ] ikev2_fallback_negotiation_alloc: Allocated fallback negotiation 1275800 [Sep 16 17:32:31][ <-> ] ssh_set_thread_debug_info: ikev2_fb_new_connection: set thread debug info - local 0x8f3bcac4 remote 0x28575b94neg 0x1275800 neg->ike_sa 0x0 ike_sa 0x0 [Sep 16 17:32:31][ <-> ] ikev2_packet_destroy: [11dd800/0] Destructor [Sep 16 17:32:31][ <-> ] ikev2_packet_free: [11dd800/0] Freeing [Sep 16 17:32:31][ <-> ] ikev2_fb_p1_negotiation_allocate_sa: FSM_SET_NEXT:ikev2_fb_p1_negotiation_wait_sa_done [Sep 16 17:32:31][ <-> ] ikev2_fb_p1_negotiation_allocate_sa: Taking reference to fallback negotiation 1275800 (now 2 references) [Sep 16 17:32:31][ <-> ] ssh_set_thread_debug_info: ikev2_fb_p1_negotiation_allocate_sa: set thread debug info - local 0x8f3bcac4 remote 0x28575b94neg 0x1275800 neg->ike_sa 0x0 ike_sa 0x0 [Sep 16 17:32:31][ <-> ] ikev2_fb_p1_negotiation_wait_sa_done: Suspending until the IKE SA is done (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_st_new_p1_connection_start: FSM_SET_NEXT:ikev2_fb_st_new_p1_connection_local_addresses [Sep 16 17:32:31][ <-> ] ikev2_fb_st_new_p1_connection_start: FB; Calling v2 policy function ike_sa_allocate [Sep 16 17:32:31][ <-> ] iked_pm_p1_sa_alloc: Incremented active p1 negotiations.Current active p1 negotiations 1 [Sep 16 17:32:31][ <-> ] chassis 0 fpc 0 pic 0 kmd-instance 0 current tunnel id 7353743 [Sep 16 17:32:31][ <-> ] Allocated IKE SA index 7353744, ref cnt 0 [Sep 16 17:32:31][ <-> ] In iked_p1_sa_patricia_tree_fpc_pic_entry_add ADDED THE PATNODEike sa index 7353744 [Sep 16 17:32:31][ <-> ] P1 SA 7353744 start timer. timer duration 30, reason 1. [Sep 16 17:32:31][ <-> ] ikev2_fb_ike_sa_allocate_cb: New IKE SA allocated successfully 1277000 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_ike_sa_allocate_cb: Taking reference to IKE SA 1277000 to ref count 1 [Sep 16 17:32:31][ <-> ] ssh_ikev2_ike_sa_take_ref: Notify call: ike_sa_take_ref [Sep 16 17:32:31][ <-> ] Taking reference to P1 SA 7353744 to ref count 1 [Sep 16 17:32:31][ <-> ] ikev2_fb_ike_sa_allocate_cb: Taking reference to IKE SA 1277000 to ref count 2 [Sep 16 17:32:31][ <-> ] ssh_ikev2_ike_sa_take_ref: Notify call: ike_sa_take_ref [Sep 16 17:32:31][ <-> ] Taking reference to P1 SA 7353744 to ref count 2 [Sep 16 17:32:31][ <-> ] ikev2_allocate_exchange_data: Calling exchange_data_alloc [Sep 16 17:32:31][ <-> ] iked_pm_ike_exchange_data_alloc: Successfully inserted pm_ed 1273a00 into list for sa_cfg N/A [Sep 16 17:32:31][ <-> ] Exchange data allocated for IKE SA 7353744. VR 65535 [Sep 16 17:32:31][ <-> ] ikev2_allocate_exchange_data: Successfully allocated exchange data for SA 1277000 [Sep 16 17:32:31][ <-> ] ikev2_allocate_exchange_data_ike: Allocating IKE exchange data for SA 1277000 ED 1279028 [Sep 16 17:32:31][ <-> ] ikev2_allocate_exchange_data_ike: Successfully allocated IKE exchange data for SA 1277000 ED 1279028 [Sep 16 17:32:31][ <-> ] ikev2_allocate_exchange_data_ipsec: Allocating IPsec exchange data for SA 1277000 ED 1279028 [Sep 16 17:32:31][ <-> ] ikev2_allocate_exchange_data_ipsec: Successfully allocated IPsec exchange data for SA 1277000 ED 1279028 [Sep 16 17:32:31][ <-> ] ssh_isakmp_update_responder_cookie: Updating responder IKE cookie [Sep 16 17:32:31][ <-> ] ssh_isakmp_update_responder_cookie: Original IKE cookie [Sep 16 17:32:31][ <-> ] 00000000: a2ca 4fac 3ddb 61f3 ..O.=.a. [Sep 16 17:32:31][ <-> ] ssh_isakmp_update_responder_cookie: New IKE cookie [Sep 16 17:32:31][ <-> ] 00000000: 2530 77f2 f3c8 dbdd %0w..... [Sep 16 17:32:31][ <-> ] ikev2_fb_st_new_p1_connection_local_addresses: Accepting new Phase-1 negotiation: local=:500, remote=:49778 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_st_new_p1_connection_local_addresses: FSM_SET_NEXT:ikev2_fb_st_new_p1_connection_result [Sep 16 17:32:31][ <-> ] ikev2_fb_st_new_p1_connection_local_addresses: FB; Calling v2 policy function get_local_address_list [Sep 16 17:32:31][ <-> ] ssh_isakmp_update_responder_cookie: Updating responder IKE cookie [Sep 16 17:32:31][ <-> ] ssh_isakmp_update_responder_cookie: Original IKE cookie [Sep 16 17:32:31][ <-> ] 00000000: 2530 77f2 f3c8 dbdd %0w..... [Sep 16 17:32:31][ <-> ] ssh_isakmp_update_responder_cookie: New IKE cookie [Sep 16 17:32:31][ <-> ] 00000000: 2530 77f2 f3c8 dbdd %0w..... [Sep 16 17:32:31][ <-> ] ikev2_fb_st_new_p1_connection_result: Accepting new Phase-1 negotiation: local=:500, remote=:49778 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fallback_negotiation_free: Fallback negotiation 1275800 has still 1 references [Sep 16 17:32:31][ <-> ] ssh_set_debug_gw_info: ssh_set_debug_gw_info: set gw debug info - local remote [Sep 16 17:32:31][ <-> ] ike_decode_packet: Start [Sep 16 17:32:31][ <-> ] ike_decode_packet: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd} / 00000000, nego = -1 [Sep 16 17:32:31][ <-> ] ike_decode_packet: first_payload_type:1. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:4. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:10. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:5. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:13. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:0. [Sep 16 17:32:31][ <-> ] ike_decode_payload_sa: Start [Sep 16 17:32:31][ <-> ] ike_decode_payload_sa: Found 1 proposals [Sep 16 17:32:31][ <-> ] ike_decode_payload_t: Start, # trans = 1 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 1 (0x0001), value = 7 (0x0007), size = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 14 (0x000e), value = 128 (0x0080), size = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 2 (0x0002), value = 2 (0x0002), size = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 3 (0x0003), value = 65001 (0xfde9), size = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 4 (0x0004), value = 2 (0x0002), size = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 11 (0x000b), value = 1 (0x0001), size = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute_size: decode_size B: type = 12 (0x000c), value = 28740 (0x7044), size = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 1 (0x0001), value = 7 (0x0007), len = 2, used_bytes = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 14 (0x000e), value = 128 (0x0080), len = 2, used_bytes = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 2 (0x0002), value = 2 (0x0002), len = 2, used_bytes = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 3 (0x0003), value = 65001 (0xfde9), len = 2, used_bytes = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 4 (0x0004), value = 2 (0x0002), len = 2, used_bytes = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 11 (0x000b), value = 1 (0x0001), len = 2, used_bytes = 4 [Sep 16 17:32:31][ <-> ] ssh_ike_decode_data_attribute: decode B: type = 12 (0x000c), value = 28740 (0x7044), len = 2, used_bytes = 4 [Sep 16 17:32:31][ <-> ] IKEv1 packet R(:500 <- :500): len= 400, mID=00000000, HDR, SA, Vid, Vid, Vid, Vid, KE, Nonce, ID, Vid [Sep 16 17:32:31][ <-> ] ike_state_step: Current state = Start sa negotiation R (2)/-1, exchange = 4, auth_method = any, Responder [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matched state = Start sa negotiation R (2) [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[0] = ike_st_i_vid [Sep 16 17:32:31][ <-> ] ike_st_i_vid: VID[0..16] = afcad713 68a1f1c9 ... [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 16, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:31][ <-> ] iked_pm_ike_received_vendor_id: Received vendor-id for RFC 3706 (Dead Peer Detection) [Sep 16 17:32:31][ <-> ] ike_st_i_vid: VID[0..8] = 09002689 dfd6b712 ... [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 8, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:31][ <-> ] ike_st_i_vid: VID[0..16] = 7d9419a6 5310ca6f ... [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 16, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_check_natt_vendor_id: NAT-T vendor id [draft-ietf-ipsec-nat-t-ike-03] [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:31][ <-> ] iked_pm_ike_received_vendor_id: Received vendor-id for draft-ietf-ipsec-nat-t-ike-03 [Sep 16 17:32:31][ <-> ] ike_st_i_vid: VID[0..16] = 90cb8091 3ebb696e ... [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 16, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_check_natt_vendor_id: NAT-T vendor id [draft-ietf-ipsec-nat-t-ike-02] [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:31][ <-> ] iked_pm_ike_received_vendor_id: Received vendor-id for draft-ietf-ipsec-nat-t-ike-02 [Sep 16 17:32:31][ <-> ] ike_st_i_vid: VID[0..17] = 4a4e5052 20495053 ... [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: Received vendor ID, length 17, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_vendor_id: FB; Calling v2 policy function vendor_id [Sep 16 17:32:31][ <-> ] iked_pm_ike_received_vendor_id: Received vendor-id for JNPR IPSec Client [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[1] = ike_st_i_id [Sep 16 17:32:31][ <-> ] ike_st_i_id: Start [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[2] = ike_st_i_sa_proposal [Sep 16 17:32:31][ <-> ] ike_st_i_sa_proposal: Start [Sep 16 17:32:31][ <-> ] ike_free_id_payload: Start, id type = 2 [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_select_sa: Select IKE SA policy call entered, IKE SA 1277000 (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_select_sa: Taking reference to fallback negotiation 1275800 (now 2 references) [Sep 16 17:32:31][ <-> ] ssh_set_thread_debug_info: ikev2_fb_isakmp_select_sa: set thread debug info - local 0x8f3bcac4 remote 0x28575b94neg 0x1275800 neg->ike_sa 0x1277000 ike_sa 0x0 [Sep 16 17:32:31][ <-> ] ike_state_step: Input function[2] = ike_st_i_sa_proposal asked retry later [Sep 16 17:32:31][ <-> ] ike_process_packet: No output packet, returning [Sep 16 17:32:31][ <-> ] ikev2_fb_st_select_ike_sa: FSM_SET_NEXT:ikev2_fb_st_select_ike_sa_finish [Sep 16 17:32:31][ <-> ] ikev2_fb_st_select_ike_sa: FB; Calling v2 policy function select_ike_sa [Sep 16 17:32:31][ <-> ] Parsing notification payload for local:, remote: IKEv1 [Sep 16 17:32:31][ <-> ] Search for a tunnel matching the IKE peers, local:, remote: IKEv1 [Sep 16 17:32:31][ <-> ] iked_pm_phase1_sa_cfg_lookup_by_addr: Address based phase 1 SA-CFG lookup failed for local:, remote: IKEv1 [Sep 16 17:32:31][ <-> ] iked_pm_phase1_sa_cfg_lookup_by_id called with id type 2 [Sep 16 17:32:31][ <-> ] ikev2_fb_idv2_to_idv1: Converting the IKEv2 payload ID IDa(type = fqdn (2), len = 15, value = dynvpn) to IKEv1 ID [Sep 16 17:32:31][ <-> ] ikev2_fb_idv2_to_idv1: IKEv2 payload ID converted to IKEv1 payload ID fqdn(any:0,[0..14]=dynvpn) [Sep 16 17:32:31][ <-> ] iked_pm_sa_cfg_lookup_by_id partial match type 2 [Sep 16 17:32:31][ <-> ] iked_pm_dynamic_gw_local_addr_based_lookup: called with local ip: [Sep 16 17:32:31][ <-> ] Not doing MM check since initiator=FALSE and exch_type=4 [Sep 16 17:32:31][ <-> ] dynamic gateway match unsuccessful: [Sep 16 17:32:31][ <-> ] iked_pm_ike_spd_select_ike_sa: Setting tunnel-event IKE gateway configuration lookup failed during negotiation for P1-SA 7353744 [Sep 16 17:32:31][ <-> ] iked_pm_ike_spd_select_ike_sa failed. rc 1, error_code: No proposal chosen [Sep 16 17:32:31][ <-> ] ikev2_fb_spd_select_sa_cb: IKEv2 SA select failed with error No proposal chosen (neg 1275800) [Sep 16 17:32:31][ <-> ] ike_isakmp_sa_reply: Start [Sep 16 17:32:31][ <-> ] ikev2_fallback_negotiation_free: Fallback negotiation 1275800 has still 1 references [Sep 16 17:32:31][ <-> ] ssh_set_debug_gw_info: ssh_set_debug_gw_info: set gw debug info - local remote [Sep 16 17:32:31][ <-> ] ike_state_restart_packet: Start, restart packet SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd}, nego = -1 [Sep 16 17:32:31][ <-> ] ike_state_step: Current state = Start sa negotiation R (2)/2, exchange = 4, auth_method = any, Responder [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matched state = Start sa negotiation R (2) [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[2] = ike_st_i_sa_proposal [Sep 16 17:32:31][ <-> ] ike_st_i_sa_proposal: Start [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[3] = ike_st_i_nonce [Sep 16 17:32:31][ <-> ] ike_st_i_nonce: Start, nonce[0..64] = c09e431a 2a238038 ... [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[4] = ike_st_i_cert [Sep 16 17:32:31][ <-> ] ike_st_i_cert: Start [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[5] = ike_st_i_hash_key [Sep 16 17:32:31][ <-> ] ike_st_i_hash_key: Start, no key_hash [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[6] = ike_st_i_ke [Sep 16 17:32:31][ <-> ] ike_st_i_ke: Ke[0..128] = 23aad369 ec0d4071 ... [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[7] = ike_st_i_cr [Sep 16 17:32:31][ <-> ] ike_st_i_cr: Start [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[8] = ike_st_i_status_n [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[9] = ike_st_i_private [Sep 16 17:32:31][ <-> ] ike_st_i_private: Start [Sep 16 17:32:31][ <-> ] ike_state_step: Calling output function[0] = ike_st_o_sa_values [Sep 16 17:32:31][ <-> ] ike_st_o_sa_values: Start [Sep 16 17:32:31][ <-> ] ike_state_step: Output function[0] = ike_st_o_sa_values failed [Sep 16 17:32:31][ <-> ] ike_packet_free: Start [Sep 16 17:32:31][ <-> ] ike_state_restart_packet: Error, send notify [Sep 16 17:32:31][ <-> ] ikev2_fb_negotiation_done_isakmp: Entered IKE error code No proposal chosen (14), IKE SA 1277000 (neg 1275800) [Sep 16 17:32:31][ <-> ] :500 (Responder) <-> :49778 { c22e9dda 912ae90f - 253077f2 f3c8dbdd [-1] / 0x00000000 } Aggr; Error = No proposal chosen (14) [Sep 16 17:32:31][ <-> ] ike_alloc_negotiation: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd} [Sep 16 17:32:31][ <-> ] ike_alloc_negotiation: Found slot 0, max 1 [Sep 16 17:32:31][ <-> ] ike_init_info_exchange: New informational negotiation message_id = 4d45904c initialized using slot 0 [Sep 16 17:32:31][ <-> ] ike_init_info_exchange: Created random message id = 4d45904c [Sep 16 17:32:31][ <-> ] ike_init_info_exchange: No phase 1 done, use only N or D payload [Sep 16 17:32:31][ <-> ] ssh_ike_encode_data_attribute: encode B: type = 12 (0x000c), len = 2, value = 0001 [Sep 16 17:32:31][ <-> ] ssh_ike_encode_data_attribute: encode V: type = 6 (0x0006), len = 34 (0x0022), value = 436f756c ... [Sep 16 17:32:31][ <-> ] ssh_ike_encode_data_attribute: encode B: type = 8 (0x0008), len = 2, value = 0000 [Sep 16 17:32:31][ <-> ] ike_encode_packet: Start, SA = { 0xc22e9dda 912ae90f - 253077f2 f3c8dbdd } / 4d45904c, nego = 0 [Sep 16 17:32:31][ <-> ] ike_encode_packet: Payload length = 74 [Sep 16 17:32:31][ <-> ] ike_encode_packet: Payload length = 102 [Sep 16 17:32:31][ <-> ] IKEv1 packet S(:500 -> :500): len= 102, mID=4d45904c, HDR, N(NO_PROPOSAL_CHOSEN) [Sep 16 17:32:31][ <-> ] ike_encode_packet: Final length = 102 [Sep 16 17:32:31][ <-> ] ike_send_notify: Sending notification to :49778 [Sep 16 17:32:31][ <-> ] ike_send_packet: Start, send SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd}, nego = 0, dst = :49778 [Sep 16 17:32:31][ <-> ] ike_packet_free: Start [Sep 16 17:32:31][ <-> ] ike_delete_negotiation: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd}, nego = 0 [Sep 16 17:32:31][ <-> ] ike_free_negotiation_info: Start, nego = 0 [Sep 16 17:32:31][ <-> ] ike_free_negotiation: Start, nego = 0 [Sep 16 17:32:31][ <-> ] ikev2_fb_phase_ii_sa_freed: Phase-II free Entered [Sep 16 17:32:31][ <-> ] ikev2_fb_p1_negotiation_wait_sa_done: Phase-I negotiation is now done (neg 1275800) [Sep 16 17:32:31][ <-> ] ikev2_fb_p1_negotiation_wait_sa_done: FB; Calling v2 policy function ike_sa_done [Sep 16 17:32:31][ <-> ] IKE negotiation fail for local:, remote: IKEv1 with status: No proposal chosen [Sep 16 17:32:31][ <-> ] iked_delete_slot_table_entry Slot released msg_id<0> cookie [Sep 16 17:32:31][ <-> ] iked_tunnel_event_add_event_in_gw: tunnel-event IKE gateway configuration lookup failed during negotiation count incremented to 396 [Sep 16 17:32:31][ <-> ] IKEv1 Error : No proposal chosen [Sep 16 17:32:31][ <-> ] ikev2_fb_p1_negotiation_destructor: Freeing fallback negotiation context [Sep 16 17:32:31][ <-> ] ikev2_fallback_negotiation_free: Freeing fallback negotiation 1275800 [Sep 16 17:32:31][ <-> ] ikev2_free_exchange_data: Freeing exchange data from SA 1277000, ED 1279028 (1) [Sep 16 17:32:31][ <-> ] ikev2_free_exchange_data_ipsec: Freeing IPsec exchange data from SA 1277000 [Sep 16 17:32:31][ <-> ] ikev2_free_exchange_data_ipsec: Successfully freed IPsec exchange data from SA 1277000 [Sep 16 17:32:31][ <-> ] ikev2_free_exchange_data_ike: Freeing IKE exchange data from SA 1277000 [Sep 16 17:32:31][ <-> ] ikev2_free_exchange_data_ike: Successfully freed IKE exchange data from SA 1277000 [Sep 16 17:32:31][ <-> ] ikev2_free_exchange_data: Notify call: exchange_data_free [Sep 16 17:32:31][ <-> ] Freeing P2 Ed for sa-cfg N/A [Sep 16 17:32:31][ <-> ] P2_ED doesn't have p1_sa pointer or peer-entry. Not calling iked_pm_reset_p2_ed_in_peer_entry_sacfgs [Sep 16 17:32:31][ <-> ] iked_pm_ike_exchange_data_free: Successfully removed pm_ed 1273a00 from list for sa_cfg N/A [Sep 16 17:32:31][ <-> ] ikev2_free_exchange_data: Successfully freed exchange data from SA 1277000 [Sep 16 17:32:31][ <-> ] ikev2_fallback_negotiation_free: Freeing reference to IKE SA 1277000 to ref count 1 [Sep 16 17:32:31][ <-> ] ssh_ikev2_ike_sa_free: Notify call: ike_sa_free_ref [Sep 16 17:32:31][ <-> ] Freeing reference to P1 SA 7353744 to ref count 1 [Sep 16 17:32:31][ <-> ] *** Processing received packet from :49778 to :0, VR 0, packet len: 40, on Interface: ge-0/0/0.0 [Sep 16 17:32:31][ <-> ] ---------> Received from :49778 to :0, VR 0, length 40 on IF ge-0/0/0.0 [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_start: [11ddc00/0] ******** Processing received ************ [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_start: FSM_SET_NEXT:ikev2_packet_st_input_v1_get_sa [Sep 16 17:32:31][ <-> ] ike_sa_find: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd } [Sep 16 17:32:31][ <-> ] ike_sa_find: Found SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd } [Sep 16 17:32:31][ <-> ] Found IKEv1 SA [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_v1_get_sa: [11ddc00/deadbeee] Packet to existing v1 SA [Sep 16 17:32:31][ <-> ] ikev2_packet_st_input_v1_get_sa: FSM_SET_NEXT:ikev2_packet_v1_start [Sep 16 17:32:31][ <-> ] ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library [Sep 16 17:32:31][ <-> ] ike_udp_callback_common: Packet from :49778, use_natt=0 data[0..40] = c22e9dda 912ae90f 253077f2 f3c8dbdd ... [Sep 16 17:32:31][ <-> ] ike_get_sa: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd } / 52edae66, remote = :49778 [Sep 16 17:32:31][ <-> ] ike_sa_find: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd } [Sep 16 17:32:31][ <-> ] ike_sa_find: Found SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd } [Sep 16 17:32:31][ <-> ] ike_alloc_negotiation: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd} [Sep 16 17:32:31][ <-> ] ike_alloc_negotiation: Found slot 0, max 1 [Sep 16 17:32:31][ <-> ] ike_udp_callback_common: New informational negotiation message_id = 52edae66 initialized using slot 0 [Sep 16 17:32:31][ <-> ] ike_udp_callback_common: Old negotiation message_id = 52edae66, slot 0 [Sep 16 17:32:31][ <-> ] ike_decode_packet: Start [Sep 16 17:32:31][ <-> ] ike_decode_packet: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd} / 52edae66, nego = 0 [Sep 16 17:32:31][ <-> ] ike_decode_packet: first_payload_type:11. [Sep 16 17:32:31][ <-> ] ike_decode_packet: next_payload_type:0. [Sep 16 17:32:31][ <-> ] IKEv1 packet R(:500 <- :500): len= 40, mID=52edae66, HDR, N(NO_PROPOSAL_CHOSEN) [Sep 16 17:32:31][ <-> ] ike_state_step: Current state = Done (53)/-1, exchange = 5, auth_method = any, Responder [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 3, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 0, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 3, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 2, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 4, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM final R (8), xchg = 2, auth = 0, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM done I (9), xchg = 2, auth = 0, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM final I (12), xchg = 4, auth = 0, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM done R (13), xchg = 4, auth = 0, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 2, fields = 0001 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM SA R (4), xchg = 2, auth = 2, fields = 0012 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM KE I (5), xchg = 2, auth = 2, fields = 0012 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM KE R (6), xchg = 2, auth = 2, fields = 000c / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM final I (7), xchg = 2, auth = 2, fields = 000c / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM SA I (10), xchg = 4, auth = 2, fields = 001f / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 2, fields = 0008 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 2, fields = 0020 / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 3, fields = 0001 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM SA R (4), xchg = 2, auth = 3, fields = 0016 / 06e0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM KE I (5), xchg = 2, auth = 3, fields = 0016 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM KE R (6), xchg = 2, auth = 3, fields = 0020 / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM final I (7), xchg = 2, auth = 3, fields = 0020 / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM SA I (10), xchg = 4, auth = 3, fields = 0037 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 3, fields = 0020 / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 4, fields = 0001 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM SA R (4), xchg = 2, auth = 4, fields = 0012 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM KE I (5), xchg = 2, auth = 4, fields = 0012 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM KE R (6), xchg = 2, auth = 4, fields = 0024 / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM final I (7), xchg = 2, auth = 4, fields = 0024 / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM SA I (10), xchg = 4, auth = 4, fields = 0037 / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = AM SA R (11), xchg = 4, auth = 4, fields = 0020 / 0680 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = MM SA I (3), xchg = 2, auth = 0, fields = 0001 / 06c0 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start QM I (14), xchg = 32, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start QM R (15), xchg = 32, auth = 1, fields = 0031 / 0206 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = QM HASH SA I (16), xchg = 32, auth = 1, fields = 0031 / 0206 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = QM HASH SA R (17), xchg = 32, auth = 1, fields = 0020 / 0200 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = QM HASH I (18), xchg = 32, auth = 1, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = QM done R (19), xchg = 32, auth = 1, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start NGM I (20), xchg = 33, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start NGM R (21), xchg = 33, auth = 1, fields = 0021 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = NGM HASH SA I (22), xchg = 33, auth = 1, fields = 0021 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = NGM HASH SA R (23), xchg = 33, auth = 1, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = NGM done I (24), xchg = 33, auth = 1, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start CFG I (25), xchg = 6, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start CFG R (26), xchg = 6, auth = 1, fields = 0820 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR I (27), xchg = 6, auth = 1, fields = 0820 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR SA R (28), xchg = 6, auth = 1, fields = 0820 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR SA R (28), xchg = 6, auth = 1, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = CFG done I (29), xchg = 6, auth = 1, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start CFG I (25), xchg = 6, auth = 0, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start CFG R (26), xchg = 6, auth = 0, fields = 0800 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR I (27), xchg = 6, auth = 0, fields = 0800 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = CFG HASH ATTR SA R (28), xchg = 6, auth = 0, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = CFG done I (29), xchg = 6, auth = 0, fields = ffff / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start GDOI I (30), xchg = 32, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Start GDOI R (31), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = GDOI ID I (32), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = GDOI SA R (33), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = GDOI HASH3 I (34), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = GDOI KD R (35), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = GDOI DONE I (36), xchg = 32, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (37), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (38), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (39), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (40), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (41), xchg = 33, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (42), xchg = 240, auth = 1, fields = 0000 / 0000 [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (43), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (44), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (45), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (46), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (47), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (48), xchg = 240, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (49), xchg = 241, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (50), xchg = 241, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (51), xchg = 241, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = unknown (52), xchg = 241, auth = 1, fields = ffff / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Any (0), xchg = 256, auth = 1, fields = 0220 / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Done (53), xchg = 256, auth = 1, fields = 0120 / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matching with state = Any (0), xchg = 256, auth = 0, fields = 0200 / ffff [Sep 16 17:32:31][ <-> ] ike_state_step: Matched state = Any (0) [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[0] = ike_st_i_n [Sep 16 17:32:31][ <-> ] ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..0] = 00000000 00000000 ..., data[0..0] = 00000000 00000000 ... [Sep 16 17:32:31][ <-> ] :500 (Responder) <-> :49778 { c22e9dda 912ae90f - 253077f2 f3c8dbdd [0] / 0x52edae66 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it [Sep 16 17:32:31][ <-> ] ike_state_step: Calling input function[1] = ike_st_i_private [Sep 16 17:32:31][ <-> ] ike_st_i_private: Start [Sep 16 17:32:31][ <-> ] ike_state_step: Calling output function[0] = ike_st_o_n_done [Sep 16 17:32:31][ <-> ] ike_packet_free: Start [Sep 16 17:32:31][ <-> ] ike_state_step: All done, new state = Done (53) [Sep 16 17:32:31][ <-> ] ike_process_packet: Connected, sending notify [Sep 16 17:32:31][ <-> ] ike_send_notify: Connected, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd}, nego = 0 [Sep 16 17:32:31][ <-> ] ike_delete_negotiation: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd}, nego = 0 [Sep 16 17:32:31][ <-> ] ike_free_negotiation_info: Start, nego = 0 [Sep 16 17:32:31][ <-> ] ike_free_negotiation: Start, nego = 0 [Sep 16 17:32:31][ <-> ] ike_packet_free: Start [Sep 16 17:32:31][ <-> ] ikev2_fb_phase_ii_sa_freed: Phase-II free Entered [Sep 16 17:32:31][ <-> ] ikev2_packet_destroy: [11ddc00/deadbeee] Destructor [Sep 16 17:32:31][ <-> ] ikev2_packet_free: [11ddc00/deadbeee] Freeing [Sep 16 17:32:31][ <-> ] ssh_set_debug_gw_info: ssh_set_debug_gw_info: set gw debug info - local remote [Sep 16 17:32:31][ <-> ] ike_remove_callback: Start, delete SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd}, nego = -1 [Sep 16 17:32:31][ <-> ] ike_delete_negotiation: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd}, nego = -1 [Sep 16 17:32:31][ <-> ] ssh_ike_tunnel_table_entry_delete: Deleting tunnel_id: 0 from IKE tunnel table [Sep 16 17:32:31][ <-> ] ssh_ike_tunnel_table_entry_delete: The tunnel id: 0 doesn't exist in IKE tunnel table [Sep 16 17:32:31][ <-> ] ike_sa_delete: Start, SA = { c22e9dda 912ae90f - 253077f2 f3c8dbdd } [Sep 16 17:32:31][ <-> ] ike_free_negotiation_isakmp: Start, nego = -1 [Sep 16 17:32:31][ <-> ] ike_free_negotiation: Start, nego = -1 [Sep 16 17:32:31][ <-> ] ike_packet_free: Start [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_sa_freed: Received notification from the ISAKMP library that the IKE SA 1277000 is freed [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_sa_freed: FB; Calling v2 policy function ike_sa_delete [Sep 16 17:32:31][ <-> ] ikev2_fb_isakmp_sa_freed: Notify call: ike_sa_delete [Sep 16 17:32:31][ <-> ] IKE SA delete called for p1 sa 7353744 (ref cnt 1) local:, remote:, IKEv1 [Sep 16 17:32:31][ <-> ] P1 SA 7353744 stop timer. timer duration 30, reason 1. [Sep 16 17:32:31][ <-> ] Freeing reference to P1 SA 7353744 to ref count 0 [Sep 16 17:32:31][ <-> ] iked_pm_p1_sa_destroy: Decremented active p1 negotiations.Current active p1 negotiations 0 [Sep 16 17:32:31][ <-> ] iked_pm_p1_sa_destroy: p1 sa 7353744 (ref cnt 0), waiting_for_del 0x0 [Sep 16 17:32:31][ <-> ] Deleting p1 sa (7353744) node from IKE p1 SA P-tree [Sep 16 17:32:31][ <-> ] The tunnel id: 7353744 doesn't exist in P1 SA P-tree [Sep 16 17:32:31][ <-> ] ikev2_transmit_window_uninit: Uninitialising transmit window 1277180 [Sep 16 17:32:31][ <-> ] ikev2_transmit_window_flush: Transmit window 1277180: Flushing. [Sep 16 17:32:31][ <-> ] ikev2_receive_window_uninit: Uninitialising receive window 1277190 [Sep 16 17:32:31][ <-> ] ike_free_id_payload: Start, id type = 2 [Sep 16 17:32:31][ <-> ] ike_free_sa: Start