Aug 9 11:37:17 In iked_rts_async_ipsec_msg_handler Aug 9 11:37:18 Received IKE Trigger message with local_gw_addr = 92.X.X.X remote_gw_addr = 94.Y.Y.Y Aug 9 11:37:18 In iked_async_ike_trigger_msg_handler; Tunnel = 2 Aug 9 11:37:18 Triggering the IKE negotiation .... Aug 9 11:37:18 kmd_pm_trigger_callback Aug 9 11:37:18 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:37:18 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:37:18 kmd_pm_ike_start_p1 Aug 9 11:37:18 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:18 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:37:18 ike_sa_allocate: Start, SA = { 54f3cbfb 54471d6d - 00000000 00000000 } Aug 9 11:37:18 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:37:18 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126263 to IKE tunnel table Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:37:18 jnp_ike_connect: SA = { 54f3cbfb 54471d6d - 00000000 00000000}, nego = -1 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:37:18 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:37:18 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:37:18 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:37:18 ike_st_o_sa_proposal: Start Aug 9 11:37:18 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:37:18 NAT is enabled Aug 9 11:37:18 Advertizing DPD capability Aug 9 11:37:18 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:37:18 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:37:18 ike_st_o_private: Start Aug 9 11:37:18 remote end does not support NAT-T Aug 9 11:37:18 ike_policy_reply_private_payload_out: Start Aug 9 11:37:18 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:37:18 ike_encode_packet: Start, SA = { 0x54f3cbfb 54471d6d - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0x54f3cbfb 54471d6d Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:37:18 ike_encode_packet: Payload length = 96 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:37:18 ike_encode_packet: Payload length = 20 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:37:18 ike_encode_packet: Payload length = 32 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:37:18 ike_encode_packet: Payload length = 20 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:37:18 ike_encode_packet: Payload length = 20 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:37:18 ike_encode_packet: Payload length = 20 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:37:18 ike_encode_packet: Payload length = 20 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:37:18 ike_encode_packet: Payload length = 20 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:37:18 ike_encode_packet: Payload length = 20 Aug 9 11:37:18 ike_encode_packet: Packet length = 296 Aug 9 11:37:18 ike_encode_packet: Final length = 296 Aug 9 11:37:18 ike_send_packet: Start, send SA = { 54f3cbfb 54471d6d - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:37:18 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:37:18 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:18 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:37:18 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:37:18 Looking up instance for server: 92.X.X.X Aug 9 11:37:18 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = 54f3cbfb 54471d6d 87d62fbd 9da4614f ... Aug 9 11:37:18 ike_get_sa: Start, SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f } / fe8d052d, remote = 94.Y.Y.Y:500 Aug 9 11:37:18 ike_sa_find: Not found SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f } Aug 9 11:37:18 ike_sa_find_half: Found half SA = { 54f3cbfb 54471d6d - 00000000 00000000 } Aug 9 11:37:18 ike_get_sa: We are intiator, first response packet Aug 9 11:37:18 ike_sa_upgrade: Start, SA = { 54f3cbfb 54471d6d - 00000000 00000000 } -> { ... - 87d62fbd 9da4614f } Aug 9 11:37:18 ike_alloc_negotiation: Start, SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f} Aug 9 11:37:18 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:37:18 ike_udp_callback_common: New informational negotiation message_id = fe8d052d initialized using slot 0 Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; New informational negotiation Aug 9 11:37:18 ike_udp_callback_common: Old negotiation message_id = fe8d052d, slot 0 Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Packet to old negotiation Aug 9 11:37:18 ike_decode_packet: Start Aug 9 11:37:18 ike_decode_packet: Start, SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f} / fe8d052d, nego = 0 Aug 9 11:37:18 ike_decode_packet: first_payload_type:11. Aug 9 11:37:18 ike_decode_packet: next_payload_type:0. Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0x54f3cbfb 54471d6d 87d62fbd 9da4614f Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:37:18 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:37:18 ike_state_step: Matched state = Any (0) Aug 9 11:37:18 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:37:18 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = 54f3cbfb 54471d6d ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Notification data has attribute list Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Notify message version = 1 Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Error text = Could not find acceptable proposal Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Offending message id = 0x00000000 Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:37:18 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:37:18 ike_st_i_private: Start Aug 9 11:37:18 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:37:18 ike_state_step: All done, new state = Done (42) Aug 9 11:37:18 ike_process_packet: Connected, sending notify Aug 9 11:37:18 ike_send_notify: Connected, SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f}, nego = 0 Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Connected Aug 9 11:37:18 ike_delete_negotiation: Start, SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f}, nego = 0 Aug 9 11:37:18 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [0] / 0xfe8d052d } Info; Deleting negotiation sa Aug 9 11:37:18 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:37:18 ike_free_negotiation: Start, nego = 0 Aug 9 11:37:18 Phase-2 freeing PMData 0 Aug 9 11:37:18 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:37:18 ike_remove_callback: Start, delete SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f}, nego = -1 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:37:18 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:18 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:18 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:37:18 Completing packet Aug 9 11:37:18 ike_delete_negotiation: Start, SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f}, nego = -1 Aug 9 11:37:18 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 54f3cbfb 54471d6d - 87d62fbd 9da4614f [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:37:18 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126263 from IKE tunnel table Aug 9 11:37:18 ike_sa_delete: Start, SA = { 54f3cbfb 54471d6d - 87d62fbd 9da4614f } Aug 9 11:37:18 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:37:18 ike_free_negotiation: Start, nego = -1 Aug 9 11:37:18 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:18 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:37:18 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:37:18 Created Peer patricia key Aug 9 11:37:18 Peer structure entry Not FOUND Aug 9 11:37:18 error not found peer entry for p1 sa Aug 9 11:37:18 P1 freeing PMdata ad3800 Aug 9 11:37:18 ike_free_id_payload: Start, id type = 1 Aug 9 11:37:18 ike_free_sa: Start Aug 9 11:37:32 In iked_rts_async_ipsec_msg_handler Aug 9 11:37:33 Received IKE Trigger message with local_gw_addr = 92.X.X.X remote_gw_addr = 94.Y.Y.Y Aug 9 11:37:33 In iked_async_ike_trigger_msg_handler; Tunnel = 2 Aug 9 11:37:33 Triggering the IKE negotiation .... Aug 9 11:37:33 kmd_pm_trigger_callback Aug 9 11:37:33 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:37:33 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:37:33 kmd_pm_ike_start_p1 Aug 9 11:37:33 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:33 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:37:33 ike_sa_allocate: Start, SA = { 7d9528b6 66c41d66 - 00000000 00000000 } Aug 9 11:37:33 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:37:33 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126264 to IKE tunnel table Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:37:33 jnp_ike_connect: SA = { 7d9528b6 66c41d66 - 00000000 00000000}, nego = -1 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:37:33 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:37:33 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:37:33 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:37:33 ike_st_o_sa_proposal: Start Aug 9 11:37:33 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:37:33 NAT is enabled Aug 9 11:37:33 Advertizing DPD capability Aug 9 11:37:33 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:37:33 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:37:33 ike_st_o_private: Start Aug 9 11:37:33 remote end does not support NAT-T Aug 9 11:37:33 ike_policy_reply_private_payload_out: Start Aug 9 11:37:33 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:37:33 ike_encode_packet: Start, SA = { 0x7d9528b6 66c41d66 - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0x7d9528b6 66c41d66 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:37:33 ike_encode_packet: Payload length = 96 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:37:33 ike_encode_packet: Payload length = 20 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:37:33 ike_encode_packet: Payload length = 32 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:37:33 ike_encode_packet: Payload length = 20 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:37:33 ike_encode_packet: Payload length = 20 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:37:33 ike_encode_packet: Payload length = 20 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:37:33 ike_encode_packet: Payload length = 20 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:37:33 ike_encode_packet: Payload length = 20 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:37:33 ike_encode_packet: Payload length = 20 Aug 9 11:37:33 ike_encode_packet: Packet length = 296 Aug 9 11:37:33 ike_encode_packet: Final length = 296 Aug 9 11:37:33 ike_send_packet: Start, send SA = { 7d9528b6 66c41d66 - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:37:33 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:37:33 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:33 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:37:33 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:37:33 Looking up instance for server: 92.X.X.X Aug 9 11:37:33 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = 7d9528b6 66c41d66 5235b81e 9cadc8b0 ... Aug 9 11:37:33 ike_get_sa: Start, SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 } / c88ddd0d, remote = 94.Y.Y.Y:500 Aug 9 11:37:33 ike_sa_find: Not found SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 } Aug 9 11:37:33 ike_sa_find_half: Found half SA = { 7d9528b6 66c41d66 - 00000000 00000000 } Aug 9 11:37:33 ike_get_sa: We are intiator, first response packet Aug 9 11:37:33 ike_sa_upgrade: Start, SA = { 7d9528b6 66c41d66 - 00000000 00000000 } -> { ... - 5235b81e 9cadc8b0 } Aug 9 11:37:33 ike_alloc_negotiation: Start, SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0} Aug 9 11:37:33 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:37:33 ike_udp_callback_common: New informational negotiation message_id = c88ddd0d initialized using slot 0 Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; New informational negotiation Aug 9 11:37:33 ike_udp_callback_common: Old negotiation message_id = c88ddd0d, slot 0 Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Packet to old negotiation Aug 9 11:37:33 ike_decode_packet: Start Aug 9 11:37:33 ike_decode_packet: Start, SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0} / c88ddd0d, nego = 0 Aug 9 11:37:33 ike_decode_packet: first_payload_type:11. Aug 9 11:37:33 ike_decode_packet: next_payload_type:0. Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0x7d9528b6 66c41d66 5235b81e 9cadc8b0 Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:37:33 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:37:33 ike_state_step: Matched state = Any (0) Aug 9 11:37:33 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:37:33 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = 7d9528b6 66c41d66 ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Notification data has attribute list Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Notify message version = 1 Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Error text = Could not find acceptable proposal Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Offending message id = 0x00000000 Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:37:33 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:37:33 ike_st_i_private: Start Aug 9 11:37:33 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:37:33 ike_state_step: All done, new state = Done (42) Aug 9 11:37:33 ike_process_packet: Connected, sending notify Aug 9 11:37:33 ike_send_notify: Connected, SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0}, nego = 0 Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Connected Aug 9 11:37:33 ike_delete_negotiation: Start, SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0}, nego = 0 Aug 9 11:37:33 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [0] / 0xc88ddd0d } Info; Deleting negotiation sa Aug 9 11:37:33 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:37:33 ike_free_negotiation: Start, nego = 0 Aug 9 11:37:33 Phase-2 freeing PMData 0 Aug 9 11:37:33 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:37:33 ike_remove_callback: Start, delete SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0}, nego = -1 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:37:33 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:33 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:33 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:37:33 Completing packet Aug 9 11:37:33 ike_delete_negotiation: Start, SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0}, nego = -1 Aug 9 11:37:33 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:37:33 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126264 from IKE tunnel table Aug 9 11:37:33 ike_sa_delete: Start, SA = { 7d9528b6 66c41d66 - 5235b81e 9cadc8b0 } Aug 9 11:37:33 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:37:33 ike_free_negotiation: Start, nego = -1 Aug 9 11:37:33 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:33 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:37:33 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:37:33 Created Peer patricia key Aug 9 11:37:33 Peer structure entry Not FOUND Aug 9 11:37:33 error not found peer entry for p1 sa Aug 9 11:37:33 P1 freeing PMdata ad3800 Aug 9 11:37:33 ike_free_id_payload: Start, id type = 1 Aug 9 11:37:33 ike_free_sa: Start Aug 9 11:37:40 Triggering all tunnels Aug 9 11:37:40 kmd_pm_trigger_callback Aug 9 11:37:40 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:37:40 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:37:40 kmd_pm_ike_start_p1 Aug 9 11:37:40 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:40 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:37:40 ike_sa_allocate: Start, SA = { d10eb7e8 6508c381 - 00000000 00000000 } Aug 9 11:37:40 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:37:40 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126265 to IKE tunnel table Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:37:40 jnp_ike_connect: SA = { d10eb7e8 6508c381 - 00000000 00000000}, nego = -1 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:37:40 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:37:40 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:37:40 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:37:40 ike_st_o_sa_proposal: Start Aug 9 11:37:40 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:37:40 NAT is enabled Aug 9 11:37:40 Advertizing DPD capability Aug 9 11:37:40 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:37:40 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:37:40 ike_st_o_private: Start Aug 9 11:37:40 remote end does not support NAT-T Aug 9 11:37:40 ike_policy_reply_private_payload_out: Start Aug 9 11:37:40 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:37:40 ike_encode_packet: Start, SA = { 0xd10eb7e8 6508c381 - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0xd10eb7e8 6508c381 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:37:40 ike_encode_packet: Payload length = 96 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:37:40 ike_encode_packet: Payload length = 20 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:37:40 ike_encode_packet: Payload length = 32 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:37:40 ike_encode_packet: Payload length = 20 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:37:40 ike_encode_packet: Payload length = 20 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:37:40 ike_encode_packet: Payload length = 20 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:37:40 ike_encode_packet: Payload length = 20 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:37:40 ike_encode_packet: Payload length = 20 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:37:40 ike_encode_packet: Payload length = 20 Aug 9 11:37:40 ike_encode_packet: Packet length = 296 Aug 9 11:37:40 ike_encode_packet: Final length = 296 Aug 9 11:37:40 ike_send_packet: Start, send SA = { d10eb7e8 6508c381 - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:37:40 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:37:40 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:40 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:37:40 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:37:40 Looking up instance for server: 92.X.X.X Aug 9 11:37:40 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = d10eb7e8 6508c381 46878422 dc0f22e7 ... Aug 9 11:37:40 ike_get_sa: Start, SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7 } / dc4c61f8, remote = 94.Y.Y.Y:500 Aug 9 11:37:40 ike_sa_find: Not found SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7 } Aug 9 11:37:40 ike_sa_find_half: Found half SA = { d10eb7e8 6508c381 - 00000000 00000000 } Aug 9 11:37:40 ike_get_sa: We are intiator, first response packet Aug 9 11:37:40 ike_sa_upgrade: Start, SA = { d10eb7e8 6508c381 - 00000000 00000000 } -> { ... - 46878422 dc0f22e7 } Aug 9 11:37:40 ike_alloc_negotiation: Start, SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7} Aug 9 11:37:40 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:37:40 ike_udp_callback_common: New informational negotiation message_id = dc4c61f8 initialized using slot 0 Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; New informational negotiation Aug 9 11:37:40 ike_udp_callback_common: Old negotiation message_id = dc4c61f8, slot 0 Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Packet to old negotiation Aug 9 11:37:40 ike_decode_packet: Start Aug 9 11:37:40 ike_decode_packet: Start, SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7} / dc4c61f8, nego = 0 Aug 9 11:37:40 ike_decode_packet: first_payload_type:11. Aug 9 11:37:40 ike_decode_packet: next_payload_type:0. Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0xd10eb7e8 6508c381 46878422 dc0f22e7 Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:37:40 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:37:40 ike_state_step: Matched state = Any (0) Aug 9 11:37:40 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:37:40 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = d10eb7e8 6508c381 ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Notification data has attribute list Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Notify message version = 1 Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Error text = Could not find acceptable proposal Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Offending message id = 0x00000000 Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:37:40 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:37:40 ike_st_i_private: Start Aug 9 11:37:40 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:37:40 ike_state_step: All done, new state = Done (42) Aug 9 11:37:40 ike_process_packet: Connected, sending notify Aug 9 11:37:40 ike_send_notify: Connected, SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7}, nego = 0 Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Connected Aug 9 11:37:40 ike_delete_negotiation: Start, SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7}, nego = 0 Aug 9 11:37:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [0] / 0xdc4c61f8 } Info; Deleting negotiation sa Aug 9 11:37:40 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:37:40 ike_free_negotiation: Start, nego = 0 Aug 9 11:37:40 Phase-2 freeing PMData 0 Aug 9 11:37:40 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:37:40 ike_remove_callback: Start, delete SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7}, nego = -1 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:37:40 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:40 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:40 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:37:40 Completing packet Aug 9 11:37:40 ike_delete_negotiation: Start, SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7}, nego = -1 Aug 9 11:37:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { d10eb7e8 6508c381 - 46878422 dc0f22e7 [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:37:40 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126265 from IKE tunnel table Aug 9 11:37:40 ike_sa_delete: Start, SA = { d10eb7e8 6508c381 - 46878422 dc0f22e7 } Aug 9 11:37:40 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:37:40 ike_free_negotiation: Start, nego = -1 Aug 9 11:37:40 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:40 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:37:40 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:37:40 Created Peer patricia key Aug 9 11:37:40 Peer structure entry Not FOUND Aug 9 11:37:40 error not found peer entry for p1 sa Aug 9 11:37:40 P1 freeing PMdata ad3800 Aug 9 11:37:40 ike_free_id_payload: Start, id type = 1 Aug 9 11:37:40 ike_free_sa: Start Aug 9 11:37:47 In iked_rts_async_ipsec_msg_handler Aug 9 11:37:47 Received IKE Trigger message with local_gw_addr = 92.X.X.X remote_gw_addr = 94.Y.Y.Y Aug 9 11:37:47 In iked_async_ike_trigger_msg_handler; Tunnel = 2 Aug 9 11:37:47 Triggering the IKE negotiation .... Aug 9 11:37:47 kmd_pm_trigger_callback Aug 9 11:37:47 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:37:47 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:37:47 kmd_pm_ike_start_p1 Aug 9 11:37:47 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:47 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:37:47 ike_sa_allocate: Start, SA = { 49f3a689 9bc0b179 - 00000000 00000000 } Aug 9 11:37:47 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:37:47 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126266 to IKE tunnel table Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:37:47 jnp_ike_connect: SA = { 49f3a689 9bc0b179 - 00000000 00000000}, nego = -1 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:37:47 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:37:47 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:37:47 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:37:47 ike_st_o_sa_proposal: Start Aug 9 11:37:47 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:37:47 NAT is enabled Aug 9 11:37:47 Advertizing DPD capability Aug 9 11:37:47 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:37:47 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:37:47 ike_st_o_private: Start Aug 9 11:37:47 remote end does not support NAT-T Aug 9 11:37:47 ike_policy_reply_private_payload_out: Start Aug 9 11:37:47 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:37:47 ike_encode_packet: Start, SA = { 0x49f3a689 9bc0b179 - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0x49f3a689 9bc0b179 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:37:47 ike_encode_packet: Payload length = 96 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:37:47 ike_encode_packet: Payload length = 20 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:37:47 ike_encode_packet: Payload length = 32 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:37:47 ike_encode_packet: Payload length = 20 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:37:47 ike_encode_packet: Payload length = 20 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:37:47 ike_encode_packet: Payload length = 20 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:37:47 ike_encode_packet: Payload length = 20 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:37:47 ike_encode_packet: Payload length = 20 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:37:47 ike_encode_packet: Payload length = 20 Aug 9 11:37:47 ike_encode_packet: Packet length = 296 Aug 9 11:37:47 ike_encode_packet: Final length = 296 Aug 9 11:37:47 ike_send_packet: Start, send SA = { 49f3a689 9bc0b179 - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:37:47 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:37:47 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:47 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:37:47 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:37:47 Looking up instance for server: 92.X.X.X Aug 9 11:37:47 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = 49f3a689 9bc0b179 e1184972 7fadb4de ... Aug 9 11:37:47 ike_get_sa: Start, SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de } / b18729ee, remote = 94.Y.Y.Y:500 Aug 9 11:37:47 ike_sa_find: Not found SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de } Aug 9 11:37:47 ike_sa_find_half: Found half SA = { 49f3a689 9bc0b179 - 00000000 00000000 } Aug 9 11:37:47 ike_get_sa: We are intiator, first response packet Aug 9 11:37:47 ike_sa_upgrade: Start, SA = { 49f3a689 9bc0b179 - 00000000 00000000 } -> { ... - e1184972 7fadb4de } Aug 9 11:37:47 ike_alloc_negotiation: Start, SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de} Aug 9 11:37:47 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:37:47 ike_udp_callback_common: New informational negotiation message_id = b18729ee initialized using slot 0 Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; New informational negotiation Aug 9 11:37:47 ike_udp_callback_common: Old negotiation message_id = b18729ee, slot 0 Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Packet to old negotiation Aug 9 11:37:47 ike_decode_packet: Start Aug 9 11:37:47 ike_decode_packet: Start, SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de} / b18729ee, nego = 0 Aug 9 11:37:47 ike_decode_packet: first_payload_type:11. Aug 9 11:37:47 ike_decode_packet: next_payload_type:0. Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0x49f3a689 9bc0b179 e1184972 7fadb4de Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:37:47 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:37:47 ike_state_step: Matched state = Any (0) Aug 9 11:37:47 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:37:47 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = 49f3a689 9bc0b179 ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Notification data has attribute list Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Notify message version = 1 Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Error text = Could not find acceptable proposal Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Offending message id = 0x00000000 Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:37:47 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:37:47 ike_st_i_private: Start Aug 9 11:37:47 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:37:47 ike_state_step: All done, new state = Done (42) Aug 9 11:37:47 ike_process_packet: Connected, sending notify Aug 9 11:37:47 ike_send_notify: Connected, SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de}, nego = 0 Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Connected Aug 9 11:37:47 ike_delete_negotiation: Start, SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de}, nego = 0 Aug 9 11:37:47 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [0] / 0xb18729ee } Info; Deleting negotiation sa Aug 9 11:37:47 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:37:47 ike_free_negotiation: Start, nego = 0 Aug 9 11:37:47 Phase-2 freeing PMData 0 Aug 9 11:37:47 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:37:47 ike_remove_callback: Start, delete SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de}, nego = -1 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:37:47 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:47 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:47 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:37:47 Completing packet Aug 9 11:37:47 ike_delete_negotiation: Start, SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de}, nego = -1 Aug 9 11:37:47 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 49f3a689 9bc0b179 - e1184972 7fadb4de [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:37:47 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126266 from IKE tunnel table Aug 9 11:37:47 ike_sa_delete: Start, SA = { 49f3a689 9bc0b179 - e1184972 7fadb4de } Aug 9 11:37:47 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:37:47 ike_free_negotiation: Start, nego = -1 Aug 9 11:37:47 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:37:47 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:37:47 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:37:47 Created Peer patricia key Aug 9 11:37:47 Peer structure entry Not FOUND Aug 9 11:37:47 error not found peer entry for p1 sa Aug 9 11:37:47 P1 freeing PMdata ad3800 Aug 9 11:37:47 ike_free_id_payload: Start, id type = 1 Aug 9 11:37:47 ike_free_sa: Start Aug 9 11:38:02 In iked_rts_async_ipsec_msg_handler Aug 9 11:38:02 Received IKE Trigger message with local_gw_addr = 92.X.X.X remote_gw_addr = 94.Y.Y.Y Aug 9 11:38:02 In iked_async_ike_trigger_msg_handler; Tunnel = 2 Aug 9 11:38:02 Triggering the IKE negotiation .... Aug 9 11:38:02 kmd_pm_trigger_callback Aug 9 11:38:02 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:38:02 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:38:02 kmd_pm_ike_start_p1 Aug 9 11:38:02 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:02 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:38:02 ike_sa_allocate: Start, SA = { 5378727b 5fe808ab - 00000000 00000000 } Aug 9 11:38:02 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:38:02 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126267 to IKE tunnel table Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:38:02 jnp_ike_connect: SA = { 5378727b 5fe808ab - 00000000 00000000}, nego = -1 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:38:02 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:38:02 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:38:02 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:38:02 ike_st_o_sa_proposal: Start Aug 9 11:38:02 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:38:02 NAT is enabled Aug 9 11:38:02 Advertizing DPD capability Aug 9 11:38:02 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:38:02 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:38:02 ike_st_o_private: Start Aug 9 11:38:02 remote end does not support NAT-T Aug 9 11:38:02 ike_policy_reply_private_payload_out: Start Aug 9 11:38:02 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:38:02 ike_encode_packet: Start, SA = { 0x5378727b 5fe808ab - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0x5378727b 5fe808ab Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:38:02 ike_encode_packet: Payload length = 96 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:38:02 ike_encode_packet: Payload length = 20 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:38:02 ike_encode_packet: Payload length = 32 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:38:02 ike_encode_packet: Payload length = 20 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:38:02 ike_encode_packet: Payload length = 20 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:38:02 ike_encode_packet: Payload length = 20 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:38:02 ike_encode_packet: Payload length = 20 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:38:02 ike_encode_packet: Payload length = 20 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:38:02 ike_encode_packet: Payload length = 20 Aug 9 11:38:02 ike_encode_packet: Packet length = 296 Aug 9 11:38:02 ike_encode_packet: Final length = 296 Aug 9 11:38:02 ike_send_packet: Start, send SA = { 5378727b 5fe808ab - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:38:02 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:38:02 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:02 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:38:02 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:38:02 Looking up instance for server: 92.X.X.X Aug 9 11:38:02 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = 5378727b 5fe808ab c45d0c1d 3d979e1d ... Aug 9 11:38:02 ike_get_sa: Start, SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d } / 26c61d92, remote = 94.Y.Y.Y:500 Aug 9 11:38:02 ike_sa_find: Not found SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d } Aug 9 11:38:02 ike_sa_find_half: Found half SA = { 5378727b 5fe808ab - 00000000 00000000 } Aug 9 11:38:02 ike_get_sa: We are intiator, first response packet Aug 9 11:38:02 ike_sa_upgrade: Start, SA = { 5378727b 5fe808ab - 00000000 00000000 } -> { ... - c45d0c1d 3d979e1d } Aug 9 11:38:02 ike_alloc_negotiation: Start, SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d} Aug 9 11:38:02 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:38:02 ike_udp_callback_common: New informational negotiation message_id = 26c61d92 initialized using slot 0 Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; New informational negotiation Aug 9 11:38:02 ike_udp_callback_common: Old negotiation message_id = 26c61d92, slot 0 Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Packet to old negotiation Aug 9 11:38:02 ike_decode_packet: Start Aug 9 11:38:02 ike_decode_packet: Start, SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d} / 26c61d92, nego = 0 Aug 9 11:38:02 ike_decode_packet: first_payload_type:11. Aug 9 11:38:02 ike_decode_packet: next_payload_type:0. Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0x5378727b 5fe808ab c45d0c1d 3d979e1d Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:38:02 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:38:02 ike_state_step: Matched state = Any (0) Aug 9 11:38:02 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:38:02 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = 5378727b 5fe808ab ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Notification data has attribute list Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Notify message version = 1 Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Error text = Could not find acceptable proposal Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Offending message id = 0x00000000 Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:38:02 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:38:02 ike_st_i_private: Start Aug 9 11:38:02 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:38:02 ike_state_step: All done, new state = Done (42) Aug 9 11:38:02 ike_process_packet: Connected, sending notify Aug 9 11:38:02 ike_send_notify: Connected, SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d}, nego = 0 Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Connected Aug 9 11:38:02 ike_delete_negotiation: Start, SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d}, nego = 0 Aug 9 11:38:02 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [0] / 0x26c61d92 } Info; Deleting negotiation sa Aug 9 11:38:02 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:38:02 ike_free_negotiation: Start, nego = 0 Aug 9 11:38:02 Phase-2 freeing PMData 0 Aug 9 11:38:02 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:38:02 ike_remove_callback: Start, delete SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d}, nego = -1 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:38:02 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:02 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:02 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:38:02 Completing packet Aug 9 11:38:02 ike_delete_negotiation: Start, SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d}, nego = -1 Aug 9 11:38:02 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 5378727b 5fe808ab - c45d0c1d 3d979e1d [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:38:02 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126267 from IKE tunnel table Aug 9 11:38:02 ike_sa_delete: Start, SA = { 5378727b 5fe808ab - c45d0c1d 3d979e1d } Aug 9 11:38:02 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:38:02 ike_free_negotiation: Start, nego = -1 Aug 9 11:38:02 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:02 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:38:02 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:38:02 Created Peer patricia key Aug 9 11:38:02 Peer structure entry Not FOUND Aug 9 11:38:02 error not found peer entry for p1 sa Aug 9 11:38:02 P1 freeing PMdata ad3800 Aug 9 11:38:02 ike_free_id_payload: Start, id type = 1 Aug 9 11:38:02 ike_free_sa: Start Aug 9 11:38:12 In iked_rts_async_ipsec_msg_handler Aug 9 11:38:12 Received IKE Trigger message with local_gw_addr = 92.X.X.X remote_gw_addr = 94.Y.Y.Y Aug 9 11:38:12 In iked_async_ike_trigger_msg_handler; Tunnel = 2 Aug 9 11:38:12 Triggering the IKE negotiation .... Aug 9 11:38:12 kmd_pm_trigger_callback Aug 9 11:38:12 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:38:12 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:38:12 kmd_pm_ike_start_p1 Aug 9 11:38:12 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:12 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:38:12 ike_sa_allocate: Start, SA = { 3f7f38f0 7e96aef9 - 00000000 00000000 } Aug 9 11:38:12 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:38:12 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126268 to IKE tunnel table Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:38:12 jnp_ike_connect: SA = { 3f7f38f0 7e96aef9 - 00000000 00000000}, nego = -1 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:38:12 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:38:12 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:38:12 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:38:12 ike_st_o_sa_proposal: Start Aug 9 11:38:12 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:38:12 NAT is enabled Aug 9 11:38:12 Advertizing DPD capability Aug 9 11:38:12 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:38:12 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:38:12 ike_st_o_private: Start Aug 9 11:38:12 remote end does not support NAT-T Aug 9 11:38:12 ike_policy_reply_private_payload_out: Start Aug 9 11:38:12 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:38:12 ike_encode_packet: Start, SA = { 0x3f7f38f0 7e96aef9 - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0x3f7f38f0 7e96aef9 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:38:12 ike_encode_packet: Payload length = 96 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:38:12 ike_encode_packet: Payload length = 20 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:38:12 ike_encode_packet: Payload length = 32 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:38:12 ike_encode_packet: Payload length = 20 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:38:12 ike_encode_packet: Payload length = 20 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:38:12 ike_encode_packet: Payload length = 20 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:38:12 ike_encode_packet: Payload length = 20 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:38:12 ike_encode_packet: Payload length = 20 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:38:12 ike_encode_packet: Payload length = 20 Aug 9 11:38:12 ike_encode_packet: Packet length = 296 Aug 9 11:38:12 ike_encode_packet: Final length = 296 Aug 9 11:38:12 ike_send_packet: Start, send SA = { 3f7f38f0 7e96aef9 - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:38:12 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:38:12 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:12 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:38:12 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:38:12 Looking up instance for server: 92.X.X.X Aug 9 11:38:12 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = 3f7f38f0 7e96aef9 067699fd 9894963d ... Aug 9 11:38:12 ike_get_sa: Start, SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d } / 77cdef56, remote = 94.Y.Y.Y:500 Aug 9 11:38:12 ike_sa_find: Not found SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d } Aug 9 11:38:12 ike_sa_find_half: Found half SA = { 3f7f38f0 7e96aef9 - 00000000 00000000 } Aug 9 11:38:12 ike_get_sa: We are intiator, first response packet Aug 9 11:38:12 ike_sa_upgrade: Start, SA = { 3f7f38f0 7e96aef9 - 00000000 00000000 } -> { ... - 067699fd 9894963d } Aug 9 11:38:12 ike_alloc_negotiation: Start, SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d} Aug 9 11:38:12 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:38:12 ike_udp_callback_common: New informational negotiation message_id = 77cdef56 initialized using slot 0 Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; New informational negotiation Aug 9 11:38:12 ike_udp_callback_common: Old negotiation message_id = 77cdef56, slot 0 Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Packet to old negotiation Aug 9 11:38:12 ike_decode_packet: Start Aug 9 11:38:12 ike_decode_packet: Start, SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d} / 77cdef56, nego = 0 Aug 9 11:38:12 ike_decode_packet: first_payload_type:11. Aug 9 11:38:12 ike_decode_packet: next_payload_type:0. Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0x3f7f38f0 7e96aef9 067699fd 9894963d Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:38:12 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:38:12 ike_state_step: Matched state = Any (0) Aug 9 11:38:12 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:38:12 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = 3f7f38f0 7e96aef9 ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Notification data has attribute list Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Notify message version = 1 Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Error text = Could not find acceptable proposal Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Offending message id = 0x00000000 Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:38:12 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:38:12 ike_st_i_private: Start Aug 9 11:38:12 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:38:12 ike_state_step: All done, new state = Done (42) Aug 9 11:38:12 ike_process_packet: Connected, sending notify Aug 9 11:38:12 ike_send_notify: Connected, SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d}, nego = 0 Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Connected Aug 9 11:38:12 ike_delete_negotiation: Start, SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d}, nego = 0 Aug 9 11:38:12 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [0] / 0x77cdef56 } Info; Deleting negotiation sa Aug 9 11:38:12 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:38:12 ike_free_negotiation: Start, nego = 0 Aug 9 11:38:12 Phase-2 freeing PMData 0 Aug 9 11:38:12 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:38:12 ike_remove_callback: Start, delete SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d}, nego = -1 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:38:12 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:12 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:12 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:38:12 Completing packet Aug 9 11:38:12 ike_delete_negotiation: Start, SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d}, nego = -1 Aug 9 11:38:12 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 3f7f38f0 7e96aef9 - 067699fd 9894963d [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:38:12 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126268 from IKE tunnel table Aug 9 11:38:12 ike_sa_delete: Start, SA = { 3f7f38f0 7e96aef9 - 067699fd 9894963d } Aug 9 11:38:12 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:38:12 ike_free_negotiation: Start, nego = -1 Aug 9 11:38:12 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:12 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:38:12 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:38:12 Created Peer patricia key Aug 9 11:38:12 Peer structure entry Not FOUND Aug 9 11:38:12 error not found peer entry for p1 sa Aug 9 11:38:12 P1 freeing PMdata ad3800 Aug 9 11:38:12 ike_free_id_payload: Start, id type = 1 Aug 9 11:38:12 ike_free_sa: Start Aug 9 11:38:26 In iked_rts_async_ipsec_msg_handler Aug 9 11:38:26 Received IKE Trigger message with local_gw_addr = 92.X.X.X remote_gw_addr = 94.Y.Y.Y Aug 9 11:38:26 In iked_async_ike_trigger_msg_handler; Tunnel = 2 Aug 9 11:38:26 Triggering the IKE negotiation .... Aug 9 11:38:26 kmd_pm_trigger_callback Aug 9 11:38:26 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:38:26 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:38:26 kmd_pm_ike_start_p1 Aug 9 11:38:26 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:26 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:38:26 ike_sa_allocate: Start, SA = { 6d8ae300 9132af12 - 00000000 00000000 } Aug 9 11:38:26 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:38:26 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126269 to IKE tunnel table Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:38:26 jnp_ike_connect: SA = { 6d8ae300 9132af12 - 00000000 00000000}, nego = -1 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:38:26 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:38:26 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:38:26 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:38:26 ike_st_o_sa_proposal: Start Aug 9 11:38:26 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:38:26 NAT is enabled Aug 9 11:38:26 Advertizing DPD capability Aug 9 11:38:26 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:38:26 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:38:26 ike_st_o_private: Start Aug 9 11:38:26 remote end does not support NAT-T Aug 9 11:38:26 ike_policy_reply_private_payload_out: Start Aug 9 11:38:26 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:38:26 ike_encode_packet: Start, SA = { 0x6d8ae300 9132af12 - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0x6d8ae300 9132af12 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:38:26 ike_encode_packet: Payload length = 96 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:38:26 ike_encode_packet: Payload length = 20 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:38:26 ike_encode_packet: Payload length = 32 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:38:26 ike_encode_packet: Payload length = 20 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:38:26 ike_encode_packet: Payload length = 20 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:38:26 ike_encode_packet: Payload length = 20 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:38:26 ike_encode_packet: Payload length = 20 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:38:26 ike_encode_packet: Payload length = 20 Aug 9 11:38:26 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:38:26 ike_encode_packet: Payload length = 20 Aug 9 11:38:26 ike_encode_packet: Packet length = 296 Aug 9 11:38:26 ike_encode_packet: Final length = 296 Aug 9 11:38:26 ike_send_packet: Start, send SA = { 6d8ae300 9132af12 - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:38:26 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:38:26 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:27 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:38:27 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:38:27 Looking up instance for server: 92.X.X.X Aug 9 11:38:27 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = 6d8ae300 9132af12 23b3ecd0 04dcbc73 ... Aug 9 11:38:27 ike_get_sa: Start, SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 } / 33229b56, remote = 94.Y.Y.Y:500 Aug 9 11:38:27 ike_sa_find: Not found SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 } Aug 9 11:38:27 ike_sa_find_half: Found half SA = { 6d8ae300 9132af12 - 00000000 00000000 } Aug 9 11:38:27 ike_get_sa: We are intiator, first response packet Aug 9 11:38:27 ike_sa_upgrade: Start, SA = { 6d8ae300 9132af12 - 00000000 00000000 } -> { ... - 23b3ecd0 04dcbc73 } Aug 9 11:38:27 ike_alloc_negotiation: Start, SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73} Aug 9 11:38:27 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:38:27 ike_udp_callback_common: New informational negotiation message_id = 33229b56 initialized using slot 0 Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; New informational negotiation Aug 9 11:38:27 ike_udp_callback_common: Old negotiation message_id = 33229b56, slot 0 Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Packet to old negotiation Aug 9 11:38:27 ike_decode_packet: Start Aug 9 11:38:27 ike_decode_packet: Start, SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73} / 33229b56, nego = 0 Aug 9 11:38:27 ike_decode_packet: first_payload_type:11. Aug 9 11:38:27 ike_decode_packet: next_payload_type:0. Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0x6d8ae300 9132af12 23b3ecd0 04dcbc73 Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:38:27 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:38:27 ike_state_step: Matched state = Any (0) Aug 9 11:38:27 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:38:27 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = 6d8ae300 9132af12 ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Notification data has attribute list Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Notify message version = 1 Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Error text = Could not find acceptable proposal Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Offending message id = 0x00000000 Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:38:27 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:38:27 ike_st_i_private: Start Aug 9 11:38:27 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:38:27 ike_state_step: All done, new state = Done (42) Aug 9 11:38:27 ike_process_packet: Connected, sending notify Aug 9 11:38:27 ike_send_notify: Connected, SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73}, nego = 0 Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Connected Aug 9 11:38:27 ike_delete_negotiation: Start, SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73}, nego = 0 Aug 9 11:38:27 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [0] / 0x33229b56 } Info; Deleting negotiation sa Aug 9 11:38:27 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:38:27 ike_free_negotiation: Start, nego = 0 Aug 9 11:38:27 Phase-2 freeing PMData 0 Aug 9 11:38:27 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:38:27 ike_remove_callback: Start, delete SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73}, nego = -1 Aug 9 11:38:27 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:38:27 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:38:27 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:27 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:27 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:38:27 Completing packet Aug 9 11:38:27 ike_delete_negotiation: Start, SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73}, nego = -1 Aug 9 11:38:27 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:38:27 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126269 from IKE tunnel table Aug 9 11:38:27 ike_sa_delete: Start, SA = { 6d8ae300 9132af12 - 23b3ecd0 04dcbc73 } Aug 9 11:38:27 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:38:27 ike_free_negotiation: Start, nego = -1 Aug 9 11:38:27 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:27 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:38:27 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:38:27 Created Peer patricia key Aug 9 11:38:27 Peer structure entry Not FOUND Aug 9 11:38:27 error not found peer entry for p1 sa Aug 9 11:38:27 P1 freeing PMdata ad3800 Aug 9 11:38:27 ike_free_id_payload: Start, id type = 1 Aug 9 11:38:27 ike_free_sa: Start Aug 9 11:38:40 Triggering all tunnels Aug 9 11:38:40 kmd_pm_trigger_callback Aug 9 11:38:40 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:38:40 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:38:40 kmd_pm_ike_start_p1 Aug 9 11:38:40 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:40 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:38:40 ike_sa_allocate: Start, SA = { b9ff9d5b eab931d7 - 00000000 00000000 } Aug 9 11:38:40 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:38:40 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126270 to IKE tunnel table Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:38:40 jnp_ike_connect: SA = { b9ff9d5b eab931d7 - 00000000 00000000}, nego = -1 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:38:40 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:38:40 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:38:40 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:38:40 ike_st_o_sa_proposal: Start Aug 9 11:38:40 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:38:40 NAT is enabled Aug 9 11:38:40 Advertizing DPD capability Aug 9 11:38:40 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:38:40 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:38:40 ike_st_o_private: Start Aug 9 11:38:40 remote end does not support NAT-T Aug 9 11:38:40 ike_policy_reply_private_payload_out: Start Aug 9 11:38:40 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:38:40 ike_encode_packet: Start, SA = { 0xb9ff9d5b eab931d7 - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0xb9ff9d5b eab931d7 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:38:40 ike_encode_packet: Payload length = 96 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:38:40 ike_encode_packet: Payload length = 20 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:38:40 ike_encode_packet: Payload length = 32 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:38:40 ike_encode_packet: Payload length = 20 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:38:40 ike_encode_packet: Payload length = 20 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:38:40 ike_encode_packet: Payload length = 20 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:38:40 ike_encode_packet: Payload length = 20 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:38:40 ike_encode_packet: Payload length = 20 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:38:40 ike_encode_packet: Payload length = 20 Aug 9 11:38:40 ike_encode_packet: Packet length = 296 Aug 9 11:38:40 ike_encode_packet: Final length = 296 Aug 9 11:38:40 ike_send_packet: Start, send SA = { b9ff9d5b eab931d7 - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:38:40 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:38:40 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:40 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:38:40 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:38:40 Looking up instance for server: 92.X.X.X Aug 9 11:38:40 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = b9ff9d5b eab931d7 99f881bc 00e97cc0 ... Aug 9 11:38:40 ike_get_sa: Start, SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 } / 8c55f146, remote = 94.Y.Y.Y:500 Aug 9 11:38:40 ike_sa_find: Not found SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 } Aug 9 11:38:40 ike_sa_find_half: Found half SA = { b9ff9d5b eab931d7 - 00000000 00000000 } Aug 9 11:38:40 ike_get_sa: We are intiator, first response packet Aug 9 11:38:40 ike_sa_upgrade: Start, SA = { b9ff9d5b eab931d7 - 00000000 00000000 } -> { ... - 99f881bc 00e97cc0 } Aug 9 11:38:40 ike_alloc_negotiation: Start, SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0} Aug 9 11:38:40 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:38:40 ike_udp_callback_common: New informational negotiation message_id = 8c55f146 initialized using slot 0 Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; New informational negotiation Aug 9 11:38:40 ike_udp_callback_common: Old negotiation message_id = 8c55f146, slot 0 Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Packet to old negotiation Aug 9 11:38:40 ike_decode_packet: Start Aug 9 11:38:40 ike_decode_packet: Start, SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0} / 8c55f146, nego = 0 Aug 9 11:38:40 ike_decode_packet: first_payload_type:11. Aug 9 11:38:40 ike_decode_packet: next_payload_type:0. Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0xb9ff9d5b eab931d7 99f881bc 00e97cc0 Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:38:40 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:38:40 ike_state_step: Matched state = Any (0) Aug 9 11:38:40 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:38:40 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = b9ff9d5b eab931d7 ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Notification data has attribute list Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Notify message version = 1 Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Error text = Could not find acceptable proposal Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Offending message id = 0x00000000 Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:38:40 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:38:40 ike_st_i_private: Start Aug 9 11:38:40 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:38:40 ike_state_step: All done, new state = Done (42) Aug 9 11:38:40 ike_process_packet: Connected, sending notify Aug 9 11:38:40 ike_send_notify: Connected, SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0}, nego = 0 Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Connected Aug 9 11:38:40 ike_delete_negotiation: Start, SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0}, nego = 0 Aug 9 11:38:40 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [0] / 0x8c55f146 } Info; Deleting negotiation sa Aug 9 11:38:40 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:38:40 ike_free_negotiation: Start, nego = 0 Aug 9 11:38:40 Phase-2 freeing PMData 0 Aug 9 11:38:40 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:38:40 ike_remove_callback: Start, delete SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0}, nego = -1 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:38:40 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:40 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:40 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:38:40 Completing packet Aug 9 11:38:40 ike_delete_negotiation: Start, SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0}, nego = -1 Aug 9 11:38:40 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:38:40 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126270 from IKE tunnel table Aug 9 11:38:40 ike_sa_delete: Start, SA = { b9ff9d5b eab931d7 - 99f881bc 00e97cc0 } Aug 9 11:38:40 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:38:40 ike_free_negotiation: Start, nego = -1 Aug 9 11:38:40 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:40 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:38:40 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:38:40 Created Peer patricia key Aug 9 11:38:40 Peer structure entry Not FOUND Aug 9 11:38:40 error not found peer entry for p1 sa Aug 9 11:38:40 P1 freeing PMdata ad3800 Aug 9 11:38:40 ike_free_id_payload: Start, id type = 1 Aug 9 11:38:40 ike_free_sa: Start Aug 9 11:38:41 In iked_rts_async_ipsec_msg_handler Aug 9 11:38:41 Received IKE Trigger message with local_gw_addr = 92.X.X.X remote_gw_addr = 94.Y.Y.Y Aug 9 11:38:41 In iked_async_ike_trigger_msg_handler; Tunnel = 2 Aug 9 11:38:41 Triggering the IKE negotiation .... Aug 9 11:38:41 kmd_pm_trigger_callback Aug 9 11:38:41 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:38:41 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:38:41 kmd_pm_ike_start_p1 Aug 9 11:38:41 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:41 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:38:41 ike_sa_allocate: Start, SA = { bc435487 9224a48f - 00000000 00000000 } Aug 9 11:38:41 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:38:41 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126271 to IKE tunnel table Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:38:41 jnp_ike_connect: SA = { bc435487 9224a48f - 00000000 00000000}, nego = -1 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:38:41 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:38:41 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:38:41 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:38:41 ike_st_o_sa_proposal: Start Aug 9 11:38:41 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:38:41 NAT is enabled Aug 9 11:38:41 Advertizing DPD capability Aug 9 11:38:41 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:38:41 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:38:41 ike_st_o_private: Start Aug 9 11:38:41 remote end does not support NAT-T Aug 9 11:38:41 ike_policy_reply_private_payload_out: Start Aug 9 11:38:41 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:38:41 ike_encode_packet: Start, SA = { 0xbc435487 9224a48f - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0xbc435487 9224a48f Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:38:41 ike_encode_packet: Payload length = 96 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:38:41 ike_encode_packet: Payload length = 20 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:38:41 ike_encode_packet: Payload length = 32 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:38:41 ike_encode_packet: Payload length = 20 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:38:41 ike_encode_packet: Payload length = 20 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:38:41 ike_encode_packet: Payload length = 20 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:38:41 ike_encode_packet: Payload length = 20 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:38:41 ike_encode_packet: Payload length = 20 Aug 9 11:38:41 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:38:41 ike_encode_packet: Payload length = 20 Aug 9 11:38:41 ike_encode_packet: Packet length = 296 Aug 9 11:38:41 ike_encode_packet: Final length = 296 Aug 9 11:38:41 ike_send_packet: Start, send SA = { bc435487 9224a48f - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:38:41 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:38:41 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:41 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Aug 9 11:38:41 iked_is_anchoring_instance: src 92.X.X.X dst 94.Y.Y.Y return true Aug 9 11:38:41 Looking up instance for server: 92.X.X.X Aug 9 11:38:41 ike_udp_callback_common: Packet from 94.Y.Y.Y:500, data[0..102] = bc435487 9224a48f c5ae81f2 03b626f4 ... Aug 9 11:38:41 ike_get_sa: Start, SA = { bc435487 9224a48f - c5ae81f2 03b626f4 } / a81c46e6, remote = 94.Y.Y.Y:500 Aug 9 11:38:41 ike_sa_find: Not found SA = { bc435487 9224a48f - c5ae81f2 03b626f4 } Aug 9 11:38:41 ike_sa_find_half: Found half SA = { bc435487 9224a48f - 00000000 00000000 } Aug 9 11:38:41 ike_get_sa: We are intiator, first response packet Aug 9 11:38:41 ike_sa_upgrade: Start, SA = { bc435487 9224a48f - 00000000 00000000 } -> { ... - c5ae81f2 03b626f4 } Aug 9 11:38:41 ike_alloc_negotiation: Start, SA = { bc435487 9224a48f - c5ae81f2 03b626f4} Aug 9 11:38:41 ike_alloc_negotiation: Found slot 0, max 1 Aug 9 11:38:41 ike_udp_callback_common: New informational negotiation message_id = a81c46e6 initialized using slot 0 Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; New informational negotiation Aug 9 11:38:41 ike_udp_callback_common: Old negotiation message_id = a81c46e6, slot 0 Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Packet to old negotiation Aug 9 11:38:41 ike_decode_packet: Start Aug 9 11:38:41 ike_decode_packet: Start, SA = { bc435487 9224a48f - c5ae81f2 03b626f4} / a81c46e6, nego = 0 Aug 9 11:38:41 ike_decode_packet: first_payload_type:11. Aug 9 11:38:41 ike_decode_packet: next_payload_type:0. Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Decode N: doi = 1, proto = 1, type = 14, spi[16] = 0xbc435487 9224a48f c5ae81f2 03b626f4 Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Decode N: data[46] = 0x800c0001 00060022 436f756c 64206e6f 74206669... Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Version = 1.0, Input packet fields = 0200 N Aug 9 11:38:41 ike_state_step: Current state = Done (42)/-1, exchange = 5, auth_method = any, Responder Aug 9 11:38:41 ike_state_step: Matched state = Any (0) Aug 9 11:38:41 ike_state_step: Calling input function[0] = ike_st_i_n Aug 9 11:38:41 ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = bc435487 9224a48f ..., data[0..46] = 800c0001 00060022 ... Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Notification data has attribute list Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Notify message version = 1 Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Error text = Could not find acceptable proposal Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Offending message id = 0x00000000 Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it Aug 9 11:38:41 ike_state_step: Calling input function[1] = ike_st_i_private Aug 9 11:38:41 ike_st_i_private: Start Aug 9 11:38:41 ike_state_step: Calling output function[0] = ike_st_o_n_done Aug 9 11:38:41 ike_state_step: All done, new state = Done (42) Aug 9 11:38:41 ike_process_packet: Connected, sending notify Aug 9 11:38:41 ike_send_notify: Connected, SA = { bc435487 9224a48f - c5ae81f2 03b626f4}, nego = 0 Aug 9 11:38:41 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Connected Aug 9 11:38:41 ike_delete_negotiation: Start, SA = { bc435487 9224a48f - c5ae81f2 03b626f4}, nego = 0 Aug 9 11:38:42 92.X.X.X:500 (Responder) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [0] / 0xa81c46e6 } Info; Deleting negotiation sa Aug 9 11:38:42 ike_free_negotiation_info: Start, nego = 0 Aug 9 11:38:42 ike_free_negotiation: Start, nego = 0 Aug 9 11:38:42 Phase-2 freeing PMData 0 Aug 9 11:38:42 iked_ha_clear_ike_sa: HA cluster is not enabled Aug 9 11:38:42 ike_remove_callback: Start, delete SA = { bc435487 9224a48f - c5ae81f2 03b626f4}, nego = -1 Aug 9 11:38:42 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [-1] / 0x00000000 } IP; Removing negotiation Aug 9 11:38:42 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [-1] / 0x00000000 } IP; Connection got error = 14, calling callback Aug 9 11:38:42 IKE negotiation deleted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:42 Phase-1 negotiation failed with error No proposal chosen for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:42 Phase-2 sa_cfg lookup with local_id=ipv4(any:0,[0..3]=192.168.1.10), remote_id=ipv4_subnet(any:0,[0..7]=192.168.12.0/24) Aug 9 11:38:42 Completing packet Aug 9 11:38:42 ike_delete_negotiation: Start, SA = { bc435487 9224a48f - c5ae81f2 03b626f4}, nego = -1 Aug 9 11:38:42 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { bc435487 9224a48f - c5ae81f2 03b626f4 [-1] / 0x00000000 } IP; Deleting negotiation sa Aug 9 11:38:42 jnp_ike_tunnel_table_entry_delete: Deleting tunnel_id: 1126271 from IKE tunnel table Aug 9 11:38:42 ike_sa_delete: Start, SA = { bc435487 9224a48f - c5ae81f2 03b626f4 } Aug 9 11:38:42 ike_free_negotiation_isakmp: Start, nego = -1 Aug 9 11:38:42 ike_free_negotiation: Start, nego = -1 Aug 9 11:38:42 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:42 Trying to lookup Peer entry for peer 94.Y.Y.Y:1f4 Aug 9 11:38:42 Trying to create Peer ID key for peer 94.Y.Y.Y:1f4 Aug 9 11:38:42 Created Peer patricia key Aug 9 11:38:42 Peer structure entry Not FOUND Aug 9 11:38:42 error not found peer entry for p1 sa Aug 9 11:38:42 P1 freeing PMdata ad3800 Aug 9 11:38:42 ike_free_id_payload: Start, id type = 1 Aug 9 11:38:42 ike_free_sa: Start Aug 9 11:38:56 In iked_rts_async_ipsec_msg_handler Aug 9 11:38:56 Received IKE Trigger message with local_gw_addr = 92.X.X.X remote_gw_addr = 94.Y.Y.Y Aug 9 11:38:56 In iked_async_ike_trigger_msg_handler; Tunnel = 2 Aug 9 11:38:56 Triggering the IKE negotiation .... Aug 9 11:38:56 kmd_pm_trigger_callback Aug 9 11:38:56 Triggering negotiation for INSTANCE-test_0002_0004_0000 config block Aug 9 11:38:56 kmd_pm_spd_phase1_gateway_lookup: match selector IPV4: \c | Aug 9 11:38:56 kmd_pm_ike_start_p1 Aug 9 11:38:56 IKE negotiation not found for phase one p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) local=ipv4(udp:500,[0..3]=92.X.X.X) remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:56 jnp_ike_connect: Start, remote_name = 94.Y.Y.Y:500, local = 92.X.X.X:500 xchg = 2, flags = 00000000 Aug 9 11:38:56 ike_sa_allocate: Start, SA = { 86bb4d3a e478094f - 00000000 00000000 } Aug 9 11:38:56 ike_init_isakmp_sa: Start, remote = 94.Y.Y.Y:500, initiator = 1 Aug 9 11:38:56 jnp_ike_tunnel_table_entry_add: Adding tunnel_id: 1126272 to IKE tunnel table Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; SA: Number of proposals = 1 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0]: Number of protocols = 1 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0]: Number of transforms = 2 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][0]: ISAKMP protocol Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; SA[0][0][1]: ISAKMP protocol Aug 9 11:38:56 jnp_ike_connect: SA = { 86bb4d3a e478094f - 00000000 00000000}, nego = -1 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Start isakmp sa negotiation Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Version = 1.0, Input packet fields = 0000 Aug 9 11:38:56 ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 2, auth_method = pre shared key, Initiator Aug 9 11:38:56 ike_state_step: Matched state = Start sa negotiation I (1) Aug 9 11:38:56 ike_state_step: Calling output function[0] = ike_st_o_sa_proposal Aug 9 11:38:56 ike_st_o_sa_proposal: Start Aug 9 11:38:56 ike_state_step: Calling output function[1] = ike_st_o_vids Aug 9 11:38:56 NAT is enabled Aug 9 11:38:56 Advertizing DPD capability Aug 9 11:38:56 ike_policy_reply_isakmp_vendor_ids: Start Aug 9 11:38:56 ike_state_step: Calling output function[2] = ike_st_o_private Aug 9 11:38:56 ike_st_o_private: Start Aug 9 11:38:56 remote end does not support NAT-T Aug 9 11:38:56 ike_policy_reply_private_payload_out: Start Aug 9 11:38:56 ike_state_step: All done, new state = MM SA I (3) Aug 9 11:38:56 ike_encode_packet: Start, SA = { 0x86bb4d3a e478094f - 00000000 00000000 } / 00000000, nego = -1 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode packet, version = 1.0, flags = 0x00000000 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: doi = 1, sit = 0x1 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: Proposal[0] = 0 .protocol[0] = 1, # transforms = 2, spi[8] = 0x86bb4d3a e478094f Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[0] = 0, id = 1, # sa = 6 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode SA: trans[1] = 1, id = 1, # sa = 7 Aug 9 11:38:56 ike_encode_packet: Payload length = 96 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xafcad713 68a1f1c9 6b8696fc 77570100 Aug 9 11:38:56 ike_encode_packet: Payload length = 20 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[28] = 0x69936922 8741c6d4 ca094c93 e242c9de 19e7b7c6 00000005 00000500 Aug 9 11:38:56 ike_encode_packet: Payload length = 32 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x27bab5dc 01ea0760 ea4e3190 ac27c0d0 Aug 9 11:38:56 ike_encode_packet: Payload length = 20 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x6105c422 e76847e4 3f968480 1292aecd Aug 9 11:38:56 ike_encode_packet: Payload length = 20 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x4485152d 18b6bbcd 0be8a846 9579ddcc Aug 9 11:38:56 ike_encode_packet: Payload length = 20 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0xcd604643 35df21f8 7cfdb2fc 68b6a448 Aug 9 11:38:56 ike_encode_packet: Payload length = 20 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x90cb8091 3ebb696e 086381b5 ec427b1f Aug 9 11:38:56 ike_encode_packet: Payload length = 20 Aug 9 11:38:56 92.X.X.X:500 (Initiator) <-> 94.Y.Y.Y:500 { 86bb4d3a e478094f - 00000000 00000000 [-1] / 0x00000000 } IP; Encode VID: vendor id[16] = 0x7d9419a6 5310ca6f 2c179d92 15529d56 Aug 9 11:38:56 ike_encode_packet: Payload length = 20 Aug 9 11:38:56 ike_encode_packet: Packet length = 296 Aug 9 11:38:56 ike_encode_packet: Final length = 296 Aug 9 11:38:56 ike_send_packet: Start, send SA = { 86bb4d3a e478094f - 00000000 00000000}, nego = -1, src = 92.X.X.X:500, dst = 94.Y.Y.Y:500, routing table id = 0 Aug 9 11:38:56 ike_send_packet: Inserting retransmission timer after 5.000000 seconds Aug 9 11:38:56 IKE negotiation inserted for p1_local=ipv4(udp:500,[0..3]=92.X.X.X) p1_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) p2_local=ipv4(udp:500,[0..3]=92.X.X.X) p2_remote=ipv4(udp:500,[0..3]=94.Y.Y.Y) Aug 9 11:38:56 iked_is_anchoring_instance: src 92.X.X.X:500 dst 94.Y.Y.Y:500 Rotating trace files [edit] admin@SRX-FW1#