SRX

Expand all | Collapse all

VPN stopped working, debug log is empty

Jump to Best Answer
  • 1.  VPN stopped working, debug log is empty

    Posted 04-25-2020 13:10

    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.



  • 2.  RE: VPN stopped working, debug log is empty

    Posted 04-26-2020 04:22

    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



  • 3.  RE: VPN stopped working, debug log is empty

    Posted 04-27-2020 00:48
    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

     



  • 4.  RE: VPN stopped working, debug log is empty

    Posted 04-27-2020 01:30

    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

     

     

     



  • 5.  RE: VPN stopped working, debug log is empty
    Best Answer

    Posted 04-27-2020 02:26

    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.