JNCIE-SEC: Traceoptions & IPSEC troubleshooting

rtoodtoo ipsec, jncie-sec, troubleshooting August 23, 2013

In IPSEC topic, I am continuing with traceoptions and troubleshooting section. In this post, I will try to explain how I troubleshoot IPSEC VPNs mostly initial setup.

IPsec VPNs

Implementation of IPsec VPNs
Multipoint tunnels
Policy and route-based VPNs
Traceoptions
Dual and backup tunnels
On-demand tunnels
DRP over a tunnel
Dynamic VPNs
Certificate-based VPNs
PKI
Interoperability with 3rd party devices

NAT

Implementation of NAT
Source NAT
Destination NAT
Static NAT
Implementation of NAT with IPSec
Overlapping IPs between sites

One of the challenging parts of JNCIE-SEC must be the troubleshooting part for which I need to understand under what sort of problems what type of error logs are generated. Because of this, I enabled IKE traceoptions and simulated several type of possible problems and observed the error logs.

But first let’s see how a successful IKE Phase 1 and IKE Phase 2 log looks like;

PS: All errors below are between ike peers 192.168.179.2 and 212.45.64.2

IKE & IPSEC SUCCESSFUL LOG

Phase 1

[Aug 22 20:40:14]ike_calc_mac: Start, initiator = true, local = false
[Aug 22 20:40:14]ike_st_i_cert: Start
[Aug 22 20:40:14]ike_st_i_private: Start
[Aug 22 20:40:14]ike_st_o_wait_done: Marking for waiting for done
[Aug 22 20:40:14]ike_st_o_all_done: MESSAGE: Phase 1 { 0xe4d65d2e a7bf1c17 - 0x498aaa01 01d0dd21 } / 00000000, version = 1.0, xchg = Identity protect, auth_method = Pre shared keys, Initiator, cipher = 3des-cbc, hash = sha1, prf = hmac-s
ha1
[Aug 22 20:40:14]192.168.179.2:500 (Initiator) <-> 212.45.64.2:500 { e4d65d2e a7bf1c17 - 498aaa01 01d0dd21 [-1] / 0x00000000 } IP; MESSAGE: Phase 1 version = 1.0, auth_method = Pre shared keys, cipher = 3des-cbc, hash = sha1, prf = hmac-
sha
[Aug 22 20:40:14]ike_send_notify: Connected, SA = { e4d65d2e a7bf1c17 - 498aaa01 01d0dd21}, nego = -1
[Aug 22 20:40:14]iked_pm_ike_sa_done: local:192.168.179.2, remote:212.45.64.2 IKEv1
[Aug 22 20:40:14]IKE negotiation done for local:192.168.179.2, remote:212.45.64.2 IKEv1 with status: Error ok
[Aug 22 20:40:14]Added (spi=0xaebf2827, protocol=0) entry to the spi table
[Aug 22 20:40:14]Added (spi=0x3037b766, protocol=0) entry to the spi table
[Aug 22 20:40:14]ssh_ike_connect_ipsec: Start, remote_name = :500, flags = 00000000
[Aug 22 20:40:14]ike_sa_find_ip_port: Remote = all:500, Found SA = { e4d65d2e a7bf1c17 - 498aaa01 01d0dd21}
[Aug 22 20:40:14]ike_alloc_negotiation: Start, SA = { e4d65d2e a7bf1c17 - 498aaa01 01d0dd21}
[Aug 22 20:40:14]ssh_ike_connect_ipsec: SA = { e4d65d2e a7bf1c17 - 498aaa01 01d0dd21}, nego = 0
[Aug 22 20:40:14]ike_init_qm_negotiation: Start, initiator = 1, message_id = 5aa9f0f2
[Aug 22 20:40:14]ike_st_o_qm_hash_1: Start
[Aug 22 20:40:14]ike_st_o_qm_sa_proposals: Start
[Aug 22 20:40:14]ike_st_o_qm_nonce: Start
[Aug 22 20:40:14]ike_policy_reply_qm_nonce_data_len: Start
[Aug 22 20:40:14]ike_st_o_qm_optional_ke: Start
[Aug 22 20:40:14]ike_st_o_qm_optional_ids: Start
[Aug 22 20:40:14]ike_st_qm_optional_id: Start
[Aug 22 20:40:14]ike_st_qm_optional_id: Start
[Aug 22 20:40:14]ike_st_o_private: Start
[Aug 22 20:40:14]Construction NHTB payload for  local:192.168.179.2, remote:212.45.64.2 IKEv1 P1 SA index 8160872 sa-cfg vpn-hub

You can see the “IKE negotiation done” log in here.

Phase 2

[Aug 22 20:40:14]ike_policy_reply_private_payload_out: Start
[Aug 22 20:40:14]ike_st_o_encrypt: Marking encryption for packet
[Aug 22 20:40:14]:500 (Initiator) <-> 212.45.64.2:500 { e4d65d2e a7bf1c17 - 498aaa01 01d0dd21 [0] / 0x5aa9f0f2 } QM; MESSAGE: Phase 2 connection succeeded, No PFS, group = 0
[Aug 22 20:40:14]ike_qm_call_callback: MESSAGE: Phase 2 connection succeeded, No PFS, group = 0
[Aug 22 20:40:14]:500 (Initiator) <-> 212.45.64.2:500 { e4d65d2e a7bf1c17 - 498aaa01 01d0dd21 [0] / 0x5aa9f0f2 } QM; MESSAGE: SA[0][0] = ESP 3des, life = 0 kB/3600 sec, group = 0, tunnel, hmac-sha1-96, Extended seq not used, key le
n =
[Aug 22 20:40:14]ike_qm_call_callback: MESSAGE: SA[0][0] = ESP 3des, life = 0 kB/3600 sec, group = 0, tunnel, hmac-sha1-96, Extended seq not used, key len = 0, key rounds = 0
[Aug 22 20:40:14]iked_pm_ipsec_sa_install: local:192.168.179.2, remote:212.45.64.2  IKEv1 for SA-CFG vpn-hub
[Aug 22 20:40:14]Added (spi=0xaebf2827, protocol=ESP dst=192.168.179.2) entry to the peer hash table
[Aug 22 20:40:14]Added (spi=0xdfa0760c, protocol=ESP dst=212.45.64.2) entry to the peer hash table
[Aug 22 20:40:14]Hardlife timer started for inbound vpn-hub with 3600 seconds/0 kilobytes
[Aug 22 20:40:14]Softlife timer started for inbound vpn-hub with 2978 seconds/0 kilobytes
[Aug 22 20:40:14]In iked_ipsec_sa_pair_add Adding GENCFG msg with key; Tunnel = 131073;SPI-In = 0xaebf2827
[Aug 22 20:40:14]Added dependency on SA config blob with tunnelid = 131073
[Aug 22 20:40:14]Successfully added ipsec SA PAIR
[Aug 22 20:40:14]ike_st_o_qm_wait_done: Marking for waiting for done
[Aug 22 20:40:14]ike_encode_packet: Start, SA = { 0xe4d65d2e a7bf1c17 - 498aaa01 01d0dd21 } / 5aa9f0f2, nego = 0

You can see “QM; MESSAGE: Phase 2 connection succeeded” message.

For this specific connection here is the CLI outputs;

root@J23-London> show security ike sa           
Index   State  Initiator cookie  Responder cookie  Mode           Remote Address   
8160872 UP     e4d65d2ea7bf1c17  498aaa0101d0dd21  Main           212.45.64.2     

root@J23-London> show security ipsec sa  
  Total active tunnels: 1
  ID    Algorithm       SPI      Life:sec/kb  Mon lsys Port  Gateway   
  <131073 ESP:3des/sha1 aebf2827 3469/ unlim   -   root 500   212.45.64.2     
  >131073 ESP:3des/sha1 dfa0760c 3469/ unlim   -   root 500   212.45.64.2

ERROR 1: “IKEv1 Error : Invalid payload type”
If your pre-shared keys aren’t matching you will get a similar error log like below.

[Aug 22 20:49:08]:500 (Responder) <-> 212.45.64.2:500 { 287c0904 ed0108cf - 1dd10036 f9452830 [0] / 0x28e022de } Info; Notification data has attribute list
[Aug 22 20:49:08]:500 (Responder) <-> 212.45.64.2:500 { 287c0904 ed0108cf - 1dd10036 f9452830 [0] / 0x28e022de } Info; Notify message version = 1
[Aug 22 20:49:08]:500 (Responder) <-> 212.45.64.2:500 { 287c0904 ed0108cf - 1dd10036 f9452830 [0] / 0x28e022de } Info; Offending payload type = 145
[Aug 22 20:49:08]:500 (Responder) <-> 212.45.64.2:500 { 287c0904 ed0108cf - 1dd10036 f9452830 [0] / 0x28e022de } Info; Offending payload data offset = 0
[Aug 22 20:49:08]:500 (Responder) <-> 212.45.64.2:500 { 287c0904 ed0108cf - 1dd10036 f9452830 [0] / 0x28e022de } Info; Error text = Incorrect pre-shared key (Invalid next payload value)
[Aug 22 20:49:08]:500 (Responder) <-> 212.45.64.2:500 { 287c0904 ed0108cf - 1dd10036 f9452830 [0] / 0x28e022de } Info; Offending message id = 0x00000000
[Aug 22 20:49:08]:500 (Responder) <-> 212.45.64.2:500 { 287c0904 ed0108cf - 1dd10036 f9452830 [0] / 0x28e022de } Info; Received notify err = Invalid payload type (1) to isakmp sa, delete it
[Aug 22 20:49:08]ike_st_i_private: Start
[Aug 22 20:49:08]ike_send_notify: Connected, SA = { 287c0904 ed0108cf - 1dd10036 f9452830}, nego = 0
[Aug 22 20:49:08]ike_delete_negotiation: Start, SA = { 287c0904 ed0108cf - 1dd10036 f9452830}, nego = 0
[Aug 22 20:49:08]ike_free_negotiation_info: Start, nego = 0
[Aug 22 20:49:08]ike_free_negotiation: Start, nego = 0
[Aug 22 20:49:08]ike_remove_callback: Start, delete SA = { 287c0904 ed0108cf - 1dd10036 f9452830}, nego = -1
[Aug 22 20:49:08]192.168.179.2:500 (Initiator) <-> 212.45.64.2:500 { 287c0904 ed0108cf - 1dd10036 f9452830 [-1] / 0x00000000 } IP; Connection got error = 1, calling callback
[Aug 22 20:49:08]ike_delete_negotiation: Start, SA = { 287c0904 ed0108cf - 1dd10036 f9452830}, nego = -1
[Aug 22 20:49:08]ssh_ike_tunnel_table_entry_delete: Deleting tunnel_id: 0 from IKE tunnel table
[Aug 22 20:49:08]ssh_ike_tunnel_table_entry_delete: The tunnel id: 0 doesn't exist in IKE tunnel table
[Aug 22 20:49:08]ike_sa_delete: Start, SA = { 287c0904 ed0108cf - 1dd10036 f9452830 }
[Aug 22 20:49:08]ike_free_negotiation_isakmp: Start, nego = -1
[Aug 22 20:49:08]ike_free_negotiation: Start, nego = -1
[Aug 22 20:49:08]ike_free_id_payload: Start, id type = 1
[Aug 22 20:49:08]ike_free_sa: Start
[Aug 22 20:49:08]IKE negotiation fail for local:192.168.179.2, remote:212.45.64.2 IKEv1 with status: Invalid syntax
[Aug 22 20:49:08]  IKEv1 Error : Invalid payload type
[Aug 22 20:49:08]IPSec Rekey for SPI 0x0 failed
[Aug 22 20:49:08]IPSec SA done callback called for sa-cfg vpn-hub local:192.168.179.2, remote:212.45.64.2 IKEv1 with status Invalid syntax

Error message “IKEv1 Error: Invalid payload type” is a likely indication of a pre-shared key mismatch. You can also see “Error text = Incorrect pe-shared-key”

Error 2: “IKEv1 Error : No proposal chosen”
You will get the following error if one of the followings mismatches in your IKE config;

dh-group
authentication algorithm
encryption algorithm

WARNING!!!: In addition to these mismatches, you will get the same error under the following conditions

if you forget to set “bind-interface st0.0” under your vpn configuration,
if st0.0 interface isn’t created with family inet and/or assigned to a security zone
if you are using routing instances, also make sure st0.0 interface is assigned to the right routing instance

[Aug 22 20:53:10]ike_st_i_n: Start, doi = 1, protocol = 1, code = No proposal chosen (14), spi[0..16] = f39ace76 bde7864a ..., data[0..46] = 800c0001 00060022 ...
[Aug 22 20:53:10]:500 (Responder) <-> 212.45.64.2:500 { f39ace76 bde7864a - 0d31547b 7e819258 [0] / 0xf638af05 } Info; Notification data has attribute list
[Aug 22 20:53:10]:500 (Responder) <-> 212.45.64.2:500 { f39ace76 bde7864a - 0d31547b 7e819258 [0] / 0xf638af05 } Info; Notify message version = 1
[Aug 22 20:53:10]:500 (Responder) <-> 212.45.64.2:500 { f39ace76 bde7864a - 0d31547b 7e819258 [0] / 0xf638af05 } Info; Error text = Could not find acceptable proposal
[Aug 22 20:53:10]:500 (Responder) <-> 212.45.64.2:500 { f39ace76 bde7864a - 0d31547b 7e819258 [0] / 0xf638af05 } Info; Offending message id = 0x00000000
[Aug 22 20:53:10]:500 (Responder) <-> 212.45.64.2:500 { f39ace76 bde7864a - 0d31547b 7e819258 [0] / 0xf638af05 } Info; Received notify err = No proposal chosen (14) to isakmp sa, delete it
[Aug 22 20:53:10]ike_st_i_private: Start
[Aug 22 20:53:10]ike_send_notify: Connected, SA = { f39ace76 bde7864a - 0d31547b 7e819258}, nego = 0
[Aug 22 20:53:10]ike_delete_negotiation: Start, SA = { f39ace76 bde7864a - 0d31547b 7e819258}, nego = 0
[Aug 22 20:53:10]ike_free_negotiation_info: Start, nego = 0
[Aug 22 20:53:10]ike_free_negotiation: Start, nego = 0
[Aug 22 20:53:10]ike_remove_callback: Start, delete SA = { f39ace76 bde7864a - 0d31547b 7e819258}, nego = -1
[Aug 22 20:53:10]192.168.179.2:500 (Initiator) <-> 212.45.64.2:500 { f39ace76 bde7864a - 0d31547b 7e819258 [-1] / 0x00000000 } IP; Connection got error = 14, calling callback
[Aug 22 20:53:10]ikev2_fb_v1_encr_id_to_v2_id: Unknown IKE encryption identifier -1
[Aug 22 20:53:10]ikev2_fb_v1_hash_id_to_v2_prf_id: Unknown IKE hash alg identifier -1
[Aug 22 20:53:10]ikev2_fb_v1_hash_id_to_v2_integ_id: Unknown IKE hash alg identifier -1
[Aug 22 20:53:10]IKE negotiation fail for local:192.168.179.2, remote:212.45.64.2 IKEv1 with status: No proposal chosen
[Aug 22 20:53:10]  IKEv1 Error : No proposal chosen
[Aug 22 20:53:10]IPSec Rekey for SPI 0x0 failed
[Aug 22 20:53:10]IPSec SA done callback called for sa-cfg vpn-hub local:192.168.179.2, remote:212.45.64.2 IKEv1 with status No proposal chosen

ERROR 3: “IKEv1 Error : Timeout”
If IKE port 500 isn’t reachable at the peer, you will get an error like this. Another problem you might encounter is that for example, you forget to enable IKE service in a zone only in one peer (e.g Peer B) but Peer A is still allowing IKE. This means peer A can’t be the initiator but only responder. Because A can’t connect to IKE port but B can.

[Aug 22 20:59:08]KMD_INTERNAL_ERROR: iked_ifstate_eoc_handler: EOC msg received
[Aug 22 20:59:13]iked_spu_ha_ipc_get_server_addr, server tnp addr (standalone): 0x1, ISSU pending=no
[Aug 22 20:59:24]iked_pm_ike_spd_notify_request: Sending Initial contact
[Aug 22 20:59:24]ssh_ike_connect: Start, remote_name = 212.45.64.2:500, xchg = 2, flags = 00090000
[Aug 22 20:59:24]ike_sa_allocate: Start, SA = { e6ed730d 487d645f - 00000000 00000000 }
[Aug 22 20:59:24]ike_init_isakmp_sa: Start, remote = 212.45.64.2:500, initiator = 1
[Aug 22 20:59:24]ssh_ike_connect: SA = { e6ed730d 487d645f - 00000000 00000000}, nego = -1
[Aug 22 20:59:24]ike_st_o_sa_proposal: Start
[Aug 22 20:59:24]ike_policy_reply_isakmp_vendor_ids: Start
[Aug 22 20:59:24]ike_st_o_private: Start
[Aug 22 20:59:24]ike_policy_reply_private_payload_out: Start
[Aug 22 20:59:24]ike_encode_packet: Start, SA = { 0xe6ed730d 487d645f - 00000000 00000000 } / 00000000, nego = -1
[Aug 22 20:59:24]ike_send_packet: Start, send SA = { e6ed730d 487d645f - 00000000 00000000}, nego = -1, dst = 212.45.64.2:500,  routing table id = 0
[Aug 22 20:59:34]ike_retransmit_callback: Start, retransmit SA = { e6ed730d 487d645f - 00000000 00000000}, nego = -1
[Aug 22 20:59:34]ike_send_packet: Start, retransmit previous packet SA = { e6ed730d 487d645f - 00000000 00000000}, nego = -1, dst = 212.45.64.2:500 routing table id = 0
[Aug 22 20:59:44]ike_retransmit_callback: Start, retransmit SA = { e6ed730d 487d645f - 00000000 00000000}, nego = -1
[Aug 22 20:59:44]ike_send_packet: Start, retransmit previous packet SA = { e6ed730d 487d645f - 00000000 00000000}, nego = -1, dst = 212.45.64.2:500 routing table id = 0
[Aug 22 20:59:54]P1 SA 2299946 timer expiry. ref cnt 2, timer reason Force delete timer expired (1), flags 0x0.
[Aug 22 20:59:54]iked_pm_ike_sa_delete_done_cb: For p1 sa index 2299946, ref cnt 2, status: Error ok
[Aug 22 20:59:54]ike_remove_callback: Start, delete SA = { e6ed730d 487d645f - 00000000 00000000}, nego = -1
[Aug 22 20:59:54]192.168.179.2:500 (Initiator) <-> 212.45.64.2:500 { e6ed730d 487d645f - 00000000 00000000 [-1] / 0x00000000 } IP; Connection timed out or error, calling callback
[Aug 22 20:59:54]ikev2_fb_v1_encr_id_to_v2_id: Unknown IKE encryption identifier -1
[Aug 22 20:59:54]ikev2_fb_v1_hash_id_to_v2_prf_id: Unknown IKE hash alg identifier -1
[Aug 22 20:59:54]ikev2_fb_v1_hash_id_to_v2_integ_id: Unknown IKE hash alg identifier -1
[Aug 22 20:59:54]iked_pm_ike_sa_done: UNUSABLE p1_sa 2299946
[Aug 22 20:59:54]  IKEv1 Error : Timeout
[Aug 22 20:59:54]IPSec Rekey for SPI 0x0 failed
[Aug 22 20:59:54]IPSec SA done callback called for sa-cfg vpn-hub local:192.168.179.2, remote:212.45.64.2 IKEv1 with status Timed out

ERROR 4: “IKEv1 Error : No proposal chosen”
This is the same error like ERROR 2 but it is actually caused by IPSEC proposals not IKE. Thus if one of the following two mismatches, you will get this error.

Authentication algorithm
Encryption algorithm

Note: I had thought that ipsec lifetime is also something that has to match but my tests showed a different result. As far as I can see peers agree on the lowest lifetime configured i.e if peer A has 3600secs and peer B has 7200secs, they agree on 3600secs.

FLOW Troubleshooting
So far I have done IKE troubleshooting. Now I will do some flow troubleshooting.

I enable traceoptions for the traffic that I am going to generate.

[edit]
root@J23-London# show security flow 
traceoptions {
    file ipsec-traf.log size 5m;
    flag basic-datapath;
    packet-filter outgoing-filter {
        protocol icmp;
        source-prefix 55.55.55.1/32;
        destination-prefix 212.45.63.1/32;
    }
    packet-filter incoming-filter {
        protocol icmp;
        source-prefix 212.45.63.1/32;
        destination-prefix 55.55.55.1/32;
    }
    packet-filter outgoing-esp {
        protocol esp;
        source-prefix 192.168.179.2/32;
        destination-prefix 212.45.64.2/32;
    }
}

First two packet filters will show us clear text packets but outgoing-esp is for the encrypted packets

Let’s send 1 ICMP packet with 1000 bytes (1008 bytes with ICMP header)

root@J23-London> ping 212.45.63.1 source 55.55.55.1 count 1 size 1000 
PING 212.45.63.1 (212.45.63.1): 1000 data bytes
1008 bytes from 212.45.63.1: icmp_seq=0 ttl=64 time=46.204 ms

--- 212.45.63.1 ping statistics ---
1 packets transmitted, 1 packets received, 0% packet loss
round-trip min/avg/max/stddev = 46.204/46.204/46.204/0.000 ms

Now examine the file ipsec-traf.log

outgoing-filter match

Aug 22 20:01:06 20:01:06.574883:CID-0:RT:<55.55.55.1/0->212.45.63.1/23813;1> matched filter outgoing-filter:
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:packet [1028] ipid = 3812, @0x4d10d6c1
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 0, common flag 0x0, mbuf 0x4d10d480, rtbl_idx = 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: in_ifp 
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_process_pkt_exception: setting rtt in lpak to 0x5d22ca70
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:Using vr id from pfe_tag with value= 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:Changing lpak->in_ifp from:.local..0 -> to:.local..0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:Over-riding lpak->vsys with 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  .local..0:55.55.55.1->212.45.63.1, icmp, (8/0)
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: find flow: table 0x552e9c90, hash 28352(0xffff), sa 55.55.55.1, da 212.45.63.1, sp 0, dp 23813, proto 1, tok 2 
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  no session found, start first path. in_tunnel - 0x0, from_cp_flag - 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  flow_first_create_session
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:(flow_first_create_session) usp_tagged set session as mng session
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  flow_first_in_dst_nat: in <.local..0>, out  dst_adr 212.45.63.1, sp 0, dp 23813
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  chose interface .local..0 as incoming nat if.
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_rule_dst_xlate: packet 55.55.55.1->212.45.63.1 nsp2 0.0.0.0->212.45.63.1.
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_routing: vr_id 0, call flow_route_lookup(): src_ip 55.55.55.1, x_dst_ip 212.45.63.1, in ifp .local..0, out ifp N/A sp 0, dp 2
3813, ip_proto 1, tos 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:Doing DESTINATION addr route-lookup
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  routed (x_dst_ip 212.45.63.1) from junos-host (.local..0 in 0) to st0.0, Next-hop: 212.45.63.1
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_policy_search: policy search from zone junos-host-> zone vpn (0x0,0x5d05,0x5d05)
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:Policy lkup: vsys 0 zone(2:junos-host) -> zone(7:vpn) scope:0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:             55.55.55.1/2048 -> 212.45.63.1/38837 proto 1
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  app 0, timeout 60s, curr ageout 60s
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  permitted by policy self-traffic-policy(1)
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  packet passed, Permitted by policy.
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_src_xlate:  nat_src_xlated: False, nat_src_xlate_failed: False
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_src_xlate: src nat returns status: 0, rule/pool id: 0/0, pst_nat: False.
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  dip id = 0/0, 55.55.55.1/0->55.55.55.1/0 protocol 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: Found tunnel for if (non-vpn or vpn without nhtb) st0.0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_get_tun_info: tunnel out 0x577cf0ec, tun id 131073
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_get_out_ifp: tunnel out 0x577cf0ec, tun id 131073
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  choose interface ge-0/0/0.0 as outgoing phy if
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:is_loop_pak: No loop: on ifp: st0.0, addr: 212.45.63.1, rtt_idx:0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf : Alloc sess plugin info for session 8
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:[JSF]Normal interest check. regd plugins 12, enabled impl mask 0x0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf int check: plugin id  2, svc_req 0x0, impl mask 0x0. rc 4
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf int check: plugin id  3, svc_req 0x0, impl mask 0x0. rc 4
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf int check: plugin id 12, svc_req 0x0, impl mask 0x0. rc 4
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: Error : parameter wrong natp 0x577cfcc8, plugin_id 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf int check: plugin id 15, svc_req 0x0, impl mask 0x0. rc 4
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:+++++++++++jsf_test_plugin_data_evh: 3
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf int check: plugin id 16, svc_req 0x0, impl mask 0x0. rc 4
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf int check: plugin id 22, svc_req 0x0, impl mask 0x0. rc 4
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf int check: plugin id 27, svc_req 0x0, impl mask 0x0. rc 2
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:[JSF]Plugins(0x0, count 0) enabled for session = 34359738368, impli mask(0x0), post_nat cnt 0 svc req(0x0)
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:-jsf : no plugin interested for session 8, free sess plugin info
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_service_lookup(): natp(0x577cfcc8): app_id, 0(0).
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  service lookup identified service 0.
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  flow_first_final_check: in <.local..0>, out 
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_first_complete_session, pak_ptr: 0xbf97d578, nsp: 0x577cfcc8, in_tunnel: 0x0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:construct v4 vector for nsp2
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  existing vector list 0x204-0x50a92108.
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  Session (id:8) created for first pak 204
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  flow_first_install_session======> 0x577cfcc8
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: nsp 0x577cfcc8, nsp2 0x577cfd48
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  make_nsp_ready_no_resolve()
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  route lookup: dest-ip 55.55.55.1 orig ifp .local..0 output_ifp .local..0 orig-zone 2 out-zone 2 vsd 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  route to 55.55.55.1
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:avt_get_config_by_lsys_id: Not supported on low memory platforms.
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:no need update ha
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:Installing c2s NP session wing
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  flow got session.
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  flow session id 8
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: vector bits 0x204 vector 0x50a92108
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:ttl vector, out_tunnel = 0x577cf0ec
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:pre-frag not needed: ipsize: 1028, mtu: 1438, nsp2->pmtu: 1438
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  encap vector
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  going into tunnel 131073 (nsp_tunnel=0x577cf0ec).
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:  flow_encrypt: tun 0x577cf0ec, type 1
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:mbuf 0x4d10d480, exit nh 0x30010 
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:flow_process_pkt_exception: Freeing lpak 0xbf97d578 associated with mbuf 0x4d10d480
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: ----- flow_process_pkt rc 0x0 (fp rc 0)

What happens here is ;

packet with size 1028 (extra 20 byte from IP header) with identification number 3812 matches: packet [1028] ipid = 3812
A new session is created “flow_first_create_session”
self-traffic-policy allows the traffic as it is locally generated
Tunnel id is identified for the traffic “flow_first_get_tun_info: tunnel out 0x577cf0ec, tun id 131073”
Physical outgoing interface is chosen: “choose interface ge-0/0/0.0 as outgoing phy if”
and finally packet is encrypted “flow_encrypt: tun 0x577cf0ec, type 1”

outgoing-esp filter match

Aug 22 20:01:06 20:01:06.574883:CID-0:RT:<192.168.179.2/0->212.45.64.2/0;50> matched filter outgoing-esp:
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:packet [1080] ipid = 405, @0x4d10d69d
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 2, common flag 0x0, mbuf 0x4d10d480, rtbl_idx = 0
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: post_encap: nsp_tunnel 0x577cf0ec. is_valid 1
Aug 22 20:01:06 20:01:06.574883:CID-0:RT:mbuf 0x4d10d480, exit nh 0xa0010 
Aug 22 20:01:06 20:01:06.574883:CID-0:RT: ----- flow_process_pkt rc 0x0 (fp rc 0)

In this filter we can see that:
Packet is in the tunnel and grew in size to 1080 bytes (i.e total length of the new IP packet with ESP header and encryption) and with outside ip id 405

incoming encrypted traffic
I have seen that though I haven’t configured returned esp traffic filter, outgoing-esp filter caught this traffic.

Aug 22 21:02:44 21:02:44.579966:CID-0:RT:<212.45.64.2/0->192.168.179.2/0;50> matched filter outgoing-esp:
Aug 22 21:02:44 21:02:44.579966:CID-0:RT:packet [1080] ipid = 4, @0x49fa83ce
Aug 22 21:02:44 21:02:44.579966:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 15, common flag 0x0, mbuf 0x49fa8180, rtbl_idx = 0
Aug 22 21:02:44 21:02:44.579966:CID-0:RT: flow process pak fast ifl 70 in_ifp ge-0/0/0.0
Aug 22 21:02:44 21:02:44.579966:CID-0:RT:  ge-0/0/0.0:212.45.64.2->192.168.179.2, 50
Aug 22 21:02:44 21:02:44.579966:CID-0:RT: find flow: table 0x552e9c90, hash 44389(0xffff), sa 212.45.64.2, da 192.168.179.2, sp 58759, dp 3018, proto 50, tok 8 
Aug 22 21:02:44 21:02:44.579966:CID-0:RT:  flow got session
Aug 22 21:02:44 21:02:44.579966:CID-0:RT:  flow session id 1
Aug 22 21:02:44 21:02:44.579966:CID-0:RT:  flow_decrypt: tun 0x577cf0ec(flag 0x82), iif 70

Return traffic enters from ge-0/0/0.0 interface : ge-0/0/0.0:212.45.64.2->192.168.179.2, 50
So called source port: 58759 and destination port: 3018
It hits the flow session with id 1 which is a one direction ESP session

root@J23-London> show security flow session protocol esp 
Session ID: 1, Policy name: N/A, Timeout: N/A, Valid
  In: 212.45.64.2/58759 --> 192.168.179.2/3018;esp, If: ge-0/0/0.0, Pkts: 0, Bytes: 0

Session ID: 2, Policy name: N/A, Timeout: N/A, Valid
  In: 212.45.64.2/0 --> 192.168.179.2/0;esp, If: ge-0/0/0.0, Pkts: 0, Bytes: 0
Total sessions: 2

root@J23-London> show security flow session session-identifier 1 
Session ID: 1, Status: Normal
Flag: 0x10000
Policy name: N/A
Source NAT pool: Null
Maximum timeout: N/A, Current timeout: N/A
Session State: Valid
Start time: 14, Duration: 7792
   In: 212.45.64.2/58759 --> 192.168.179.2/3018;esp, 
    Interface: ge-0/0/0.0, 
    Session token: 0x8, Flag: 0x100621
    Route: 0xa0010, Gateway: 192.168.179.1, Tunnel: 0
    Port sequence: 0, FIN sequence: 0, 
    FIN state: 0, 
    Pkts: 0, Bytes: 0

I hope to have covered various scenarios in this post related to traceoptions and troubleshooting of IPSEC VPN sessions. In the future posts, I will do some troubleshooting if required.

If you have any other error you have received which isn’t covered here, please do share.

About: rtoodtoo

Worked for more than 10 years as a Network/Support Engineer and also interested in Python, Linux, Security and SD-WAN // JNCIE-SEC #223 / RHCE / PCNSE

17 thoughts on “JNCIE-SEC: Traceoptions & IPSEC troubleshooting”

philip says:

2013/08/23 at 4:01 pm

Love your blog about SRX, but can’t do some posts about Appsecure ? 😉

Reply
rtoodtoo says:

2013/08/23 at 9:39 pm

Hi Philip,
I haven’t worked with Appsecure much actually. Maybe in the future who knows:)

Genco.

Reply
Didzis Ozolins says:

2013/11/12 at 11:29 am

Hello,

I’m having trouble with SRX IKE debugging output.. I can’t get the same detailed output as you are showing. I’ve turned on all the traceoptions (level 15, flags all, etc), no luck so far.
Your output is from SRX device?

Thanks,
Didzis

Reply
1. cduced says:
  
  2013/11/20 at 4:47 pm
  
  > request security ike debug-enable
  > show log kmd
  
  Reply
  1. cduced says:
    
    2013/11/20 at 4:51 pm
    
    More exactly:
    
    > request security ike debug-enable local remote
    
    Reply
2. rtoodtoo says:
  
  2013/11/20 at 8:42 pm
  
  To be honest, these outputs are from X44 release which might produce more verbose output but I didn’t really compare the outputs between different release and yes output is from SRX device.
  
  Reply
nocturnalreaderKeith says:

2013/11/12 at 11:39 pm

Awesome!!

Reply
Hirantha says:

2013/12/16 at 4:38 pm

Can you post about JNCIS Ent and JNCIP Ent

Reply
1. rtoodtoo says:
  
  2013/12/16 at 9:08 pm
  
  I don’t write specifically for ENT exam but I do several tests for routing. I am mostly interested in security indeed. Security itself is huge to digest anyway!
  
  Reply
merictabakoglu says:

2014/07/17 at 1:34 pm

Hi All,
Any comments for “ike_get_sa: Invalid cookie, no sa found, SA ”

Thank You

Reply
1. rtoodtoo says:
  
  2014/07/17 at 4:14 pm
  
  I think it isn’t easy to say what went wrong here. In trace file, in a normal rekey, you see ike_get_sa to find the available SA between this peers and normally it should be followed by “ike_sa_find: Found SA” which isn’t your case. It seems there wasn’t any SA for this ISAKMP message. Maybe an abrupt shutdown on one side.
  
  Reply
Vlad says:

2015/03/24 at 9:17 pm

Hi rtoodtoo,

Thank you for your tremendous posts. I read them all the time and find information that you provide very helpfull in my day to day work. I was wondering if you were planning to make a post for Ikev2. Im running into the following message when trying to force Ikev2 only. It works fine when in ikev1.

[Mar 24 12:49:12]IPSec negotiation failed for SA-CFG xxxxxx for local:x.x.x.x., remote:y.y.y.y IKEv2. status: Invalid argument

and it generates the following syslog:

%DAEMON-3: IKE negotiation failed with error: Invalid argument. IKE Version: 2, VPN: xxxxxxx Gateway: xxxxxx, Local: x.x.x.x/500, Remote: y.y.y.y/500, Local IKE-ID: Not-Available, Remote IKE-ID: Not-Available, VR-ID: 6

Reply
1. rtoodtoo says:
  
  2015/03/26 at 9:45 pm
  
  I haven’t done much IKEv2 stuff so far actually but maybe in the future!
  
  Reply
David Mackintosh says:

2015/03/26 at 3:48 pm

iked_pm_id_validate id NOT matched.

I was doing a VPN with a Cisco running ASA 8.0, and it was expecting IKE-IDs by default, and so the options for the same were not present in the Cisco’s config. The result was a phase-1 that appeared to come up and then drop 2 to 5 seconds later before phase-2 could be negotiated. It wasn’t clear which side was doing the dropping.

The solution is to set the general IKE ID option:

set security ike gateway $GATEWAY general-ikeid

Reply
1. rtoodtoo says:
  
  2015/03/26 at 9:49 pm
  
  Thanks for sharing your experience David. Much appreciated.
  
  Reply
lutfe habib khan says:

2015/12/31 at 3:04 am

Hi,
Do you have configuration sample for IPSec between MX and SRX???
Thanks
Habib

Reply
bj.yu says:

2018/01/10 at 7:56 am

No proposal chosen (14)
mistakes ipsec dh-group

Reply