An exploration of the Intenet Key Exchange (IKE) version 1, IKE version 2, and the different modes in which it operates, aggressive, main and quick.
We will step through the operation of IKEv1 Main mode using pre-shared keys by going through an actual example; the establishment of an IKEv1 main mode security association between SRX-11 and SRX-13. Both boxes will be using their loopback addresses of 192.168.11.11 and 192.168.13.13 respectively for the endpoints of the SA.
The Phase 1 SA on SRX-11 can be seen with the command show security ike security-associations.
Phase 1 IKE SA on SRX-11
juniper@SRX-11> show security ike security-associations detail
IKE peer 192.168.13.13, Index 8103321, Gateway Name: SRX-13
Role: Initiator, State: UP
Initiator cookie: 66d3e0d14604eb50, Responder cookie: 89829bbf324bc708
Exchange type: Main, Authentication method: Pre-shared-keys
Local: 192.168.11.11:500, Remote: 192.168.13.13:500
Lifetime: Expires in 86373 seconds
Peer ike-id: 192.168.13.13
Xauth assigned IP: 0.0.0.0
Algorithms:
Authentication : hmac-md5-96
Encryption : 3des-cbc
Pseudo random function: hmac-md5
Diffie-Hellman group : DH-group-1
Traffic statistics:
Input bytes : 584
Output bytes : 796
Input packets: 4
Output packets: 5
Flags: IKE SA is created
IPSec security associations: 1 created, 0 deleted
Phase 2 negotiations in progress: 0
Negotiation type: Quick mode, Role: Initiator, Message ID: 0
Local: 192.168.11.11:500, Remote: 192.168.13.13:500
Local identity: 192.168.11.11
Remote identity: 192.168.13.13
Flags: IKE SA is created
juniper@SRX-11> show security ipsec security-associations detail
ID: 131073 Virtual-system: root, VPN Name: SRX-13
Local Gateway: 192.168.11.11, Remote Gateway: 192.168.13.13
Local Identity: ipv4_subnet(any:0,[0..7]=0.0.0.0/0)
Remote Identity: ipv4_subnet(any:0,[0..7]=0.0.0.0/0)
Version: IKEv1
DF-bit: clear
Bind-interface: st0.0
Port: 500, Nego#: 1, Fail#: 0, Def-Del#: 0 Flag: 0x600a29
Last Tunnel Down Reason: SA not initiated
Direction: inbound, SPI: 7ec82ce1, AUX-SPI: 0
, VPN Monitoring: -
Hard lifetime: Expires in 1166 seconds
Lifesize Remaining: Unlimited
Soft lifetime: Expires in 904 seconds
Mode: Tunnel(0 0), Type: dynamic, State: installed
Protocol: ESP, Authentication: hmac-md5-96, Encryption: aes-cbc (128 bits)
Anti-replay service: counter-based enabled, Replay window size: 64
Direction: outbound, SPI: 90159539, AUX-SPI: 0
, VPN Monitoring: -
Hard lifetime: Expires in 1166 seconds
Lifesize Remaining: Unlimited
Soft lifetime: Expires in 904 seconds
Mode: Tunnel(0 0), Type: dynamic, State: installed
Protocol: ESP, Authentication: hmac-md5-96, Encryption: aes-cbc (128 bits)
Anti-replay service: counter-based enabled, Replay window size: 64
juniper@SRX-11>
The Phase 1 SA on SRX-13 can be seen using the same command.
Phase 1 IKE SA on SRX-13
juniper@SRX-13> show security ike security-associations detail
IKE peer 192.168.11.11, Index 4488225, Gateway Name: SRX-11
Role: Responder, State: UP
Initiator cookie: 66d3e0d14604eb50, Responder cookie: 89829bbf324bc708
Exchange type: Main, Authentication method: Pre-shared-keys
Local: 192.168.13.13:500, Remote: 192.168.11.11:500
Lifetime: Expires in 86384 seconds
Peer ike-id: 192.168.11.11
Xauth assigned IP: 0.0.0.0
Algorithms:
Authentication : hmac-md5-96
Encryption : 3des-cbc
Pseudo random function: hmac-md5
Diffie-Hellman group : DH-group-1
Traffic statistics:
Input bytes : 796
Output bytes : 584
Input packets: 5
Output packets: 4
Flags: IKE SA is created
IPSec security associations: 1 created, 0 deleted
Phase 2 negotiations in progress: 0
Negotiation type: Quick mode, Role: Responder, Message ID: 0
Local: 192.168.13.13:500, Remote: 192.168.11.11:500
Local identity: 192.168.13.13
Remote identity: 192.168.11.11
Flags: IKE SA is created
juniper@SRX-13> show security ipsec security-associations detail
ID: 131073 Virtual-system: root, VPN Name: SRX-11
Local Gateway: 192.168.13.13, Remote Gateway: 192.168.11.11
Local Identity: ipv4_subnet(any:0,[0..7]=0.0.0.0/0)
Remote Identity: ipv4_subnet(any:0,[0..7]=0.0.0.0/0)
Version: IKEv1
DF-bit: clear
Bind-interface: st0.0
Port: 500, Nego#: 1, Fail#: 0, Def-Del#: 0 Flag: 0x600a29
Last Tunnel Down Reason: SA not initiated
Direction: inbound, SPI: 90159539, AUX-SPI: 0
, VPN Monitoring: -
Hard lifetime: Expires in 1180 seconds
Lifesize Remaining: Unlimited
Soft lifetime: Expires in 963 seconds
Mode: Tunnel(0 0), Type: dynamic, State: installed
Protocol: ESP, Authentication: hmac-md5-96, Encryption: aes-cbc (128 bits)
Anti-replay service: counter-based enabled, Replay window size: 64
Direction: outbound, SPI: 7ec82ce1, AUX-SPI: 0
, VPN Monitoring: -
Hard lifetime: Expires in 1180 seconds
Lifesize Remaining: Unlimited
Soft lifetime: Expires in 963 seconds
Mode: Tunnel(0 0), Type: dynamic, State: installed
Protocol: ESP, Authentication: hmac-md5-96, Encryption: aes-cbc (128 bits)
Anti-replay service: counter-based enabled, Replay window size: 64
juniper@SRX-13>
As we go through this example, we're going to dig through a packet capture of the entire exchange, and crawl through the logs line by line. You can download the entire IKEv1 main mode exchange with pre-shared keys, the IKE logs from the initiator SRX-11 and the IKE logs from the responder SRX-13 in order to parse through at your leisure.
The process starts with one of the peers, the initiator, deciding that it wants to establish and IKE security association with it's peer -- the responder. In this example, SRX-11 using it loopback address of 192.168.11.11, initiates the session to SRX-13's loopback address of 192.168.13.13.
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] Received IKE Trigger message with local_gw_addr = 11.11.168.192 remote_gw_addr = 13.13.168.192 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] In iked_async_ike_trigger_msg_handler; Tunnel = 131073 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] Triggering the IKE negotiation .... [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_trigger_callback: FOUND peer entry for gateway SRX-13 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] Initiating new P1 SA for gateway SRX-13
The initiator creates a new Security Association (SA) locally.
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] Allocated IKE SA index 8103321, ref cnt 0 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] P1 SA 8103321 start timer. timer duration 30, reason 1. [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_ike_sa_alloc_cb: Allocated IKE SA 8c76400 I66d3e0d1 4604eb50 (192.168.13.13;500/4500) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ikev2_ipsec_create_sa: State = IKE_INIT_SA
The first bit of information to be packaged in the packet is the Initiator's cookie value, which in this case is 66d3e0d14604eb50. The SRX notes that it only has half of a Phase 1 security association at this point, because it is the initiator; it leaves a field for the responder's cookie padded with zeros. The cookie is used for session identification and as a DoS mitigation technique. The cookie is essentially a random number or a hash derived from some unique system components. The ISAKMP RFC2408 suggests to create a hash from the senders IP address and the destination IP address, port numbers and a locally generated random secret. The cookies will be placed in the ISAKMP header and will be used by both peers to associate incoming ISAKMP packets with the SA that is being setup as part of the IKEv1 exchange.
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_sa_allocate_half: Start
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_sa_allocate: Start, SA = { 66d3e0d1 4604eb50 - 00000000 00000000 }
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_init_isakmp_sa: Start, remote = 192.168.13.13:500, initiator = 1
The initiator then decides what authentication algorithms, encryption algorithms, Diffie-Hellman groups, Phase 1 key lifetimes, and the type of authentication to be used for the session and packages these in a proposal. This proposal, or proposals as there can be more than one are wrapped in a IKAKMP header as a modular payload with a next-header data structure that point to additional payloads. Other options that need to be negotiated for the security association such as Dead Peer Detection (DPD) and NAT traversal (NAT-T) can be added as additionally payloads. There is also room for vendor specific options as well, packaged neatly in a Vendor ID payload.
The proposal components from the SRX configuration are converted into ISAKMP payloads, reference RFC2408 section 3.1 and IANA IKE Attributes. Each payload's contents are identified by a type. Decoding the below attributes, we find they match (or should match), what our proposal is configured as: Type 1 is an Encryption Algorithm and value 5 is 3DES-CBC, type 4 is a Group Description (Diffie-Hellman-Merkel) and is a default 768-bit MODP group, type 2 identifies the Hash Algorithm and value 1 corresponds to MD5, type 11 is the life type (time or amount of data) and value 1 corresponds to seconds, type 12 is the duration which is 86400, and finally type 3 identifies the authentication method whereby 1 indicates pre-shared keys. These values match our Phase 1 proposal in our configuration.
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_get_data_attribute_int: get_int: type = 1 (0x0001), value = 5 (0x00000005), len = 2 (0x0002) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_get_data_attribute_int: get_int: type = 4 (0x0004), value = 1 (0x00000001), len = 2 (0x0002) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_get_data_attribute_int: get_int: type = 2 (0x0002), value = 1 (0x00000001), len = 2 (0x0002) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_get_data_attribute_int: get_int: type = 11 (0x000b), value = 1 (0x00000001), len = 2 (0x0002) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_get_data_attribute_int: get_int: type = 12 (0x000c), value = 86400 (0x00015180), len = 4 (0x0004) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_get_data_attribute_int: get_int: type = 3 (0x0003), value = 1 (0x00000001), len = 2 (0x0002)
Next we can see several Vendor ID (VID) payloads being defined. Several add-on RFCs to IKEv1 actually use the VID payload for their own purposes, such as RFC 3706 uses it for Dead Peer Detection, and RFC3947 uses it for NAT Traversal.
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling output function[1] = ike_st_o_vids [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_isakmp_request_vendor_ids: Request vendor ID's policy call entered, IKE SA 8c76400 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_isakmp_request_vendor_ids: FB; Calling v2 policy function vendor_id_request [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID RFC 3706 (Dead Peer Detection) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID draft-stenberg-ipsec-nat-traversal-01 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID draft-stenberg-ipsec-nat-traversal-02 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID draft-ietf-ipsec-nat-t-ike-00 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID draft-ietf-ipsec-nat-t-ike-02 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID draft-ietf-ipsec-nat-t-ike-02 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID draft-ietf-ipsec-nat-t-ike-03 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID RFC 3947 [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: Got a VID of length 28 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_request_vendor_id: Sending VID NetScreen Technologies [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_vid_request_cb: No more VIDs [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_policy_reply_isakmp_vendor_ids: Start [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling output function[2] = ike_st_o_private [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_st_o_private: Start [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_private_p_1_out: Phase-I output: packet_number 1 ike_sa 8c76400 (neg 8c7a800) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_phase1_pending_natt_operations: Processing pending NAT-T operations [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_private_p_1_out: Remote end does not support NAT-T (or Vendor IDs not received yet) [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ikev2_fb_private_p_1_out: FB; Calling v2 policy function private_payload_request [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_policy_reply_private_payload_out: Start [Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_state_step: All done, new state = MM SA I (3)
Finally, the initial ISAKMP packet in the IKEv1 main mode exchange is packaged up.
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Start, SA = { 0x66d3e0d1 4604eb50 - 00000000 00000000 } / 00000000, nego = -1
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_encode_data_attribute: encode B: type = 1 (0x0001), len = 2, value = 0005
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_encode_data_attribute: encode B: type = 4 (0x0004), len = 2, value = 0001
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_encode_data_attribute: encode B: type = 2 (0x0002), len = 2, value = 0001
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_encode_data_attribute: encode B: type = 11 (0x000b), len = 2, value = 0001
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_encode_data_attribute: encode V: type = 12 (0x000c), len = 4 (0x0004), value = 00015180 ...
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ssh_ike_encode_data_attribute: encode B: type = 3 (0x0003), len = 2, value = 0001
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 64
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 32
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Packet length = 284
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Final length = 284
To summarize the first actions taken by the initiator in a nice finite state machine-like box:
Initiator Formulates Initial Request.
And the initial packet is sent on it's way to 192.168.13.13.
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_send_packet: Start, send SA = { 66d3e0d1 4604eb50 - 00000000 00000000}, nego = -1, dst = 192.168.13.13:500, routing table id = 0
[Feb 11 20:39:51][192.168.11.11 <-> 192.168.13.13] ike_send_packet: Inserting retransmission timer after 10.000000 seconds
Packet #1: Initial ISAKMP packet sent to responder.Click on the packet to download it. View it with tcpdump, Wireshark or Cloudshark.
The responder in the IKE exchange becomes aware that it's being asked to setup a new SA by receiving the initial packet sent from the initiator. It finds an unknown SPI, and checks if the connection is allowed.
Responding SRX processing received IKEv1 packet.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] *** Processing received packet from 192.168.11.11:500 to 192.168.13.13:0 VR 0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_packet_st_input_start: [8c11800/0] Processing received [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] Failed to find IKEv1 SA for given spi [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_packet_st_input_v1_create_sa: [8c11800/0] No IKE SA for packet; requesting permission to create one. [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] iked_pm_ike_rate_limit: Soft limit for p1 negotiation 100.Current active p1 negotiations 0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] New connection from 192.168.11.11:500 allowed [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_packet_st_connect_decision: [8c11800/0] Pad allows connection
If the connection is allowed, it parses the contents and finds that the responders cookie is all zeros, and realizes that it is the responder in the IKE process.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_udp_callback_common: Packet from 192.168.11.11:500, use_natt=0 data[0..284] = 66d3e0d1 4604eb50 00000000 00000000 ...
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_get_sa: Start, SA = { 66d3e0d1 4604eb50 - 00000000 00000000 } / 00000000, remote = 192.168.11.11:500
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_get_sa: We are responder and this is initiators first packet
The responder goes about creating the responder cookie, 0xd2462a04d4c2c7e9, and completing the SA indicator.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_cookie_create: Cookie create
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] 00000000: d246 2a04 d4c2 c7e9 .F*.....
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_sa_allocate: Start, SA = { 66d3e0d1 4604eb50 - d2462a04 d4c2c7e9 }
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_udp_callback_common: New SA
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_init_isakmp_sa: Start, remote = 192.168.11.11:500, initiator = 0
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_new_connection: New ISAKMP connection from remote address 192.168.11.11/500
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] Allocated IKE SA index 4488225, ref cnt 0
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] P1 SA 4488225 start timer. timer duration 30, reason 1.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_ike_sa_allocate_cb: New IKE SA allocated successfully 8c76400 (neg 8c7a800)
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_isakmp_update_responder_cookie: Updating responder IKE cookie
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_isakmp_update_responder_cookie: Original IKE cookie
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] 00000000: d246 2a04 d4c2 c7e9 .F*.....
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_isakmp_update_responder_cookie: New IKE cookie
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] 00000000: 8982 9bbf 324b c708 ....2K..
Next, the responding SRX begins to parse through the payloads in the ISAKMP packet.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_st_new_p1_connection_local_addresses: Accepting new Phase-1 negotiation: local=192.168.13.13:500, remote=192.168.11.11:500 (neg 8c7a800)
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_st_new_p1_connection_local_addresses: FB; Calling v2 policy function get_local_address_list
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fallback_negotiation_free: Fallback negotiation 8c7a800 has still 1 references
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_set_debug_gw_info: ssh_set_debug_gw_info: set gw debug info - local 192.168.13.13 remote 192.168.11.11
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: Start
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708} / 00000000, nego = -1
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: first_payload_type:1.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:0.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_payload_sa: Start
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_payload_sa: Found 1 proposals
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_decode_payload_t: Start, # trans = 1
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute_size: decode_size B: type = 1 (0x0001), value = 5 (0x0005), size = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute_size: decode_size B: type = 4 (0x0004), value = 1 (0x0001), size = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute_size: decode_size B: type = 2 (0x0002), value = 1 (0x0001), size = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute_size: decode_size B: type = 11 (0x000b), value = 1 (0x0001), size = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute_size: decode_size V: type = 12 (0x000c), len = 4 (0x0004), padding = 0, size = 8
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute_size: decode_size B: type = 3 (0x0003), value = 1 (0x0001), size = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute: decode B: type = 1 (0x0001), value = 5 (0x0005), len = 2, used_bytes = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute: decode B: type = 4 (0x0004), value = 1 (0x0001), len = 2, used_bytes = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute: decode B: type = 2 (0x0002), value = 1 (0x0001), len = 2, used_bytes = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute: decode B: type = 11 (0x000b), value = 1 (0x0001), len = 2, used_bytes = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute: decode V: type = 12 (0x000c), len = 4 (0x0004), padding = 0, used_bytes = 8, value = 00015180 80030001 ...
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_decode_data_attribute: decode B: type = 3 (0x0003), value = 1 (0x0001), len = 2, used_bytes = 4
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Current state = Start sa negotiation R (2)/-1, exchange = 2, auth_method = any, Responder
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0
The SRX then checks to see if it is configured to peer with the initiator, and finds one.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_st_select_ike_sa: FB; Calling v2 policy function select_ike_sa [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] Parsing notification payload for local:192.168.13.13, remote:192.168.11.11 IKEv1 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] Search for a tunnel matching the IKE peers, local:192.168.13.13, remote:192.168.11.11 IKEv1 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] iked_pm_phase1_sa_cfg_lookup_by_addr: Found SA-CFG SRX-11 by ip address for local:192.168.13.13, remote:192.168.11.11 IKEv1 remote_port:500 ksa_cfg_remote_port=0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] iked_pm_id_validate NO remote ID, skip validation. [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] address based lookup successful: Sa_cfg:SRX-11 Gateway:SRX-11 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ikev2_sa_select: SA_SELECT: Selecting IKEv1 proposal.
At this point the responder starts to compare the proposals it received from the initiator with the configuration parameters it has for the peer. The peers have to agree to the letter on the encryption algorithm, authentication hash, Diffie-Hellman-Merkel group, key lifetimes and authentication type. IKEv1 can only carry one proposal, so if anything doesn't match here the IKE exchange will fail.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ikev2_sav1_select: Comparing 1 input proposals against 1 policy proposals [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ikev2_sav1_select: Comparing input proposal #1 against policy proposal #1 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_proposal: Comparing 1 protocol(s) [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_proposal: Comparing transforms of protocol 1 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_transform: Comparing 1 input transforms against 1 policy transforms [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_transform: Comparing input transform #0 against policy transform #0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_transform: Transform id 1 matches, comparing attributes [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing 6 input attributes against 6 policy attributes [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 0 against policy attribute 0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Input and policy attributes of type 1 match [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 1 against policy attribute 0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 1 against policy attribute 1 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Input and policy attributes of type 4 match [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 2 against policy attribute 0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 2 against policy attribute 1 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 2 against policy attribute 2 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Input and policy attributes of type 2 match [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Input attribute 3 is life type/duration, ignoring [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Input attribute 4 is life type/duration, ignoring [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 5 against policy attribute 0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 5 against policy attribute 1 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 5 against policy attribute 2 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 5 against policy attribute 3 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 5 against policy attribute 4 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Comparing input attribute 5 against policy attribute 5
And everything matches so far.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Input and policy attributes of type 3 match [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Attributes matched successfully [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_ikev1_attribute_check: Setting life in seconds to 86400 from policy [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_transform: Attributes match; selected input transform 0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_proposal: Protocols match [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_proposal: Selected proposal number 1 and transforms for 1 protocols [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_choose_v1_proposal: Selected transform id 1 for protocol 1 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ikev2_sav1_select: Proposals match
Next, the responder prepares it's initial reply telling the initiator that it has accepted a proposal by echoing back the parameters in an ISAKMP packet send back to the initiator. Ff more than one proposal is was sent, the accepted proposal is sent back as a reply. If only one proposal was sent by the initiator, it is still sent back as a reply. Here we see the SRX packaging up the proposal.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Current state = Start sa negotiation R (2)/1, exchange = 2, auth_method = pre shared key, Responder [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Matched state = Start sa negotiation R (2) [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[1] = ike_st_i_sa_proposal [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_st_i_sa_proposal: Start [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[2] = ike_st_i_cr [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_st_i_cr: Start [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[3] = ike_st_i_cert [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_st_i_cert: Start [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[4] = ike_st_i_status_n [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[5] = ike_st_i_private [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_st_i_private: Start [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[0] = ike_st_o_sa_values [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_st_o_sa_values: Start [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[1] = ike_st_o_optional_certs [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[2] = ike_st_o_vids [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_isakmp_request_vendor_ids: Request vendor ID's policy call entered, IKE SA 8c76400 (neg 8c7a800) [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_isakmp_request_vendor_ids: FB; Calling v2 policy function vendor_id_request [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] iked_pm_ike_request_vendor_id: Sending VID RFC 3706 (Dead Peer Detection) [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_vid_request_cb: Got a VID of length 16 (neg 8c7a800) [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] iked_pm_ike_request_vendor_id: Sending VID RFC 3947 [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_vid_request_cb: Got a VID of length 28 (neg 8c7a800) [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] iked_pm_ike_request_vendor_id: Sending VID NetScreen Technologies [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_vid_request_cb: No more VIDs [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_policy_reply_isakmp_vendor_ids: Start [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[3] = ike_st_o_private [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_st_o_private: Start [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_private_p_1_out: Phase-I output: packet_number 2 ike_sa 8c76400 (neg 8c7a800) [Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ikev2_fb_phase1_pending_natt_operations: Processing pending NAT-T operations
In summary, the finite state machine at this point has the responder peforming the actions below:
Responder's initial actions.
And finally the responder sends Packet #2 in the main mode exchange back to the initiator.
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Start, SA = { 0x66d3e0d1 4604eb50 - 89829bbf 324bc708 } / 00000000, nego = -1
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_encode_data_attribute: encode B: type = 1 (0x0001), len = 2, value = 0005
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_encode_data_attribute: encode B: type = 4 (0x0004), len = 2, value = 0001
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_encode_data_attribute: encode B: type = 2 (0x0002), len = 2, value = 0001
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_encode_data_attribute: encode B: type = 11 (0x000b), len = 2, value = 0001
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_encode_data_attribute: encode V: type = 12 (0x000c), len = 4 (0x0004), value = 00015180 ...
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ssh_ike_encode_data_attribute: encode B: type = 3 (0x0003), len = 2, value = 0001
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Payload length = 56
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Payload length = 20
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Payload length = 20
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Payload length = 32
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Packet length = 156
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Final length = 156
[Feb 11 20:39:52][192.168.13.13 <-> 192.168.11.11] ike_send_packet: Start, send SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708}, nego = -1, dst = 192.168.11.11:500, routing table id = 0
Packet #2: IKEv1 packet sent to initiator.
The initiator receives it's first response from the responder. It tries to look up the SA, consisting of the cookie it first generated and the one that the responder filled in, but finds an unknown value: the responders cookie. It
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] *** Processing received packet from 192.168.13.13:500 to 192.168.11.11:0 VR 0
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_packet_st_input_start: [8c11800/0] Processing received
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_find: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_find: Not found SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] Failed to find IKEv1 SA for given spi
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_packet_st_input_v1_create_sa: [8c11800/0] No IKE SA for packet; requesting permission to create one.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] iked_pm_ike_rate_limit: Soft limit for p1 negotiation 100.Current active p1 negotiations 0
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] New connection from 192.168.13.13:500 allowed
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_packet_st_connect_decision: [8c11800/0] Pad allows connection
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library
Upon looking up the cookie values, it realizes that this is the first reply coming back from the responder. It now has the responder's cookie and can complete the SA information.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_get_sa: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 } / 00000000, remote = 192.168.13.13:500
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_find: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_find: Not found SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_find_half: Start, SA = { 66d3e0d1 4604eb50 - 00000000 00000000 }
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_find_half: Found half SA = { 66d3e0d1 4604eb50 - 00000000 00000000 }
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_get_sa: We are intiator, first response packet
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_upgrade: Start, SA = { 66d3e0d1 4604eb50 - 00000000 00000000 } -> { ... - 89829bbf 324bc708 }
Next, the SRX parses through the payloads of the packet. Here it checks which proposal was accepted, and processes any other payloads such as NAT-T.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: Start
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708} / 00000000, nego = -1
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: first_payload_type:1.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:13.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:0.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_payload_sa: Start
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_payload_sa: Found 1 proposals
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_payload_t: Start, # trans = 1
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 2, auth = 0, fields = 0001 / 06c0
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Matching with state = Start sa negotiation R (2), xchg = 4, auth = 0, fields = 0017 / 06e0
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 3, fields = 0000 / 0000
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 2, auth = 0, fields = 0000 / 0000
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 3, fields = 0000 / 0000
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 2, fields = 0000 / 0000
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Matching with state = Start sa negotiation I (1), xchg = 4, auth = 4, fields = 0000 / 0000
which indicates which proposal is acceptable. The SRX figures out it is an IKEv1 packet, looks up the SA and finds that it belongs to a SA that is not fully setup. It inserts the responders cookie into the SA to fully identify it and begins to process the vendor options.
Initiating SRX processing first response from Responder
[Feb 1 05:45:43]ikev2_packet_allocate: Allocated packet 8c11800 from freelist
[Feb 1 05:45:43]ike_sa_find: Not found SA = { 48472f65 fb1b5dee - ccec02c6 d3ddd1a5 }
[Feb 1 05:45:43]ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library
[Feb 1 05:45:43]ike_get_sa: Start, SA = { 48472f65 fb1b5dee - ccec02c6 d3ddd1a5 } / 00000000, remote = 192.168.13.13:500
[Feb 1 05:45:43]ike_sa_find: Not found SA = { 48472f65 fb1b5dee - ccec02c6 d3ddd1a5 }
[Feb 1 05:45:43]ike_sa_find_half: Found half SA = { 48472f65 fb1b5dee - 00000000 00000000 }
[Feb 1 05:45:43]ike_sa_upgrade: Start, SA = { 48472f65 fb1b5dee - 00000000 00000000 } -> { ... - ccec02c6 d3ddd1a5 }
[Feb 1 05:45:43]ike_decode_packet: Start
[Feb 1 05:45:43]ike_decode_packet: Start, SA = { 48472f65 fb1b5dee - ccec02c6 d3ddd1a5} / 00000000, nego = -1
[Feb 1 05:45:43]ike_decode_payload_sa: Start
[Feb 1 05:45:43]ike_decode_payload_t: Start, # trans = 1
[Feb 1 05:45:43]ike_st_i_sa_value: Start
[Feb 1 05:45:43]ike_st_i_cr: Start
[Feb 1 05:45:43]ike_st_i_cert: Start
[Feb 1 05:45:43]ike_st_i_vid: VID[0..16] = afcad713 68a1f1c9 ...
[Feb 1 05:45:43]ike_st_i_vid: VID[0..16] = 4a131c81 07035845 ...
[Feb 1 05:45:43]ike_st_i_vid: VID[0..28] = 69936922 8741c6d4 ...
Next the initiator selects a Diffie-Hellman-Merkle secret, and calculates it's public key.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[5] = ike_st_i_private [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_st_i_private: Start [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling output function[0] = ike_st_o_ke [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_st_o_ke: Start [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] Using software for dh_gen operation [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] Inside kmd_sw_dh_gen...
Then it selects a nonce which will be used to prevent replay attacks.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling output function[1] = ike_st_o_nonce [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_st_o_nonce: Start [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_isakmp_nonce_data_len: Entered [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_policy_reply_isakmp_nonce_data_len: Start
Any other options are processed as well, such as NAT-T
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_phase1_pending_natt_operations: Processing pending NAT-T operations [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_handle_send_hash_id: Adding NAT-D payloads: ike_sa 8c76400 (neg 8c7a800) [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_id_as_hashed_string: Start ip = 192.168.13.13 port = 500 [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_id_as_hashed_string: Hash input: [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] 00000000: 66d3 e0d1 4604 eb50 8982 9bbf 324b c708 f...F..P....2K.. [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] 00000010: c0a8 0d0d 01f4 ...... [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_policy_reply_private_payload_out: Start [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_id_as_hashed_string: Start ip = 192.168.11.11 port = 500 [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_id_as_hashed_string: Hash input: [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] 00000000: 66d3 e0d1 4604 eb50 8982 9bbf 324b c708 f...F..P....2K.. [Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] 00000010: c0a8 0b0b 01f4 ......
Then the Diffie-Hellman-Merkel public value, the nonce and any ongoing vendor ID payloads are packaged up to be sent out in the third ISAKMP packet.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Start, SA = { 0x66d3e0d1 4604eb50 - 89829bbf 324bc708 } / 00000000, nego = -1
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 100
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Packet length = 188
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Final length = 188
The IKEv1 Main Mode finite state machine at step three.
Initiator processes Diffie-Hellman-Merkle components and a nonce.
And the initiator sends off packet #3 to the responder.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_send_packet: Start, send SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708}, nego = -1, dst = 192.168.13.13:500, routing table id = 0
Packet #3: ISAKMP packet sent to responder.
The responder recieves the third packet, and can immediately associate this with an exising SA as all of the cookie values are finallyl filled in and known to both parties.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] *** Processing received packet from 192.168.11.11:500 to 192.168.13.13:0 VR 0
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_packet_st_input_start: [8c11c00/0] Processing received
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_sa_find: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_sa_find: Found SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] Found IKEv1 SA
The responder finds the initiators Diffie-Hellman-Merkel public value in the first payload (type 4 Key Exchange (KE)), and it's nonce in the second payload (type 10), and a private payload (type 20) which is the ongoing NAT-T exchanges from RFC 3947.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: Start
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708} / 00000000, nego = -1
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: first_payload_type:4.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:10.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:20.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_private_p_1_check: New Phase-I private payload:
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_private_p_1_check: New Phase-I private payload: private_payload_id 20
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_private_p_1_check: RFC 3947 NAT-D payload
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:20.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[0] = ike_st_i_nonce
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_nonce: Start, nonce[0..16] = debff51e aea541fe ...
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[1] = ike_st_i_ke
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_ke: Ke[0..96] = edc7f17e 0f741f0b ...
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[2] = ike_st_i_cr
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_cr: Start
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[3] = ike_st_i_cert
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_cert: Start
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[4] = ike_st_i_status_n
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[5] = ike_st_i_vid
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[6] = ike_st_i_private
It is now the reponders turn to choose it's own Diffie-Hellman-Merkle secret, caluculates it's Diffie-Hellman-Merkle public key, and select a nonce.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_ke: Start [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] Using software for dh_gen operation [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] Inside kmd_sw_dh_gen... [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[1] = ike_st_o_nonce [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_nonce: Start [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_isakmp_nonce_data_len: Entered [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_policy_reply_isakmp_nonce_data_len: Start
Next we can see that the SRX is trying to encrypt the packet, but it can't since the initiator doesn't have it's Diffie-Hellman-Merkel public value yet.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[2] = ike_st_o_get_pre_shared_key [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_find_pre_shared_key: Find pre shared key key for 192.168.13.13:500, id = No Id -> 192.168.11.11:500, id = No Id [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_find_pre_shared_key: Find pre-shared key policy call entered, IKE SA 8c76400 (neg 8c7a800) [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_find_pre_shared_key: Taking reference to fallback negotiation 8c7a800 (now 2 references) [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ssh_set_thread_debug_info: ikev2_fb_find_pre_shared_key: set thread debug info - local 192.168.13.13 remote 192.168.11.11 neg 0x8c7a800 neg->ike_sa 0x8c76400 ike_sa 0x0 [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Output function[2] = ike_st_o_get_pre_shared_key asked retry later [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_process_packet: No output packet, returning [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_packet_destroy: [8c11c00/deadbeee] Destructor [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_packet_free: [8c11c00/deadbeee] Freeing [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_st_find_pre_shared_key: FB; Calling v2 policy function shared_key [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] iked_pm_ike_pre_shared_key Start... [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] iked_pm_phase1_sa_cfg_lookup_by_addr: Found SA-CFG SRX-11 by ip address for local:192.168.13.13, remote:192.168.11.11 IKEv1 remote_port:500 ksa_cfg_remote_port=0 [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] iked_pm_id_validate NO remote ID, skip validation. [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] address based lookup successful: Sa_cfg:SRX-11 Gateway:SRX-11 [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] iked_pm_id_validate NO remote ID, skip validation.
The responder packages up it's own Diffie-Hellman-Merkle public value, it's nonce, and the ongoing NAT-T negotiations.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_private: Start
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_private_p_1_out: Phase-I output: packet_number 4 ike_sa 8c76400 (neg 8c7a800)
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_phase1_pending_natt_operations: Processing pending NAT-T operations
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_handle_send_hash_id: Adding NAT-D payloads: ike_sa 8c76400 (neg 8c7a800)
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_id_as_hashed_string: Start ip = 192.168.11.11 port = 500
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_id_as_hashed_string: Hash input:
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] 00000000: 66d3 e0d1 4604 eb50 8982 9bbf 324b c708 f...F..P....2K..
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] 00000010: c0a8 0b0b 01f4 ......
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_policy_reply_private_payload_out: Start
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_id_as_hashed_string: Start ip = 192.168.13.13 port = 500
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_id_as_hashed_string: Hash input:
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] 00000000: 66d3 e0d1 4604 eb50 8982 9bbf 324b c708 f...F..P....2K..
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] 00000010: c0a8 0d0d 01f4 ......
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_policy_reply_private_payload_out: Start
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_private_p_1_out: FB; Calling v2 policy function private_payload_request
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_policy_reply_private_payload_out: Start
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[4] = ike_st_o_calc_skeyid
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_calc_skeyid: Calculating skeyid
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] Using software for dh_comp operation
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] Inside kmd_sw_dh_comp...
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_find_pre_shared_key: Find pre shared key key for 192.168.13.13:500, id = No Id -> 192.168.11.11:500, id = No Id
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: All done, new state = MM KE R (6)
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Start, SA = { 0x66d3e0d1 4604eb50 - 89829bbf 324bc708 } / 00000000, nego = -1
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Payload length = 100
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Payload length = 20
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Payload length = 20
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Payload length = 20
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Packet length = 188
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_encode_packet: Final length = 188
The IKE finite state machine actions at step 4.
The responder recieves the initiators Diffie-Hellman-Merkle public key, nonce and sends back it's own values.
And the responder sends off packet #4 back to the initiator.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_send_packet: Start, send SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708}, nego = -1, dst = 192.168.11.11:500, routing table id = 0
Packet #4: IKEv1 packet sent to initiator.
The initiator receives the fourth packet in the exchange, and matches it with an existing SA.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] *** Processing received packet from 192.168.13.13:500 to 192.168.11.11:0 VR 0
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_packet_st_input_start: [8c11c00/0] Processing received
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_find: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_sa_find: Found SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] Found IKEv1 SA
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_packet_st_input_v1_get_sa: [8c11c00/deadbeee] Packet to existing v1 SA
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_packet_v1_start: Passing IKE v1.0 packet to IKEv1 library
In the payloads, it now has the responders Diffie-Hellman-Merkel public value and it's nonce.
Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: Start
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708} / 00000000, nego = -1
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: first_payload_type:4.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:10.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:20.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_private_p_1_check: New Phase-I private payload: private_payload_id 20
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_private_p_1_check: RFC 3947 NAT-D payload
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:20.
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ikev2_fb_private_p_1_check: New Phase-I private payload: private_payload_id 20
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[0] = ike_st_i_nonce
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_st_i_nonce: Start, nonce[0..16] = 36a3b1c3 1a211ac4 ...
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[1] = ike_st_i_ke
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_st_i_ke: Ke[0..96] = 855974b7 717d7676 ...
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[2] = ike_st_i_cr
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_st_i_cr: Start
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[3] = ike_st_i_cert
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_st_i_cert: Start
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[4] = ike_st_i_status_n
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[5] = ike_st_i_vid
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[6] = ike_st_i_private
[Feb 11 20:39:52][192.168.11.11 <-> 192.168.13.13] ike_st_i_private: Start
The initiator can now compute the Diffie-Hellman-Merkel secret value.
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] Using software for dh_comp operation [Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] Inside kmd_sw_dh_comp...
From this point on, both the initiator and the responder have enough information to encrypt the contents of the IKE exchange. IKEv1 uses the pre-shared-key, both nonces, the Diffie-Hellman-Merkel secret value, and both cookies to create the authentication key SKEYID_a, and the encryption key SKEYID_e from Section 3.2 and 5 from RFC 2409.
Now the initiator needs to send it's identity to the responder, so the responder can verify that it is talking to who it should be, and not some impostor or middle-man. This packet is encrypted with the the key that was just calculated.
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_calc_mac: Start, initiator = true, local = true
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling output function[2] = ike_st_o_status_n
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_st_o_status_n: Start
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling output function[3] = ike_st_o_private
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_st_o_private: Start
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ikev2_fb_private_p_1_out: Phase-I output: packet_number 5 ike_sa 8c76400 (neg 8c7a800)
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_policy_reply_private_payload_out: Start
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling output function[4] = ike_st_o_encrypt
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_st_o_encrypt: Marking encryption for packet
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_state_step: All done, new state = MM final I (7)
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Start, SA = { 0x66d3e0d1 4604eb50 - 89829bbf 324bc708 } / 00000000, nego = -1
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 12
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 20
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Payload length = 28
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Packet length = 92
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Encrypting packet
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_encode_packet: Final length = 92
At this point, our IKE state machine summarizes the actions that take place in the fifth step.
Initiator calculates Diffie-Hellman-Merkel secret, keying material, and sends ID in the fifth.
And the initiator sends off packet #5 in the exchange.
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_send_packet: Start, send SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708}, nego = -1, dst = 192.168.13.13:500, routing table id = 0
Packet #5: ISAKMP packet sent to responder.
The responder recieves the fifth packet in the exchange, and immediately matches it up with the ongoing SA.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] *** Processing received packet from 192.168.11.11:500 to 192.168.13.13:0 VR 0
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_packet_st_input_start: [8c25000/0] Processing received
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_sa_find: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_sa_find: Found SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] Found IKEv1 SA
Now it has to decrypt the packet, before it can parse through the contents. Once it does it uncovers the following ISAKMP payloads: a type 5 payload indicating an identification, type 8 indicating a hash, and finally a type 11 payload which is a notification.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: Start
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708} / 00000000, nego = -1
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: first_payload_type:5.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: Decrypting packet
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:8.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:11.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_decode_packet: next_payload_type:0.
The responding SRX then checks the encryption and hash on the packet to make sure everything is valid.
ike_state_step: Calling input function[0] = ike_st_i_encrypt [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_encrypt: Check that packet was encrypted succeeded [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[1] = ike_st_i_id [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_id: Start [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[2] = ike_st_i_hash [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_hash: Start, hash[0..16] = a4bfde35 16be4785 ... [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_calc_mac: Start, initiator = false, local = false [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[3] = ike_st_i_cert [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_cert: Start
And it verifies the identity of the initiator as 192.168.11.11.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling input function[4] = ike_st_i_status_n [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_status_n: Start, doi = 1, protocol = 1, code = Initial contact notification (24578), spi[0..16] = 66d3e0d1 4604eb50 ..., data[0..0] = 00000000 00000000 ... [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ssh_ike_check_isakmp_spi: Spi match [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ssh_ike_check_isakmp_spi: Spi match [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_i_status_n: Initial contact [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_phase_i_notification: Phase-I notification call entered, IKE SA 8c76400 (neg 8c7a800) [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] iked_pm_ike_spd_notify_received: Received authenticated notification payload unknown from local:192.168.13.13 remote:192.168.11.11 IKEv1 for P1 SA 4488225 [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_phase_i_notification: Got initial contact notification [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_phase_i_notification: Registering initial contact notification from `192.168.11.11'
At this point, the responder makes a note that it has enough informatin to consider phase 1 complete.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_all_done: MESSAGE: Phase 1 { 0x66d3e0d1 4604eb50 - 0x89829bbf 324bc708 } / 00000000, version = 1.0, xchg = Identity protect, auth_method = Pre shared keys, Responder, cipher = 3de
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] 192.168.13.13:500 (Responder) <-> 192.168.11.11:500 { 66d3e0d1 4604eb50 - 89829bbf 324bc708 [-1] / 0x00000000 } IP; MESSAGE: Phase 1 version = 1.0, auth_method = Pre shared keys, cipher =
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: All done, new state = MM final R (8)
However, it still needs to send it's identity back to the initiator. It uses the calculated key to encrypt the packet contents and hide it's identity from any eavesdroppers.
[Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[0] = ike_st_o_id [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_id: Start [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[1] = ike_st_o_hash [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_hash: Start [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_calc_mac: Start, initiator = false, local = true [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[2] = ike_st_o_status_n [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_status_n: Start [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[3] = ike_st_o_private [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_private: Start [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_private_p_1_out: Phase-I output: packet_number 6 ike_sa 8c76400 (neg 8c7a800) [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_phase1_pending_natt_operations: Processing pending NAT-T operations [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ikev2_fb_private_p_1_out: FB; Calling v2 policy function private_payload_request [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_policy_reply_private_payload_out: Start [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_state_step: Calling output function[4] = ike_st_o_encrypt [Feb 11 20:39:53][192.168.13.13 <-> 192.168.11.11] ike_st_o_encrypt: Marking encryption for packet
In summary, our finite state machine's actions during the fifth step of the exchange.
The responder, SRX-13, verifies SRX-11's identity, and sends it's own ID back.
And the responder sends the sixth and final packet of IKEv1 Phase 1 Main Mode back to the initiator.
Packet #6: IKEv1 packet sent to initiator.
The initiator recieves the final packet of phase 1 and matches it to an SA.
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] *** Processing received packet from 192.168.13.13:500 to 192.168.11.11:0 VR 0
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ikev2_packet_st_input_start: [8c25000/0] Processing received
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_sa_find: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_sa_find: Found SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708 }
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] Found IKEv1 SA
Next, it parses through the packet contents after decrypting it and finds an identity and a hash contained within.
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: Start
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: Start, SA = { 66d3e0d1 4604eb50 - 89829bbf 324bc708} / 00000000, nego = -1
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: first_payload_type:5.
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: Decrypting packet
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:8.
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_decode_packet: next_payload_type:0.
It checks to make sure the decryptioh operation work, and that the authentication hash is as it should.
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[0] = ike_st_i_encrypt [Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_st_i_encrypt: Check that packet was encrypted succeeded [Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[1] = ike_st_i_id [Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_st_i_id: Start [Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_state_step: Calling input function[2] = ike_st_i_hash [Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_st_i_hash: Start, hash[0..16] = ef52f096 0aaa5470 ...
And finding everything in order, it notes that Phase 1 is complete!
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_st_o_wait_done: Marking for waiting for done
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] ike_st_o_all_done: MESSAGE: Phase 1 { 0x66d3e0d1 4604eb50 - 0x89829bbf 324bc708 } / 00000000, version = 1.0, xchg = Identity protect, auth_method = Pre shared keys, Initiator, cipher = 3de
[Feb 11 20:39:53][192.168.11.11 <-> 192.168.13.13] 192.168.11.11:500 (Initiator) <-> 192.168.13.13:500 { 66d3e0d1 4604eb50 - 89829bbf 324bc708 [-1] / 0x00000000 } IP; MESSAGE: Phase 1 version = 1.0, auth_method = Pre shared keys, cipher =
The final step of the IKEv1 Main Mode Phase 1 finite state machine.
Initiator verifies responder's identity.
The two IKE peers will now move onto Phase 2, Quick Mode.