This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

IP SEC site-to-site terminates and establishes every 30 minutes

XG210 (SFOS 17.0.6 MR-6)

According to the SYSTEM logs one of my IPSEC site-to-site connection terminates and then is established every thirty minutes. I don't see any other error's or logs that correlate with this. I also have another IPSEC site-to-site that is connected that isn't logging this activity. 

I had a 12 hour file transfer that ended on 6/8 at 3:55am that doesn't seem to have been affected by it.

 

This is what it looks like:

6/8/2018 3:41 IPSec Successful
6/8/2018 3:41 IPSec Established
6/8/2018 3:41 IPSec Terminated
6/8/2018 3:24 IPSec Terminated
6/8/2018 3:24 IPSec Established
6/8/2018 3:11 IPSec Successful
6/8/2018 3:10 IPSec Established
6/8/2018 3:10 IPSec Terminated

 

Before I contact the client on the other end of the tunnel I thought I'd ask if this is some kind of normal behavior or if there is some other diagnostics I can perform.

 



This thread was automatically locked due to age.
Parents
  • Hey  

    From the logs does it look like this issue has been going on for a while or just recently?

    What are you able to observe in your IPsec logs (strongswan.log/charon.log)?
    You could also perform a constant ping test to a remote machine on the other side of the IPsec tunnel to further test if you indeed drop connection. 

  • Thank you -

    This is what I found in the charon.log for the corresponding times. 

    2018-06-07 01:01:21 26[NET] <XXXX_ATL-1|1804> sending packet: from xx.xx.xxx.xxx[500] to yy.yyy.yy.yyy[500] (92 bytes)
    2018-06-07 01:01:28 10[NET] <XXXX_ATL-1|1804> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (76 bytes)
    2018-06-07 01:01:28 10[ENC] <XXXX_ATL-1|1804> parsed INFORMATIONAL_V1 request 1674245859 [ HASH D ]
    2018-06-07 01:01:28 10[IKE] <XXXX_ATL-1|1804> received DELETE for ESP CHILD_SA with SPI db465724
    2018-06-07 01:01:28 10[IKE] <XXXX_ATL-1|1804> closing CHILD_SA XXXX_ATL-1{2268} with SPIs c4b2ff79_i (0 bytes) db465724_o (0 bytes) and TS 192.168.0.25/32 === zz.zz.zzz.z/24
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [SSO] (sso_invoke_once) SSO is disabled.
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN] (ref_counting) ref_count: 1 to 0 -- down -- (192.168.0.25/32#zz.zz.zzz.z/24)
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN] (cop_updown_invoke_once) no user identification is provided! client mode?
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN] (cop_updown_invoke_once) UID: 1804 Net: Local xx.xx.xxx.xxx Remote yy.yyy.yy.yyy Connection: XXXX_ATL Fullname: XXXX_ATL-1
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN] (cop_updown_invoke_once) Tunnel: User '' Peer-IP '' my-IP '' down-client
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][DB] (db_conn_info) hostname: 'XXXX_ATL' result --> id: '1', mode: 'ntn', tunnel_type: '0', subnet_family:'0'
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN] (cop_updown_invoke_once) ---- exec updown -- down --
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN] (cop_updown_invoke_once) [NTN] NTN get actual...
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][DB] (db_query) No data retrieved from query: 'SELECT ( nath.netid || '/' || nath.netmask ) AS natedlan FROM tblvpnconnhostrel AS rel JOIN tblhost AS h ON h.hostid = rel.hostid JOIN tblhost AS nath ON rel .natedhost = nath.hostid WHERE rel.connectionid = $1 AND rel.hostlocation = 'L' AND h.netid = $2 AND h.netmask = $3 LIMIT 1;' status: 2 rows: 0
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804>
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN] (cop_updown_invoke_once) [IPSEC0] using ipsec dummy interface 'ipsec0'
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][NET] (get_src_ip) source address for 192.168.0.25 is IP: 192.168.0.1
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804>
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) 'ip route del zz.zz.zzz.z/24 dev ipsec0 src 192.168.0.1 table 220': success 0
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN] (add_routes) no routes to del for XXXX_ATL on interface ipsec0
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) 'ip route flush cache': success 0
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) 'ip route flush cache': success 0
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) '/bin/service fwm:vpn_connection_chains -t json -s nosync -b '{"me":"xx.xx.xxx.xxx","peer":"yy.yyy.yy.yyy","mynet":"192.168.0.25/32","peernet":"zz.zz.zzz.z/24","connop":"0","iface":"unknown","myproto":"0","myport":"0","peerproto":"0","peerport":"0","conntype":"ntn","actnet":"","compress":"0","conn_id":"1"}'': success 0
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) 'conntrack -D --not-protonum=6 --inzone-outzone=2': success 0
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) 'conntrack -D --not-protonum=6 --inzone-outzone=5': error returned 1
    2018-06-07 01:01:28 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) 'conntrack -D --protonum=50': error returned 1
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) '/bin/opcode updown_vpnconn_status -t json -s nosync -b '{"connectionname":"XXXX_ATL","operation":"-","fullname":"XXXX_ATL-1"}'': success 0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) '/bin/opcode dgd_peer_disconnect -s nosync -t json -b '{"connection":"XXXX_ATL"}'': success 0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1804> [COP-UPDOWN][SHELL] (run_shell) '/bin/opcode set_timer_mail_updown -s nosync -t json -b '{"event":"down","conn":"XXXX_ATL","local_net":"192.168.0.25/32","remote_net":"zz.zz.zzz.z/24","reason":"0"}'': success 0
    2018-06-07 01:01:29 10[ENC] <XXXX_ATL-1|1804> generating QUICK_MODE request 1705534712 [ HASH SA No KE ID ID ]
    2018-06-07 01:01:29 10[NET] <XXXX_ATL-1|1804> sending packet: from xx.xx.xxx.xxx[500] to yy.yyy.yy.yyy[500] (380 bytes)
    2018-06-07 01:01:29 17[NET] <XXXX_ATL-1|1804> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (92 bytes)
    2018-06-07 01:01:29 17[ENC] <XXXX_ATL-1|1804> parsed INFORMATIONAL_V1 request 1932865524 [ HASH D ]
    2018-06-07 01:01:29 17[IKE] <XXXX_ATL-1|1804> received DELETE for IKE_SA XXXX_ATL-1[1804]
    2018-06-07 01:01:29 17[IKE] <XXXX_ATL-1|1804> deleting IKE_SA XXXX_ATL-1[1804] between xx.xx.xxx.xxx[xx.xx.xxx.xxx]...yy.yyy.yy.yyy[yy.yyy.yy.yyy]
    2018-06-07 01:01:29 17[IKE] <XXXX_ATL-1|1804> initiating Main Mode IKE_SA XXXX_ATL-1[1806] to yy.yyy.yy.yyy
    2018-06-07 01:01:29 17[ENC] <XXXX_ATL-1|1804> generating ID_PROT request 0 [ SA V V V V V V ]
    2018-06-07 01:01:29 17[NET] <XXXX_ATL-1|1804> sending packet: from xx.xx.xxx.xxx[500] to yy.yyy.yy.yyy[500] (272 bytes)
    2018-06-07 01:01:29 30[NET] <XXXX_ATL-1|1806> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (132 bytes)
    2018-06-07 01:01:29 30[ENC] <XXXX_ATL-1|1806> parsed ID_PROT response 0 [ SA V V ]
    2018-06-07 01:01:29 30[IKE] <XXXX_ATL-1|1806> received NAT-T (RFC 3947) vendor ID
    2018-06-07 01:01:29 30[IKE] <XXXX_ATL-1|1806> received FRAGMENTATION vendor ID
    2018-06-07 01:01:29 30[ENC] <XXXX_ATL-1|1806> generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
    2018-06-07 01:01:29 30[NET] <XXXX_ATL-1|1806> sending packet: from xx.xx.xxx.xxx[500] to yy.yyy.yy.yyy[500] (308 bytes)
    2018-06-07 01:01:29 28[NET] <XXXX_ATL-1|1806> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (368 bytes)
    2018-06-07 01:01:29 28[ENC] <XXXX_ATL-1|1806> parsed ID_PROT response 0 [ KE No V V V V NAT-D NAT-D ]
    2018-06-07 01:01:29 28[IKE] <XXXX_ATL-1|1806> received Cisco Unity vendor ID
    2018-06-07 01:01:29 28[IKE] <XXXX_ATL-1|1806> received XAuth vendor ID
    2018-06-07 01:01:29 28[ENC] <XXXX_ATL-1|1806> received unknown vendor ID: 31:29:ab:92:22:45:5b:f0:34:9f:29:1f:5c:74:b8:e6
    2018-06-07 01:01:29 28[ENC] <XXXX_ATL-1|1806> received unknown vendor ID: 1f:07:f7:0e:aa:65:14:d3:b0:fa:96:54:2a:50:01:00
    2018-06-07 01:01:29 28[ENC] <XXXX_ATL-1|1806> generating ID_PROT request 0 [ ID HASH ]
    2018-06-07 01:01:29 28[NET] <XXXX_ATL-1|1806> sending packet: from xx.xx.xxx.xxx[500] to yy.yyy.yy.yyy[500] (76 bytes)
    2018-06-07 01:01:29 18[NET] <XXXX_ATL-1|1806> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (92 bytes)
    2018-06-07 01:01:29 18[ENC] <XXXX_ATL-1|1806> parsed ID_PROT response 0 [ ID HASH V ]
    2018-06-07 01:01:29 18[IKE] <XXXX_ATL-1|1806> received DPD vendor ID
    2018-06-07 01:01:29 18[IKE] <XXXX_ATL-1|1806> IKE_SA XXXX_ATL-1[1806] established between xx.xx.xxx.xxx[xx.xx.xxx.xxx]...yy.yyy.yy.yyy[yy.yyy.yy.yyy]
    2018-06-07 01:01:29 18[IKE] <XXXX_ATL-1|1806> scheduling rekeying in 85927s
    2018-06-07 01:01:29 18[IKE] <XXXX_ATL-1|1806> maximum IKE_SA lifetime 86287s
    2018-06-07 01:01:29 18[ENC] <XXXX_ATL-1|1806> generating QUICK_MODE request 2455173659 [ HASH SA No KE ID ID ]
    2018-06-07 01:01:29 18[NET] <XXXX_ATL-1|1806> sending packet: from xx.xx.xxx.xxx[500] to yy.yyy.yy.yyy[500] (380 bytes)
    2018-06-07 01:01:29 08[NET] <XXXX_ATL-1|1806> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (92 bytes)
    2018-06-07 01:01:29 08[ENC] <XXXX_ATL-1|1806> parsed INFORMATIONAL_V1 request 642098215 [ HASH N((24576)) ]
    2018-06-07 01:01:29 08[IKE] <XXXX_ATL-1|1806> received (24576) notify
    2018-06-07 01:01:29 10[NET] <XXXX_ATL-1|1806> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (396 bytes)
    2018-06-07 01:01:29 10[ENC] <XXXX_ATL-1|1806> parsed QUICK_MODE response 2455173659 [ HASH SA No KE ID ID N((24576)) ]
    2018-06-07 01:01:29 10[IKE] <XXXX_ATL-1|1806> CHILD_SA XXXX_ATL-1{2270} established with SPIs c88ffcd2_i 6058c876_o and TS 192.168.0.25/32 === zz.zz.zzz.z/24
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [SSO] (sso_invoke_once) SSO is disabled.
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN] (ref_counting) ref_count: 0 to 1 ++ up ++ (192.168.0.25/32#zz.zz.zzz.z/24)
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN] (cop_updown_invoke_once) no user identification is provided! client mode?
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN] (cop_updown_invoke_once) UID: 1806 Net: Local xx.xx.xxx.xxx Remote yy.yyy.yy.yyy Connection: XXXX_ATL Fullname: XXXX_ATL-1
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN] (cop_updown_invoke_once) Tunnel: User '' Peer-IP '' my-IP '' up-client
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][DB] (db_conn_info) hostname: 'XXXX_ATL' result --> id: '1', mode: 'ntn', tunnel_type: '0', subnet_family:'0'
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN] (cop_updown_invoke_once) ---- exec updown ++ up ++
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN] (cop_updown_invoke_once) [NTN] NTN get actual...
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][DB] (db_query) No data retrieved from query: 'SELECT ( nath.netid || '/' || nath.netmask ) AS natedlan FROM tblvpnconnhostrel AS rel JOIN tblhost AS h ON h.hostid = rel.hostid JOIN tblhost AS nath ON rel .natedhost = nath.hostid WHERE rel.connectionid = $1 AND rel.hostlocation = 'L' AND h.netid = $2 AND h.netmask = $3 LIMIT 1;' status: 2 rows: 0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806>
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN] (cop_updown_invoke_once) [IPSEC0] using ipsec dummy interface 'ipsec0'
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][NET] (get_src_ip) source address for 192.168.0.25 is IP: 192.168.0.1
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806>
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) 'ip route add zz.zz.zzz.z/24 dev ipsec0 src 192.168.0.1 table 220': success 0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN] (add_routes) no routes to add for XXXX_ATL on interface ipsec0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) 'ip route flush cache': success 0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) 'ip route flush cache': success 0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) '/bin/service fwm:vpn_connection_chains -t json -s nosync -b '{"me":"xx.xx.xxx.xxx","peer":"yy.yyy.yy.yyy","mynet":"192.168.0.25/32","peernet":"zz.zz.zzz.z/24","connop":"1","iface":"Port2","myproto":"0","myport":"0","peerproto":"0","peerport":"0","conntype":"ntn","actnet":"","compress":"0","conn_id":"1"}'': success 0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) 'conntrack -D --not-protonum=6 --inzone-outzone=2': error returned 1
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) 'conntrack -D --not-protonum=6 --inzone-outzone=5': error returned 1
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) 'conntrack -D --protonum=50': error returned 1
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) '/bin/opcode updown_vpnconn_status -t json -s nosync -b '{"connectionname":"XXXX_ATL","operation":"+","fullname":"XXXX_ATL-1"}'': success 0
    2018-06-07 01:01:29 10[APP] <XXXX_ATL-1|1806> [COP-UPDOWN][SHELL] (run_shell) '/bin/opcode set_timer_mail_updown -s nosync -t json -b '{"event":"up","conn":"XXXX_ATL","local_net":"192.168.0.25/32","remote_net":"zz.zz.zzz.z/24","reason":"0"}'': success 0
    2018-06-07 01:01:29 10[ENC] <XXXX_ATL-1|1806> generating QUICK_MODE request 2455173659 [ HASH ]
    2018-06-07 01:01:29 10[NET] <XXXX_ATL-1|1806> sending packet: from xx.xx.xxx.xxx[500] to yy.yyy.yy.yyy[500] (60 bytes)
    2018-06-07 01:01:41 12[NET] <XXXX_ATL-1|1806> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (92 bytes)
    2018-06-07 01:01:41 12[ENC] <XXXX_ATL-1|1806> parsed INFORMATIONAL_V1 request 4210007371 [ HASH N(DPD) ]
    2018-06-07 01:01:41 12[ENC] <XXXX_ATL-1|1806> generating INFORMATIONAL_V1 request 2421631039 [ HASH N(DPD_ACK) ]
    2018-06-07 01:01:41 12[NET] <XXXX_ATL-1|1806> sending packet: from xx.xx.xxx.xxx[500] to yy.yyy.yy.yyy[500] (92 bytes)

  • Hi Eric,

    Thanks for providing your logs.

    It looks like it's receiving a DELETE from your remote VPN peer. You might have to gather the log entries from the other side to confirm why. It could be possible that the IPsec policies (keep alive, dead peer detection time) are mis-matching between you and your remote peer.


    2018-06-07 01:01:29 17[NET] <XXXX_ATL-1|1804> received packet: from yy.yyy.yy.yyy[500] to xx.xx.xxx.xxx[500] (92 bytes)
    2018-06-07 01:01:29 17[ENC] <XXXX_ATL-1|1804> parsed INFORMATIONAL_V1 request 1932865524 [ HASH D ]
    2018-06-07 01:01:29 17[IKE] <XXXX_ATL-1|1804> received DELETE for IKE_SA XXXX_ATL-1[1804]
    2018-06-07 01:01:29 17[IKE] <XXXX_ATL-1|1804> deleting IKE_SA XXXX_ATL-1[1804] between xx.xx.xxx.xxx[xx.xx.xxx.xxx]...yy.yyy.yy.yyy[yy.yyy.yy.

    Regards,

  • Thank you, I'll get back with what they say.

Reply Children
No Data