[strongSwan] received retransmit of response with ID 0, but next request already sent

[Thomas Egerer]

Hi Axel,

On 10/28/2014 07:11 PM, Axel Zöllich wrote:
> Hi Thomas,
> 
>>>> Can you please do the following:
>>>> 'ipsec stroke loglevel ike 4' # this should show us the
>>>> keying material (unlike my first advice it's the ike
>>>> facility, not the enc facility).
>>>>
>>>>
>>>> Then try to get your draytek to initiate the connection
>>>> so we can see if the packets can be
>>>> a) decrypted
>>>> b) authenticated using PSK
> 
> 
> 1831_charon.log: Connection initiated through a cleint behind the draytek. 
> This one seems to work well.

Yes, the CHILD_SA (aka quick mode) is established just fine:
Oct 27 17:22:17 02[IKE] <jung|1831> CHILD_SA jung{138} established
    with SPIs c425b5e3_i bf113ad0_o and TS 192.168.222.0/24 === 192.168.1.0/24

it is however torn down just a minute later:
Oct 27 17:23:16 04[IKE] <jung|1831> queueing QUICK_DELETE task

and I cannot see why from the log (it looks filtered, maybe it's
some inactivity DPD-timeout?)
And the good news is, that it's being used:
<snip>
       jung{157}:  INSTALLED, TUNNEL, ESP SPIs: c26199e4_i bf114b96_o
        jung{157}:  3DES_CBC/HMAC_SHA1_96, 1156392 bytes_i (21119 pkts, 0s
ago), 39480312 bytes_o (38561 pkts, 0s ago), rekeying in 5 hours
<snap>
You could use iproute2 to check for potential errors in decryption/
auth by calling 'ip -s x s s' (check out 'ip x s h' for information
on how to filter the results).

> 1875_charon.log: Initiated from my side.
> the first attempt stays in "connecting" state the second one succeeds.
> 
> initiating Main Mode IKE_SA jung[1876] to 217.86.257.203
> generating ID_PROT request 0 [ SA V V V V ]
> sending packet: from 80.152.262.292[500] to 217.86.257.203[500] (192 bytes)
> received packet: from 217.86.257.203[500] to 80.252.162.292[500] (124 bytes)
> parsed ID_PROT response 0 [ SA V V ]
> received DPD vendor ID
> received NAT-T (RFC 3947) vendor ID
> generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
> sending packet: from 80.152.262.292[500] to 217.86.257.203[500] (372 bytes)
> received packet: from 217.86.257.203[500] to 80.152.262.292[500] (356 bytes)
> parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
> generating ID_PROT request 0 [ ID HASH ]
> sending packet: from 80.152.262.292[500] to 217.86.257.203[500] (68 bytes)
> received packet: from 217.86.257.203[500] to 80.152.262.292[500] (356 bytes)
> received retransmit of response with ID 0, but next request already sent
> 
> Security Associations (4 up, 0 connecting):
>         jung[1879]: ESTABLISHED 7 minutes ago, 
> 80.152.262.292[217.86.257.203]...217.86.257.203[217.86.257.203]
>         jung[1879]: IKEv1 SPIs: add629d01fbfff80_i 04f9c350f91efff4_r*, rekeying 
> in 23 hours
>         jung[1879]: IKE proposal: 3DES_CBC/HMAC_MD5_96/PRF_HMAC_MD5/MODP_1536
>         jung{157}:  INSTALLED, TUNNEL, ESP SPIs: c26199e4_i bf114b96_o
>         jung{157}:  3DES_CBC/HMAC_SHA1_96, 1156392 bytes_i (21119 pkts, 0s 
> ago), 39480312 bytes_o (38561 pkts, 0s ago), rekeying in 5 hours
>         jung{157}:   192.168.222.0/24 === 192.168.1.0/24 
>         jung[1876]: CONNECTING, 
> 80.152.162.192[217.86.257.203]...217.86.257.203[%any]
>         jung[1876]: IKEv1 SPIs: 133dde7fcdc170c2_i* 55906950f6a25cef_r
>         jung[1876]: IKE proposal: 
> 3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
>         jung[1876]: Tasks queued: QUICK_MODE 
>         jung[1876]: Tasks active: ISAKMP_VENDOR MAIN_MODE 
> 
> 
> After some cycles like 1875 there are only "connecting" tries left.

Again: I can't see from the log why the ESTABLISHED SAs get torn down.

Let's summarize: Dray acting as initiator seems to work (you should
get traffic through the tunnel), the tunnel won't persist for long.
Charon being initiator won't work since Dray seems to refuse to
establish the CHILD (hence the retransmits, I guess). So it's
definitely not a problem with the IKE-Keys and most likely none with
the CHILD-keys, too.
When it comes to the retransmissions of the Dray, it looks to me like
a misbehaving state machine on it's side. IKE-SA, as well as CHILD_SA
are established (lines 333, 334 resp. 357 in the 1875 log), yet it
keeps retransmitting the packets (that's why charon can't retransmit
the appropriate response: 'received retransmit of response with ID 0,\
   but next request already sent'
I don't want to point any fingers but it looks like a problem on
their side. Maybe they already know about that. You should contact
them and ask for support.
Quite frankely, I'm out of ideas here.

Cheers,
Thomas