[Swan-dev] IKEv1: Remove all IPsec SA's of a connection when newest SA is removedrefs/heads/master

Wed Aug 26 17:48:49 EEST 2015

On Wed, Aug 26, 2015 at 10:25:22AM -0400, Paul Wouters wrote:
> On Wed, 26 Aug 2015, Lennart Sorensen wrote:
> 
> >Aug  5 14:50:13 ruggedcom pluto[8239]: "Test" #3: ignoring Delete SA payload:
> >PROTO_IPSEC_ESP SA(0xbd111c17) not found (our SPI - bogus implementation)
> >Aug  5 14:50:13 ruggedcom pluto[8239]: "Test" #3: received and ignored
> >informational message
> 
> Ahhh. maybe this is the source of the problem. We are not deleting the
> IPsec SA because they used the wrong SPI number to send the delete.
> 
> I guess we could use our spi to lookup their spi, and if we find
> something that's covered under the same ISKAMP SA (eg st_clonedfrom)
> then delete it anyway.

That might work.

> >192.168.30.0/24===192.168.10.1<192.168.10.1>[+S=C]...192.168.10.2<192.168.10.2>[+S=C]===192.168.20.0/24;
> >prospective erouted; eroute owner: #0
> >       000 #4: "Test":500 STATE_QUICK_R2 (IPsec SA established);
> >EVENT_SA_REPLACE in 3143s; isakmp#3; idle; import:not set
> >       000 #4: "Test" esp.a405e7fb at 192.168.10.2 esp.d35ec5e5 at 192.168.10.1
> >tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761
> >       000 #3: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established);
> >EVENT_SA_REPLACE in 3142s; newest ISAKMP; lastdpd=52s(seq in:0 out:0); idle;
> >import:not set
> >       000 #2: "Test":500 STATE_QUICK_R2 (IPsec SA established);
> >EVENT_SA_REPLACE in 3072s; isakmp#1; idle; import:not set
> >       000 #2: "Test" esp.169405af at 192.168.10.2 esp.2bb99e85 at 192.168.10.1
> >tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761
> >       000 #1: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established);
> >EVENT_SA_REPLACE in 3071s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
> 
> Although why am I not seeing the spi 0xbd111c17 anywhere? Does your bug
> report have more plutologs that we can trace down 0xbd111c17 and see if
> this is indeed an ESP SPI and not an ISAKMPD SPI?

Well here are some:

auth.log:
Aug 11 09:07:23 ruggedcom confd[3399]: audit user: system/762 Logged out from maapi ctx=system (closed)
Aug 11 09:07:23 ruggedcom confd[3399]: audit user: system/763 Logged out from maapi ctx=system (closed)
Aug 11 09:08:19 ruggedcom confd[3399]: audit user: system/766 Logged out from maapi ctx=system (closed)
Aug 11 09:08:19 ruggedcom confd[3399]: audit user: system/767 Logged out from maapi ctx=system (closed)
Aug 11 09:08:21 ruggedcom pluto[25039]: packet from 192.168.10.2:500: received Vendor ID payload [RFC 3947] meth=109, but port floating is off
Aug 11 09:08:21 ruggedcom pluto[25039]: packet from 192.168.10.2:500: ignoring unknown Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Aug 11 09:08:21 ruggedcom pluto[25039]: packet from 192.168.10.2:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but port floating is off
Aug 11 09:08:21 ruggedcom pluto[25039]: packet from 192.168.10.2:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but port floating is off
Aug 11 09:08:21 ruggedcom pluto[25039]: "Test" #43: responding to Main Mode
Aug 11 09:08:21 ruggedcom pluto[25039]: "Test" #43: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Aug 11 09:08:21 ruggedcom pluto[25039]: "Test" #43: STATE_MAIN_R1: sent MR1, expecting MI2
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: received Vendor ID payload [Dead Peer Detection]
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: ignoring unknown Vendor ID payload [39dd469d609b7bda870fb25f6123a1d3]
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: received Vendor ID payload [XAUTH]
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: STATE_MAIN_R2: sent MR2, expecting MI3
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: ignoring informational payload, type IPSEC_INITIAL_CONTACT msgid=00000000
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: Main mode peer ID is ID_IPV4_ADDR: '192.168.10.2'
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_md5 group=modp1536}
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: the peer proposed: 192.168.30.0/24:0/0 -> 192.168.20.0/24:0/0
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: responding to Quick Mode proposal {msgid:58750a85}
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44:     us: 192.168.30.0/24===192.168.10.1<192.168.10.1>[+S=C]
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44:   them: 192.168.10.2<192.168.10.2>[+S=C]===192.168.20.0/24
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: keeping refhim=4294901761 during rekey
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: the peer proposed: 192.168.30.0/24:0/0 -> 192.168.20.0/24:0/0
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: responding to Quick Mode proposal {msgid:ae48e9ab}
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45:     us: 192.168.30.0/24===192.168.10.1<192.168.10.1>[+S=C]
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45:   them: 192.168.10.2<192.168.10.2>[+S=C]===192.168.20.0/24
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: keeping refhim=4294901761 during rekey
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0xe701c648 <0x43b180e5 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
Aug 11 09:08:23 ruggedcom pluto[25039]: "Test" #45: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Aug 11 09:08:23 ruggedcom pluto[25039]: "Test" #45: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0x20e9b4b8 <0x65bd9c08 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}

I think the test would have to be run again to get more logs.

> >Debug on cisco suggesting that RC device is responding to DPD message with
> >correct sequence number even when the tunnel is in the state of "Prespective
> >erouted"
> 
> Well, the ISAKMP SA is still up, so it should?

Yes, but the user isn't happy with the result since it thinks the
connection is fine when it isn't.

-- 
Len Sorensen