[Openswan Users] WG: openswan 2.6.45 : Tunnel gets established and is working but only until first IPsec SA expires

Tue Sep 15 02:05:43 EDT 2015

Hi all 

We are experiencing strange problems with IPsec on our gateway. The configuration used has been working up to openswan 2.6.43 without any known issues:

#--------------------------------------------------
ipsec02:~ # cat /etc/ipsec.conf
# /etc/ipsec.conf - Openswan IPsec configuration file

# This file:  /usr/local/share/doc/openswan/ipsec.conf-sample
#
# Manual:     ipsec.conf.5

version 2.0     # conforms to second version of ipsec.conf specification

# basic configuration
config setup
        # Do not set debug options to debug configuration issues!
        # plutodebug / klipsdebug = "all", "none" or a combation from below:
        # "raw crypt parsing emitting control klips pfkey natt x509 dpd private"
        # eg:
        # plutodebug="control parsing"
        # Again: only enable plutodebug or klipsdebug when asked by a developer
        #
        # enable to get logs per-peer
        # plutoopts="--perpeerlog"
        #
        # Enable core dumps (might require system changes, like ulimit -C)
        # This is required for abrtd to work properly
        # Note: incorrect SElinux policies might prevent pluto writing the core
        dumpdir=/var/run/pluto/
        #
        # NAT-TRAVERSAL support, see README.NAT-Traversal
        nat_traversal=yes
        # exclude networks used on server side by adding %v4:!a.b.c.0/24
        # It seems that T-Mobile in the US and Rogers/Fido in Canada are
        # using 25/8 as "private" address space on their 3G network.
        # This range has not been announced via BGP (at least upto 2010-12-21)
        virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12,%v4:25.0.0.0/8,%v6:fd00::/8,%v6:fe80::/10
        # OE is now off by default. Uncomment and change to on, to enable.
        oe=off
        # which IPsec stack to use. auto will try netkey, then klips then mast
        protostack=netkey
        # Use this to log to a file, or disable logging on embedded systems (like openwrt)
        #plutostderrlog=/dev/null

.

conn CONN_IPSECT1_IPSEC02
        leftid=@ipsec02.lotto-rlp.de
        left=194.25.170.40
        leftsubnet=192.168.129.10/32
        leftnexthop=194.25.170.33
        leftrsasigkey=%cert
        leftcert=certs/ipsec02-2008-cert.pem
        rightid=@ipsect1.lotto-rlp.de
        right=194.113.173.41
        rightsubnet=192.168.1.12/32
        rightrsasigkey=%cert
        keylife=10m
        auto=add

#--------------------------------------------------

This is what we do : 

On a running pluto we raise mentioned connection, for fast problem cycling it has a keylife of only 10 minutes (problem occurs with regular keylife of 2 hours as well). The tunnel gets established and is working. Once the first EVENT_SA_EXPIRE occurs, SA is replaced, established, but tunnel fails afterwards :     

#--------------------------------------------------

Mon Sep 14 13:29:05 CEST 2015
000 #3: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 66s; newest IPSEC; isakmp#1; idle; import:admin initiate
000 #2: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_QUICK_I2 (sent QI2, IPsec SA established); EVENT_SA_EXPIRE in 5s; isakmp#1; idle; import:admin initiate
000 #1: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_MAIN_I4 (ISAKMP SA established); EVENT_SA_REPLACE in 2426s; newest ISAKMP; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate

PING 192.168.1.12 (192.168.1.12) from 192.168.129.10 : 56(84) bytes of data.
64 bytes from 192.168.1.12: icmp_seq=1 ttl=64 time=13.0 ms
64 bytes from 192.168.1.12: icmp_seq=2 ttl=64 time=13.0 ms
64 bytes from 192.168.1.12: icmp_seq=3 ttl=64 time=13.0 ms
64 bytes from 192.168.1.12: icmp_seq=4 ttl=64 time=12.9 ms
64 bytes from 192.168.1.12: icmp_seq=5 ttl=64 time=13.1 ms

--- 192.168.1.12 ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 4004ms
rtt min/avg/max/mdev = 12.947/13.040/13.102/0.055 ms

Mon Sep 14 13:29:09 CEST 2015
000 #3: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 62s; newest IPSEC; isakmp#1; idle; import:admin initiate
000 #2: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_QUICK_I2 (sent QI2, IPsec SA established); EVENT_SA_EXPIRE in 1s; isakmp#1; idle; import:admin initiate
000 #1: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_MAIN_I4 (ISAKMP SA established); EVENT_SA_REPLACE in 2422s; newest ISAKMP; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate

PING 192.168.1.12 (192.168.1.12) from 192.168.129.10 : 56(84) bytes of data.
64 bytes from 192.168.1.12: icmp_seq=1 ttl=64 time=13.1 ms

--- 192.168.1.12 ping statistics ---
5 packets transmitted, 1 received, 80% packet loss, time 4001ms                  # !!!!!!!!!!!!!!!!!!!!!!!!!
rtt min/avg/max/mdev = 13.115/13.115/13.115/0.000 ms

Mon Sep 14 13:29:14 CEST 2015
000 #3: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 57s; newest IPSEC; isakmp#1; idle; import:admin initiate
000 #1: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_MAIN_I4 (ISAKMP SA established); EVENT_SA_REPLACE in 2417s; newest ISAKMP; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate

PING 192.168.1.12 (192.168.1.12) from 192.168.129.10 : 56(84) bytes of data.

--- 192.168.1.12 ping statistics ---
5 packets transmitted, 0 received, 100% packet loss, time 4000ms

#--------------------------------------------------

.

When SA replacement occurs, tunnel resumes working again. The cycle begins again with occuring of next expiration leading to tunnel failure. Please note that both IPsec and ISAKMP SA remain established all of the time:

#--------------------------------------------------

PING 192.168.1.12 (192.168.1.12) from 192.168.129.10 : 56(84) bytes of data.

--- 192.168.1.12 ping statistics ---
5 packets transmitted, 0 received, 100% packet loss, time 4000ms

Mon Sep 14 13:30:10 CEST 2015
000 #3: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 1s; newest IPSEC; isakmp#1; idle; import:admin initiate
000 #1: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_MAIN_I4 (ISAKMP SA established); EVENT_SA_REPLACE in 2361s; newest ISAKMP; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate

PING 192.168.1.12 (192.168.1.12) from 192.168.129.10 : 56(84) bytes of data.    # !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
64 bytes from 192.168.1.12: icmp_seq=3 ttl=64 time=13.1 ms
64 bytes from 192.168.1.12: icmp_seq=4 ttl=64 time=12.9 ms
64 bytes from 192.168.1.12: icmp_seq=5 ttl=64 time=13.1 ms

--- 192.168.1.12 ping statistics ---
5 packets transmitted, 3 received, 40% packet loss, time 4002ms
rtt min/avg/max/mdev = 12.996/13.109/13.172/0.154 ms

Mon Sep 14 13:30:15 CEST 2015
000 #4: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_QUICK_I2 (sent QI2, IPsec SA established); EVENT_SA_EXPIRE in 596s; newest IPSEC; isakmp#1; idle; import:admin initiate
000 #3: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_EXPIRE in 266s; isakmp#1; idle; import:admin initiate
000 #1: "CONN_IPSECT1_IPSEC02":500 IKEv1.0 STATE_MAIN_I4 (ISAKMP SA established); EVENT_SA_REPLACE in 2356s; newest ISAKMP; lastdpd=-1s(seq in:0 out:0); idle; import:admin initiate

PING 192.168.1.12 (192.168.1.12) from 192.168.129.10 : 56(84) bytes of data.
64 bytes from 192.168.1.12: icmp_seq=1 ttl=64 time=13.2 ms
64 bytes from 192.168.1.12: icmp_seq=2 ttl=64 time=13.0 ms
64 bytes from 192.168.1.12: icmp_seq=3 ttl=64 time=13.1 ms
64 bytes from 192.168.1.12: icmp_seq=4 ttl=64 time=13.1 ms
64 bytes from 192.168.1.12: icmp_seq=5 ttl=64 time=13.0 ms

#--------------------------------------------------