[strongSwan] Header verification failed and NAT mapping changed

Mon Mar 19 19:16:05 CET 2012

Hi Tobias,

> Very strange.  Due to the NAT this packet should actually be sent from
> port 4500 to port 4500.  The complete log of moon (and sun) would help
> to see whether there is something wrong with the NAT detection etc.
> 
Here are excerpts of the two log files. I tried to get similar time
slot. I also added some further 'bits' where the behaviour seems a bit
strange. Hope it helps.

-- sun ipsec.log --
Mar 19 16:15:48 sun charon: 03[CFG] received stroke: initiate 'sun-moon'
Mar 19 16:15:48 sun charon: 14[AUD] initiating IKE_SA sun-moon[1140] to
moon
Mar 19 16:15:48 sun charon: 14[AUD] initiating IKE_SA sun-moon[1140] to
moon
Mar 19 16:15:48 sun charon: 14[ENC] generating IKE_SA_INIT request 0 [
SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
Mar 19 16:15:48 sun charon: 14[NET] sending packet: from
sun[500] to moon[500]
Mar 19 16:15:48 sun charon: 17[NET] received packet: from
moon[500] to sun[500]
Mar 19 16:15:48 sun charon: 17[ENC] parsed IKE_SA_INIT response 0 [ SA
KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N((16404)) ]
Mar 19 16:15:48 sun charon: 17[IKE] remote host is behind NAT
Mar 19 16:15:48 sun charon: 17[IKE] received cert request for "C=...
Mar 19 16:15:48 sun charon: 17[IKE] sending cert request for "C=...
Mar 19 16:15:48 sun charon: 17[IKE] authentication of
'sun' (myself) with RSA signature successful
Mar 19 16:15:48 sun charon: 17[IKE] sending end entity cert "C=...
Mar 19 16:15:48 sun charon: 17[AUD] establishing CHILD_SA sun-moon
Mar 19 16:15:48 sun charon: 17[AUD] establishing CHILD_SA sun-moon
Mar 19 16:15:48 sun charon: 17[ENC] generating IKE_AUTH request 1 [ IDi
CERT CERTREQ IDr AUTH SA TSi TSr ]
Mar 19 16:15:48 sun charon: 17[NET] sending packet: from
sun[4500] to moon[4500]
Mar 19 16:15:49 sun charon: 13[NET] received packet: from
moon[4500] to sun[4500]
Mar 19 16:15:49 sun charon: 13[ENC] parsed IKE_AUTH response 1 [ IDr
CERT AUTH SA TSi TSr N(AUTH_LFT) ]
Mar 19 16:15:49 sun charon: 13[IKE] received end entity cert "C=...
Mar 19 16:15:49 sun charon: 13[CFG]   using certificate "C=...
Mar 19 16:15:49 sun charon: 13[CFG]   using trusted ca certificate
Mar 19 16:15:49 sun charon: 13[CFG] checking certificate status of
Mar 19 16:15:49 sun charon: 13[CFG] certificate status is not available
Mar 19 16:15:49 sun charon: 13[IKE] authentication of 'C=...' with RSA
signature successful
Mar 19 16:15:49 sun charon: 13[IKE] scheduling reauthentication in
3285s
Mar 19 16:15:49 sun charon: 13[IKE] maximum IKE_SA lifetime 3465s
Mar 19 16:15:49 sun charon: 13[AUD] IKE_SA sun-moon[1140] established
between sun...moon
Mar 19 16:15:49 sun charon: 13[AUD] IKE_SA sun-moon[1140] established
between sun...moon
Mar 19 16:15:49 sun charon: 13[KNL] no local address found in traffic
selector 172.18.0.0/16
Mar 19 16:15:49 sun charon: 13[KNL] no local address found in traffic
selector 172.30.0.0/24
Mar 19 16:15:49 sun charon: 13[AUD] CHILD_SA sun-moon{916} established with
SPIs cf938ad2_i c152593b_o and TS 172.16.0.0/16 172.18.0.0/16
172.30.0.0/24 === 172.17.0.0/16 172.17.0.0/16 172.17.0.0/16
Mar 19 16:15:49 sun charon: 13[AUD] CHILD_SA sun-moon{916} established with
SPIs cf938ad2_i c152593b_o and TS 172.16.0.0/16 172.18.0.0/16
172.30.0.0/24 === 172.17.0.0/16 172.17.0.0/16 172.17.0.0/16
Mar 19 16:15:49 sun charon: 13[IKE] received AUTH_LIFETIME of 3259s,
scheduling reauthentication in 3079s
Mar 19 16:16:01 sun charon: 09[ENC] header verification failed
Mar 19 16:16:01 sun charon: 09[NET] received invalid IKE header from
moon - ignored
...
Mar 19 16:29:59 sun charon: 04[KNL] creating rekey job for ESP CHILD_SA
with SPI cf938ad2 and reqid {916}
Mar 19 16:29:59 sun charon: 03[AUD] establishing CHILD_SA sun-moon{916}
Mar 19 16:29:59 sun charon: 03[AUD] establishing CHILD_SA sun-moon{916}
Mar 19 16:29:59 sun charon: 03[ENC] generating CREATE_CHILD_SA request
2 [ N(REKEY_SA) SA No TSi TSr ]
Mar 19 16:29:59 sun charon: 03[NET] sending packet: from
sun[4500] to moon[4500]
Mar 19 16:29:59 sun charon: 13[NET] received packet: from
moon[4500] to sun[4500]
Mar 19 16:29:59 sun charon: 13[ENC] parsed CREATE_CHILD_SA response 2 [
SA No TSi TSr ]
Mar 19 16:29:59 sun charon: 13[KNL] no local address found in traffic
selector 172.18.0.0/16
Mar 19 16:29:59 sun charon: 13[KNL] no local address found in traffic
selector 172.30.0.0/24
Mar 19 16:29:59 sun charon: 13[AUD] CHILD_SA sun-moon{916} established with
SPIs ced57a15_i ca5c514b_o and TS 172.16.0.0/16 172.18.0.0/16
172.30.0.0/24 === 172.17.0.0/16 172.17.0.0/16 172.17.0.0/16
Mar 19 16:29:59 sun charon: 13[AUD] CHILD_SA sun-moon{916} established with
SPIs ced57a15_i ca5c514b_o and TS 172.16.0.0/16 172.18.0.0/16
172.30.0.0/24 === 172.17.0.0/16 172.17.0.0/16 172.17.0.0/16
Mar 19 16:29:59 sun charon: 13[AUD] closing CHILD_SA sun-moon{916} with SPIs
cf938ad2_i c152593b_o and TS 172.16.0.0/16 172.18.0.0/16 172.30.0.0/24
=== 172.17.0.0/16 172.17.0.0/16 172.17.0.0/16
Mar 19 16:29:59 sun charon: 13[AUD] closing CHILD_SA sun-moon{916} with SPIs
cf938ad2_i c152593b_o and TS 172.16.0.0/16 172.18.0.0/16 172.30.0.0/24
=== 172.17.0.0/16 172.17.0.0/16 172.17.0.0/16
Mar 19 16:29:59 sun charon: 13[IKE] sending DELETE for ESP CHILD_SA
with SPI cf938ad2
Mar 19 16:29:59 sun charon: 13[ENC] generating INFORMATIONAL request 3
[ D ]
Mar 19 16:29:59 sun charon: 13[NET] sending packet: from
sun[4500] to moon[4500]
Mar 19 16:29:59 sun charon: 15[NET] received packet: from
moon[4500] to sun[4500]
Mar 19 16:29:59 sun charon: 15[ENC] parsed INFORMATIONAL response 3 [ D
]
Mar 19 16:29:59 sun charon: 15[IKE] received DELETE for ESP CHILD_SA
with SPI c152593b
Mar 19 16:29:59 sun charon: 15[AUD] CHILD_SA closed
Mar 19 16:29:59 sun charon: 15[AUD] CHILD_SA closed

-- moon ipsec.log --
Mar 19 16:12:07 moon charon: 14[NET] sending packet: from
192.168.2.17[4500] to sun[500]
Mar 19 16:12:11 moon charon: 01[KNL] NAT mappings of ESP CHILD_SA
with SPI cadd18c0 and reqid {817} changed, queuing update job
Mar 19 16:13:16  charon: last message repeated 104 times
Mar 19 16:13:21 moon charon: 01[KNL] NAT mappings of ESP CHILD_SA
with SPI cadd18c0 and reqid {817} changed, queuing update job
Mar 19 16:13:23 moon charon: 01[KNL] creating delete job for ESP
CHILD_SA with SPI c6ca2843 and reqid {817}
Mar 19 16:13:23 moon charon: 09[IKE] giving up after 5 retransmits
Mar 19 16:13:23 moon vpn: - sun 172.16.0.0/16 ==
sun -- 192.168.2.17 == 172.17.0.0/16
Mar 19 16:13:23 moon vpn: - sun 172.18.0.0/16 ==
sun -- 192.168.2.17 == 172.17.0.0/16
Mar 19 16:13:23 moon vpn: - sun 172.30.0.0/24 ==
sun -- 192.168.2.17 == 172.17.0.0/16
Mar 19 16:13:23 moon charon: 01[KNL] NAT mappings of ESP CHILD_SA
with SPI cadd18c0 and reqid {817} changed, queuing update job
Mar 19 16:13:23 moon charon: 09[KNL] received netlink error: No such
process (3)
Mar 19 16:13:23 moon charon: 09[KNL] unable to delete SAD entry with
SPI c6ca2843
Mar 19 16:13:23 moon charon: 10[JOB] CHILD_SA with reqid 817 not
found for update
Mar 19 16:13:23 moon charon: 01[KNL] NAT mappings of ESP CHILD_SA
with SPI cadd18c0 and reqid {817} changed, queuing update job
Mar 19 16:13:23 moon charon: 09[JOB] CHILD_SA with reqid 817 not
found for update
Mar 19 16:13:29 moon charon: 01[KNL] creating acquire job for policy
172.17.0.1/32[tcp] === 172.16.0.24/32[tcp/ldap] with reqid {817}
Mar 19 16:13:29 moon charon: 12[CFG] trap not found, unable to
acquire reqid 817
Mar 19 16:15:47 moon charon: 09[NET] received packet: from
sun[500] to 192.168.2.17[500]
Mar 19 16:15:47 moon charon: 09[ENC] parsed IKE_SA_INIT request 0 [
SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
Mar 19 16:15:47 moon charon: 09[IKE] sun is initiating an
IKE_SA
Mar 19 16:15:47 moon charon: 09[IKE] sun is initiating an
IKE_SA
Mar 19 16:15:47 moon charon: 09[IKE] local host is behind NAT,
sending keep alives
Mar 19 16:15:47 moon charon: 09[IKE] sending cert request for "C=...
Mar 19 16:15:47 moon charon: 09[ENC] generating IKE_SA_INIT response
0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ]
Mar 19 16:15:47 moon charon: 09[NET] sending packet: from
192.168.2.17[500] to sun[500]
Mar 19 16:15:47 moon charon: 12[NET] received packet: from
sun[4500] to 192.168.2.17[4500]
Mar 19 16:15:47 moon charon: 12[ENC] parsed IKE_AUTH request 1 [ IDi
CERT CERTREQ IDr AUTH SA TSi TSr ]
Mar 19 16:15:47 moon charon: 12[IKE] received cert request for "C=...
Mar 19 16:15:47 moon charon: 12[IKE] received end entity cert "C=...
Mar 19 16:15:47 moon charon: 12[CFG] looking for peer configs
matching 192.168.2.17[moon]...sun[sun]
Mar 19 16:15:47 moon charon: 12[CFG] selected peer config
'moon-sun'
Mar 19 16:15:47 moon charon: 12[CFG]   using certificate "C=...
Mar 19 16:15:47 moon charon: 12[CFG]   using trusted ca certificate
Mar 19 16:15:47 moon charon: 12[CFG] checking certificate status of
Mar 19 16:15:47 moon charon: 12[CFG] certificate status is not
available
Mar 19 16:15:47 moon charon: 12[CFG]   reached self-signed root ca
with a path length of 0
Mar 19 16:15:47 moon charon: 12[IKE] authentication of
'sun' with RSA signature successful
Mar 19 16:15:48 moon charon: 12[IKE] authentication of 'C=...
, CN=moon' (myself)
with RSA signature successful
Mar 19 16:15:48 moon charon: 12[IKE] IKE_SA moon-sun[809]
established between 192.168.2.17[CN=moon]...sun[sun]
Mar 19 16:15:48 moon charon: 12[IKE] IKE_SA moon-sun[809]
established between 192.168.2.17[ CN=moon]...sun[sun]
Mar 19 16:15:48 moon charon: 12[IKE] scheduling reauthentication in
3259s
Mar 19 16:15:48 moon charon: 12[IKE] maximum IKE_SA lifetime 3439s
Mar 19 16:15:48 moon charon: 12[IKE] sending end entity cert "C=...
Mar 19 16:15:48 moon charon: 12[IKE] CHILD_SA moon-sun{818}
established with SPIs c152593b_i cf938ad2_o and TS 172.17.0.0/16 ===
172.16.0.0/16 172.18.0.0/16 172.30.0.0/24
Mar 19 16:15:48 moon vpn: + sun 172.16.0.0/16 ==
sun -- 192.168.2.17 == 172.17.0.0/16
Mar 19 16:15:48 moon vpn: + sun 172.18.0.0/16 ==
sun -- 192.168.2.17 == 172.17.0.0/16
Mar 19 16:15:48 moon vpn: + sun 172.30.0.0/24 ==
sun -- 192.168.2.17 == 172.17.0.0/16
Mar 19 16:15:48 moon charon: 12[IKE] CHILD_SA moon-sun{818}
established with SPIs c152593b_i cf938ad2_o and TS 172.17.0.0/16 ===
172.16.0.0/16 172.18.0.0/16 172.30.0.0/24
Mar 19 16:15:48 moon charon: 12[ENC] generating IKE_AUTH response 1 [
IDr CERT AUTH SA TSi TSr N(AUTH_LFT) ]
Mar 19 16:15:48 moon charon: 12[NET] sending packet: from
192.168.2.17[4500] to sun[4500]
Mar 19 16:15:49 moon charon: 01[KNL] NAT mappings of ESP CHILD_SA
with SPI c152593b and reqid {818} changed, queuing update job

> > Mar 19 11:02:46 moon charon: 01[KNL] NAT mappings of ESP CHILD_SA
> > with SPI c2aa0995 and reqid {804} changed, queuing update job
> 
> This seems strange too as this should not really happen for the host
> *behind* the NAT (unless the other end is natted too, of course) - and
> only if the actual endpoints have changed.  A possible reason could be
> that sun sends ESP packets from port 4500 while moon has port 500
> configured (if the port used above is any indication).
sun is connected via a router directly to the internet and holds a
public IP.

moon is connected to the internet via a NAT ADSL-Router/Modem
Combination with port forwarding on UDP 500 and UDP 4500 to moon.

What I also noticed in this setup, that if both sides only call
auto=route in the configuration I can see the configuration with ipsec
statusall, but no SA is installed on receiving traffic to the other
network.

Cheers,
Kim
> 
> 
> _______________________________________________
> Users mailing list
> Users at lists.strongswan.org
> https://lists.strongswan.org/mailman/listinfo/users
> 