SRX

Hey there.

I have one SRX 210 (PPPOE, static IP) and a SRX 100 (WWAN dial in, GCNAT). Everything worked well, but it suddendly stopped working.

SRX 210 (central site, PPPOE, static IP):

security {
    ike {
        policy ike-policy1 {
            mode aggressive;
            proposal-set standard;
            pre-shared-key ascii-text "$9$j5ikmzF/xxxxxxxxxx"; ## SECRET-DATA
        }
        gateway GW-J-Remote {
            ike-policy ike-policy1;
            dynamic hostname remote.dyndns.org;
            dead-peer-detection {       
                interval 10;            
                threshold 5;            
            }                           
            local-identity hostname central.dyndns.org;
            external-interface pp0.0;   
            version v1-only;            
        }                               
    }                                   
    ipsec {                             
        policy vpn-policy1 {            
            perfect-forward-secrecy {   
                keys group2;            
            }                           
            proposal-set standard;      
        }                               
        vpn VPN-J-Remote {              
            bind-interface st0.0;       
            ike {                       
                gateway GW-J-Remote;    
                ipsec-policy vpn-policy1;
            }                           
            establish-tunnels immediately;
        }                               
    }
}

show log kmd-logs outputs nothing helpful.

SRX 100 (remote site, WWAN, CGNAT):

security {
    ike {
        policy ike-policy1 {
            mode aggressive;
            proposal-set standard;
            pre-shared-key ascii-text "$9$9xA1AuBMxxxxxxxxxxx";
        }
        gateway Central-GW {
            ike-policy ike-policy1;
            address XXX.YYY.ZZZ.114;
            local-identity hostname remote.dyndns.org;
            external-interface dl0.0;
        }
    }
    ipsec {
        policy vpn-policy1 {
            proposal-set standard;
        }
        vpn Central-VPN {
            bind-interface st0.0;
            ike {
                gateway Central-GW;
                ipsec-policy vpn-policy1;
            }
            establish-tunnels immediately;
        }
    }
}

Do you have any hints to increase the logging for troubleshooting? Or can you find issues at the first glace? Would be appreciated for any help.

Hello,

Did You enable IKE debug for this peer? 

https://www.juniper.net/documentation/en_US/junos/topics/reference/command-summary/request-security-ike-debug-enable.html

If not then please enable and post the sanitized logs for examination.

HTH

Thx

Alex

Apr 27 09:17:46  Remote kmd[1447]: IKE negotiation failed with error: Timed out. IKE Version: 1, VPN: Central-VPN Gateway: Central-GW, Local: 10.160.243.226/500, Remote: XXX.YYY.ZZZ.114/500, Local IKE-ID: Not-Available, Remote IKE-ID: Not-Available, VR-ID: 0

This log entry is from the remote site. I'm wondering about port 500. Shouldn't it be 4500, since it uses NAT-T? It is not disabled explicitly...

Debug from the Remote site:

[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  Triggering negotiation for Central-VPN config block
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_pm_trigger_callback: lookup peer entry for gateway Central-GW, local_port=500, remote_port=500
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_create_peer_entry: Created peer entry 0xeed800 for local 10.160.243.226:500 remote XXX.YYY.ZZZ.114:500
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_fetch_or_create_peer_entry: Create peer entry 0xeed800 for local 10.160.243.226:500 remote XXX.YYY.ZZZ.114:500. gw Central-GW, VR id 0
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_pm_trigger_callback: FOUND peer entry for gateway Central-GW
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  Initiating new P1 SA for gateway Central-GW
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  P1 SA 2914619 start timer. timer duration 30, reason 1.
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_pm_trigger_negotiation Set p2_ed in sa_cfg=Central-VPN
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_peer_insert_p1sa_entry: Insert p1 sa 2914619 in peer entry 0xeed800
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_pm_trigger_negotiation Convert traffic selectors from V1 format to V2 format for narrowing/matching selectors
 
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ikev2_fallback_negotiation_alloc: Allocated fallback negotiation eef800
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  Parsing notification payload for local:10.160.243.226, remote:XXX.YYY.ZZZ.114 IKEv1
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_pm_ike_spd_notify_request: Sending Initial contact
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  IKE SA fill called for negotiation of local:10.160.243.226, remote:XXX.YYY.ZZZ.114 IKEv1
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ikev2_fallback_negotiation_free: Fallback negotiation eef800 has still 1 references
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ssh_ike_connect: Start, remote_name = XXX.YYY.ZZZ.114:500, xchg = 4, flags = 00040000
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_sa_allocate: Start, SA = { 49fb4dc3 7053f349 - 00000000 00000000 }
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_init_isakmp_sa: Start, remote = XXX.YYY.ZZZ.114:500, initiator = 1
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ssh_ike_connect: SA = { 49fb4dc3 7053f349 - 00000000 00000000}, nego = -1
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_state_step: Current state = Start sa negotiation I (1)/-1, exchange = 4, auth_method = pre shared key, Initiator
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_st_o_sa_proposal: Start
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_st_o_ke: Start
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_dh_get_group: DH Group type dl-modp
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_dh_get_group: DH Group size 1024
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_dh_get_group: DH Group 2
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_dh_generate_sync: Requested DH group 2
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_dh_generate: Generated DH keys using hardware for DH group 2
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  juniper_dlp_diffie_hellman_generate_async: DH Generate Secs [0] USecs [6415]
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  juniper_dlp_diffie_hellman_generate_async: Generated DH using hardware
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_st_o_nonce: Start
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_policy_reply_isakmp_nonce_data_len: Start
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_st_o_id: Start
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_policy_reply_isakmp_vendor_ids: Start
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_st_o_private: Start
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_policy_reply_private_payload_out: Start
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_state_step: All done, new state = AM SA I (10)
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_encode_packet: Start, SA = { 0x49fb4dc3 7053f349 - 00000000 00000000 } / 00000000, nego = -1
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_encode_packet: Final length = 505
[Apr 27 09:35:16][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_send_packet: Start, send SA = { 49fb4dc3 7053f349 - 00000000 00000000}, nego = -1, local ip= 10.160.243.226, dst = XXX.YYY.ZZZ.114:500,  routing table id = 0
[Apr 27 09:35:26][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_retransmit_callback: Start, retransmit SA = { 49fb4dc3 7053f349 - 00000000 00000000}, nego = -1
[Apr 27 09:35:26][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_send_packet: Start, retransmit previous packet SA = { 49fb4dc3 7053f349 - 00000000 00000000}, nego = -1, dst = XXX.YYY.ZZZ.114:500 routing table id = 0
[Apr 27 09:35:36][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_retransmit_callback: Start, retransmit SA = { 49fb4dc3 7053f349 - 00000000 00000000}, nego = -1
[Apr 27 09:35:36][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_send_packet: Start, retransmit previous packet SA = { 49fb4dc3 7053f349 - 00000000 00000000}, nego = -1, dst = XXX.YYY.ZZZ.114:500 routing table id = 0
[Apr 27 09:35:46][10.160.243.226 <-> XXX.YYY.ZZZ.114]  P1 SA 2914619 timer expiry. ref cnt 2, timer reason Force delete timer expired (1), flags 0x0.
[Apr 27 09:35:46][10.160.243.226 <-> XXX.YYY.ZZZ.114]  Initiate IKE P1 SA 2914619 delete. curr ref count 2, del flags 0x3
[Apr 27 09:35:46][10.160.243.226 <-> XXX.YYY.ZZZ.114]  iked_pm_ike_sa_delete_done_cb: For p1 sa index 2914619, ref cnt 2, status: Error ok
[Apr 27 09:35:46][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ike_remove_callback: Start, delete SA = { 49fb4dc3 7053f349 - 00000000 00000000}, nego = -1
[Apr 27 09:35:46][10.160.243.226 <-> XXX.YYY.ZZZ.114]  10.160.243.226:500 (Initiator) <-> XXX.YYY.ZZZ.114:500 { 49fb4dc3 7053f349 - 00000000 00000000 [-1] / 0x00000000 } Aggr; Connection timed out or error, calling callback
[Apr 27 09:35:46][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ikev2_fb_v1_encr_id_to_v2_id: Unknown IKE encryption identifier -1
[Apr 27 09:35:46][10.160.243.226 <-> XXX.YYY.ZZZ.114]  ikev2_fb_v1_hash_id_to_v2_prf_id: Unknown IKE hash alg identifier -1

I can ping the central site (and verified the right target with disabling system service ping): internet and routing works.

The central site shows nothing. I used the public (CGNAT) IP for the debugging, is this right?

Edit, "empty" log of the central site (show log kmd):

[Apr 10 17:02:31]KMD_INTERNAL_ERROR: iked_ifstate_eoc_handler: EOC msg received
[Apr 12 16:50:34]KMD_INTERNAL_ERROR: iked_ifstate_eoc_handler: EOC msg received
[Apr 12 17:32:00]KMD_INTERNAL_ERROR: kmd_read_securitycfg: dax_get_object_by_path() returned FALSE, secop: 0x38269a60.
[Apr 12 17:35:19]KMD_INTERNAL_ERROR: iked_ifstate_eoc_handler: EOC msg received

root@J-Central> show system uptime    
Current time: 2020-04-27 09:55:28 CEST
System booted: 2020-04-10 16:58:00 CEST (2w2d 16:57 ago)
Protocols started: 2020-04-10 17:00:29 CEST (2w2d 16:54 ago)
Last configured: 2020-04-27 09:15:49 CEST (00:39:39 ago) by root
 9:55AM  up 16 days, 16:57, 1 user, load averages: 0.34, 0.24, 0.23

Hello,

---

@dennis_u wrote:

 I'm wondering about port 500. Shouldn't it be 4500, since it uses NAT-T? It is not disabled explicitly...

IKE starts with port 500 and only switches over to port 4500 when both sides detect NAT-T payload. So if You or Your provider blocked UDP/500, then IKE Ph1 is not going to succeed.

Please check Your FW filters (on lo0.0 or on regular FE|GE interfaces, and enable UDP/500 if blocked.

Other than that, Your logs show only timeouts which are usual when UDP/500 is blocked.

Other possibilities are:

1/ Your "static IP" on "central site" SRX is not in fact static public but behind provider' static NAT which has suddenly changed unbeknownst for You; or

2/ it may be sold as "static public" to You but provider decided to change it without notice.

In either case, if You have a PC behind this "central site" SRX, visit https://whatismyip.com from it and confirm that Your "static IP" is the same as You'd expect. 

HTH

Thx
Alex

Gosh, I found the misconfiguration!

Because of Corona/Covid-19, someone installed a Jitsi server behind the firewall and added the following statements:

set security nat destination rule-set dst-nat rule rule6 match destination-address 0.0.0.0/0
set security nat destination rule-set dst-nat rule rule6 match protocol udp
set security nat destination rule-set dst-nat rule rule6 then destination-nat pool dnat-comm01-jitsi

The SRX was not in charge for UDP/500 anymore... that's embarrassing.