IPSec troubles

miken32 · Dec 4, 2014, 5:56 PM

Just setting up my first 2.2 install, trying to tunnel to our Cisco ASA. The tunnel seems to drop partially at times – I'm not well versed in this stuff by any means, so forgive me for not knowing the terminology.

Under Status/IPSec, if the tunnel is working, there is an option to "Show child SA entries." When I come in in the mornings, that option is not there and I can't reach anything on the other side of the tunnel, though it shows as being up. Disconnecting and reconnecting manually brings everything back up.

P1: IKE v2, mutual PSK, AES 256, SHA512, DH 14
P2: tunnel, ESP, AES 256, SHA512, PFS group 14

No logs yet, as the IPSec logging seems very verbose. Will get logging sent to a remote syslog server if it will help…

miken32 · Dec 8, 2014, 5:25 PM

This is what the log file looks like when the tunnel times out and tries to restart automatically:

Dec 8 03:17:21 charon: 03[KNL] creating acquire job for policy 1.2.3.4/32|/0 === 9.8.7.6/32|/0 with reqid {1}
Dec 8 03:17:21 charon: 05[IKE] <con1|174>establishing CHILD_SA con1{1}
Dec 8 03:17:21 charon: 05[IKE] establishing CHILD_SA con1{1}
Dec 8 03:17:21 charon: 05[ENC] generating CREATE_CHILD_SA request 482 [ N(ESP_TFC_PAD_N) SA No TSi TSr ]
Dec 8 03:17:21 charon: 05[NET] sending packet: from 1.2.3.4[4500] to 9.8.7.6[4500] (240 bytes)
Dec 8 03:17:21 charon: 05[NET] received packet: from 9.8.7.6[4500] to 1.2.3.4[4500] (80 bytes)
Dec 8 03:17:21 charon: 05[ENC] parsed CREATE_CHILD_SA response 482 [ N(NO_PROP) ]
Dec 8 03:17:21 charon: 05[IKE] <con1|174>received NO_PROPOSAL_CHOSEN notify, no CHILD_SA built
Dec 8 03:17:21 charon: 05[IKE] received NO_PROPOSAL_CHOSEN notify, no CHILD_SA built
Dec 8 03:17:21 charon: 05[IKE] <con1|174>failed to establish CHILD_SA, keeping IKE_SA
Dec 8 03:17:21 charon: 05[IKE] failed to establish CHILD_SA, keeping IKE_SA

And for a manual start of the tunnel:

Dec 8 09:14:49 charon: 16[CFG] received stroke: initiate 'con1'
Dec 8 09:14:49 charon: 10[IKE] <con1|177>initiating IKE_SA con1[177] to 9.8.7.6
Dec 8 09:14:49 charon: 10[IKE] initiating IKE_SA con1[177] to 9.8.7.6
Dec 8 09:14:49 charon: 10[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) ]
Dec 8 09:14:49 charon: 10[NET] sending packet: from 1.2.3.4[500] to 9.8.7.6[500] (376 bytes)
Dec 8 09:14:49 charon: 10[NET] received packet: from 9.8.7.6[500] to 1.2.3.4[500] (521 bytes)
Dec 8 09:14:49 charon: 10[ENC] parsed IKE_SA_INIT response 0 [ SA KE No V V V N(NATD_S_IP) N(NATD_D_IP) V ]
Dec 8 09:14:49 charon: 10[IKE] <con1|177>received Cisco Delete Reason vendor ID
Dec 8 09:14:49 charon: 10[IKE] received Cisco Delete Reason vendor ID
Dec 8 09:14:49 charon: 10[IKE] <con1|177>received Cisco Copyright 2009 vendor ID
Dec 8 09:14:49 charon: 10[IKE] received Cisco Copyright 2009 vendor ID
Dec 8 09:14:49 charon: 10[ENC] received unknown vendor ID: 43:49:53:43:4f:2d:47:52:45:2d:4d:4f:44:45:02
Dec 8 09:14:49 charon: 10[IKE] <con1|177>received FRAGMENTATION vendor ID
Dec 8 09:14:49 charon: 10[IKE] received FRAGMENTATION vendor ID
Dec 8 09:14:49 charon: 10[IKE] <con1|177>authentication of '1.2.3.4' (myself) with pre-shared key
Dec 8 09:14:49 charon: 10[IKE] authentication of '1.2.3.4' (myself) with pre-shared key
Dec 8 09:14:49 charon: 10[IKE] <con1|177>establishing CHILD_SA con1
Dec 8 09:14:49 charon: 10[IKE] establishing CHILD_SA con1
Dec 8 09:14:49 charon: 10[ENC] generating IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(EAP_ONLY) ]
Dec 8 09:14:49 charon: 10[NET] sending packet: from 1.2.3.4[4500] to 9.8.7.6[4500] (272 bytes)
Dec 8 09:14:49 charon: 10[NET] received packet: from 9.8.7.6[4500] to 1.2.3.4[4500] (256 bytes)
Dec 8 09:14:49 charon: 10[ENC] parsed IKE_AUTH response 1 [ V IDr AUTH SA TSi TSr N(ESP_TFC_PAD_N) N(NON_FIRST_FRAG) ]
Dec 8 09:14:49 charon: 10[IKE] <con1|177>authentication of '9.8.7.6' with pre-shared key successful
Dec 8 09:14:49 charon: 10[IKE] authentication of '9.8.7.6' with pre-shared key successful
Dec 8 09:14:49 charon: 10[IKE] <con1|177>IKE_SA con1[177] established between 1.2.3.4[1.2.3.4]…9.8.7.6[9.8.7.6]
Dec 8 09:14:49 charon: 10[IKE] IKE_SA con1[177] established between 1.2.3.4[1.2.3.4]…9.8.7.6[9.8.7.6]
Dec 8 09:14:49 charon: 10[IKE] <con1|177>scheduling reauthentication in 27966s
Dec 8 09:14:49 charon: 10[IKE] scheduling reauthentication in 27966s
Dec 8 09:14:49 charon: 10[IKE] <con1|177>maximum IKE_SA lifetime 28506s
Dec 8 09:14:49 charon: 10[IKE] maximum IKE_SA lifetime 28506s
Dec 8 09:14:49 charon: 10[IKE] <con1|177>received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
Dec 8 09:14:49 charon: 10[IKE] received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
Dec 8 09:14:49 charon: 10[IKE] <con1|177>CHILD_SA con1{1} established with SPIs cbbb4fef_i 2dec761d_o and TS 192.168.244.0/24|/0 === 192.168.242.0/24|/0
Dec 8 09:14:49 charon: 10[IKE] CHILD_SA con1{1} established with SPIs cbbb4fef_i 2dec761d_o and TS 192.168.244.0/24|/0 === 192.168.242.0/24|/0</con1|177></con1|177></con1|177></con1|177></con1|177></con1|177></con1|177></con1|177></con1|177></con1|177></con1|177></con1|177></con1|174></con1|174></con1|174>

cmb · Dec 8, 2014, 5:34 PM

The ASA logs would be more telling, it's sending back a "no proposal chosen" which means it's claiming the proposal doesn't match anything it has configured, the question is why. ASAs are easy to configure in such a way that they'll use diff settings as initiator than responder, which is usually what causes issues along those lines.

miken32 · Dec 8, 2014, 9:54 PM

Syslog would only say this:

Dec 8 16:19:01 192.168.242.1 %ASA-3-751022: Local:9.8.7.6:4500 Remote:1.2.3.4:4500 Username:1.2.3.4 IKEv2 Tunnel rejected: Crypto Map Policy not found for remote traffic selector 192.168.244.0/192.168.244.255/0/65535/0 local traffic selector 192.168.242.0/192.168.242.255/0/65535/0!
Dec 8 16:19:01 192.168.242.1 %ASA-4-750003: Local:9.8.7.6:4500 Remote:1.2.3.4:4500 Username:1.2.3.4 IKEv2 Negotiation aborted due to ERROR: Failed to find a matching policy

But debug from the console says:

IKEv2-PROTO-1: (48): Failed to find a matching policy
IKEv2-PROTO-1: (48): Received Policies:
ESP: Proposal 1: AES-CBC-256 SHA512 DH_GROUP_2048_MODP/Group 14 Don't use ESN

ESP: Proposal 2: AES-GCM-256 DH_GROUP_2048_MODP/Group 14 Don't use ESN

IKEv2-PROTO-1: (48): Failed to find a matching policy
IKEv2-PROTO-1: (48): Expected Policies:
IKEv2-PROTO-1: (48): Failed to find a matching policy
IKEv2-PROTO-1: (48):
IKEv2-PROTO-1: (48): Create child exchange failed
IKEv2-PROTO-1: (48):

I guess the lack of anything listed after "expected policies" suggests it must be a configuration issue on my Cisco, and not a pfSense problem. No idea what it could be though.

miken32 · Dec 10, 2014, 12:54 AM

@cmb:

ASAs are easy to configure in such a way that they'll use diff settings as initiator than responder

I'd be curious to have you expand on that. BTW debug from the Cisco is here: http://pastebin.com/egAZmYFu

Cisco config looks like this:


object network Victoria-network
 subnet 192.168.244.0 255.255.255.0
 description Victoria office subnet
object network NOC-network
 subnet 192.168.242.0 255.255.255.0
 description NOC management subnet

nat (INSIDE,OUTSIDE) source static NOC-network NOC-network destination static Victoria-network Victoria-network no-proxy-arp route-lookup

access-list OUTSIDE_cryptomap extended permit ip 192.168.242.0 255.255.255.0 object Victoria-network 

crypto ipsec ikev2 ipsec-proposal AES256-SHA256
 protocol esp encryption aes-256
 protocol esp integrity sha-512

crypto map OUTSIDE_map 1 match address OUTSIDE_cryptomap
crypto map OUTSIDE_map 1 set pfs group14
crypto map OUTSIDE_map 1 set peer 1.2.3.4 
crypto map OUTSIDE_map 1 set ikev2 ipsec-proposal AES256-SHA256
crypto map OUTSIDE_map interface OUTSIDE
crypto ca trustpool policy

crypto ikev2 policy 3
 encryption aes-256
 integrity sha512
 group 14
 prf sha512
 lifetime seconds 43200

crypto ikev2 enable OUTSIDE

group-policy GroupPolicy_1.2.3.4 internal
group-policy GroupPolicy_1.2.3.4 attributes
 vpn-tunnel-protocol ikev2

tunnel-group 1.2.3.4 type ipsec-l2l
tunnel-group 1.2.3.4 general-attributes
 default-group-policy GroupPolicy_1.2.3.4
tunnel-group 1.2.3.4 ipsec-attributes
 ikev2 remote-authentication pre-shared-key *****
 ikev2 local-authentication pre-shared-key *****

eri-- · Dec 10, 2014, 10:06 AM

You need to show the logs from pfSense side.

miken32 · Dec 10, 2014, 5:41 PM

@ermal:

You need to show the logs from pfSense side.

I did that on the second post. @cmb told me to post logs from the Cisco side :)

FWIW, here's what the ipsec.conf looks like at the moment:


conn con1
	fragmentation = yes
	keyexchange = ikev2
	reauth = yes
	forceencaps = no
	rekey = yes
	reqid = 1
	installpolicy = yes
	type = tunnel
	dpdaction = restart
	dpddelay = 10s
	dpdtimeout = 60s
	auto = route
	left = 1.2.3.4
	right = 9.8.7.6
	leftid = 1.2.3.4
	ikelifetime = 28800s
	lifetime = 3600s
	rightsubnet = 192.168.242.0/24
	leftsubnet = 192.168.244.0/24
	ike = aes256-sha512-modp2048!
	esp = aes256-sha512-modp2048,aes256gcm128-sha512-modp2048!
	leftauth = psk
	rightauth = psk
	rightid = 9.8.7.6

cmb · Dec 10, 2014, 7:40 PM

The source of the issue is definitely the "Crypto Map Policy not found for remote traffic selector" log from the ASA. As to why, probably a better question for a Cisco forum. Your crypto map looks like it matches what the ASA claims doesn't match.

miken32 · Dec 11, 2014, 8:12 PM

@cmb:

The source of the issue is definitely the "Crypto Map Policy not found for remote traffic selector" log from the ASA. As to why, probably a better question for a Cisco forum. Your crypto map looks like it matches what the ASA claims doesn't match.

Ok, thanks for checking it out. Will report back if it does turn out to be anything with pfSense. Using IKE v1 in the meantime…

miken32 · Dec 18, 2014, 7:30 PM

I think this is an issue with the pfSense…

Here's a partial debug trace of the pfSense trying to initiate a connection. The tunnel is down, and I try to ping a host in the remote subnet. This brings up phase 1 of the tunnel but not phase 2 (or whatever the IKEv2 terms are.)


IKEv2-PROTO-2: (153): Received Packet [From 1.2.3.4:4500/To 9.8.7.6:500/VRF i0:f0] 
(153): Initiator SPI : 8CE2615A4BA17050 - Responder SPI : 3A1657181A5F8FB2 Message id: 1
(153): IKEv2 IKE_AUTH Exchange REQUESTIKEv2-PROTO-3: (153): Next payload: ENCR, version: 2.0 (153): Exchange type: IKE_AUTH, flags: INITIATOR (153): Message id: 1, length: 464(153):  
Payload contents: 
(153): REAL Decrypted packet:(153): Data: 376 bytes
(153):  IDi(153):   Next payload: NOTIFY, reserved: 0x0, length: 12
(153):     Id type: IPv4 address, Reserved: 0x0 0x0
(153): 
(153):      b8 45 a9 a2
(153):  NOTIFY(INITIAL_CONTACT)(153):   Next payload: IDr, reserved: 0x0, length: 8
(153):     Security protocol id: Unknown - 0, spi size: 0, type: INITIAL_CONTACT
(153):  IDr(153):   Next payload: AUTH, reserved: 0x0, length: 12
(153):     Id type: IPv4 address, Reserved: 0x0 0x0
(153): 
(153):      a2 d4 ca 7e
(153):  AUTH(153):   Next payload: NOTIFY, reserved: 0x0, length: 72
(153):     Auth method PSK, reserved: 0x0, reserved 0x0
(153): Auth data: 64 bytes
(153):  NOTIFY(ESP_TFC_NO_SUPPORT)(153):   Next payload: SA, reserved: 0x0, length: 8
(153):     Security protocol id: Unknown - 0, spi size: 0, type: ESP_TFC_NO_SUPPORT
(153):  SA(153):   Next payload: TSi, reserved: 0x0, length: 156
(153):   last proposal: 0x2, reserved: 0x0, length: 40
  Proposal: 1, Protocol id: ESP, SPI size: 4, #trans: 3(153):     last transform: 0x3, reserved: 0x0: length: 12
    type: 1, reserved: 0x0, id: AES-CBC
(153):     last transform: 0x3, reserved: 0x0: length: 8
    type: 3, reserved: 0x0, id: SHA96
(153):     last transform: 0x0, reserved: 0x0: length: 8
    type: 5, reserved: 0x0, id: Don't use ESN
(153):   last proposal: 0x2, reserved: 0x0, length: 40
  Proposal: 2, Protocol id: ESP, SPI size: 4, #trans: 3(153):     last transform: 0x3, reserved: 0x0: length: 12
    type: 1, reserved: 0x0, id: AES-CBC
(153):     last transform: 0x3, reserved: 0x0: length: 8
    type: 3, reserved: 0x0, id: SHA512
(153):     last transform: 0x0, reserved: 0x0: length: 8
    type: 5, reserved: 0x0, id: Don't use ESN
(153):   last proposal: 0x2, reserved: 0x0, length: 36
  Proposal: 3, Protocol id: ESP, SPI size: 4, #trans: 3(153):     last transform: 0x3, reserved: 0x0: length: 8
    type: 1, reserved: 0x0, id: 3DES
(153):     last transform: 0x3, reserved: 0x0: length: 8
    type: 3, reserved: 0x0, id: SHA96
(153):     last transform: 0x0, reserved: 0x0: length: 8
    type: 5, reserved: 0x0, id: Don't use ESN
(153):   last proposal: 0x0, reserved: 0x0, length: 36
  Proposal: 4, Protocol id: ESP, SPI size: 4, #trans: 3(153):     last transform: 0x3, reserved: 0x0: length: 8
    type: 1, reserved: 0x0, id: 3DES
(153):     last transform: 0x3, reserved: 0x0: length: 8
    type: 3, reserved: 0x0, id: SHA512
(153):     last transform: 0x0, reserved: 0x0: length: 8
    type: 5, reserved: 0x0, id: Don't use ESN
(153):  TSi(153):   Next payload: TSr, reserved: 0x0, length: 40
(153):     Num of TSs: 2, reserved 0x0, reserved 0x0
(153):     TS type: TS_IPV4_ADDR_RANGE, proto id: 0, length: 16
(153):     start port: 0, end port: 65535
(153):     start addr: 1.2.3.4, end addr: 1.2.3.4
(153):     TS type: TS_IPV4_ADDR_RANGE, proto id: 0, length: 16
(153):     start port: 0, end port: 65535
(153):     start addr: 192.168.244.0, end addr: 192.168.244.255
(153):  TSr(153):   Next payload: NOTIFY, reserved: 0x0, length: 40
(153):     Num of TSs: 2, reserved 0x0, reserved 0x0
(153):     TS type: TS_IPV4_ADDR_RANGE, proto id: 0, length: 16
(153):     start port: 0, end port: 65535
(153):     start addr: 9.8.7.6, end addr: 9.8.7.6
(153):     TS type: TS_IPV4_ADDR_RANGE, proto id: 0, length: 16
(153):     start port: 0, end port: 65535
(153):     start addr: 192.168.242.0, end addr: 192.168.242.255
(153):  NOTIFY(Unknown - 16396)(153):   Next payload: NOTIFY, reserved: 0x0, length: 8
(153):     Security protocol id: Unknown - 0, spi size: 0, type: Unknown - 0
(153):  NOTIFY(Unknown - 16397)(153):   Next payload: NOTIFY, reserved: 0x0, length: 12
(153):     Security protocol id: Unknown - 0, spi size: 0, type: Unknown - 0
(153): 
(153):      c0 a8 f4 01
(153):  NOTIFY(Unknown - 16417)(153):   Next payload: NONE, reserved: 0x0, length: 8
(153):     Security protocol id: Unknown - 0, spi size: 0, type: Unknown - 0
(153):  
(153): Decrypted packet:(153): Data: 464 bytes

Note the public IP addresses are included in the 'TS_IPV4_ADDR_RANGE' section. The resulting failure looks like this:


IKEv2-PROTO-1: (153): Failed to find a matching policy
IKEv2-PROTO-1: (153): Received Policies: 
IKEv2-PROTO-1: (153): Failed to find a matching policy
IKEv2-PROTO-1: (153): Expected Policies: 
IKEv2-PROTO-5: (153): Failed to verify the proposed policies
IKEv2-PROTO-1: (153): Failed to find a matching policy

Here is what happens, moments later, when I manually start the tunnel from the IPSec status page:


IKEv2-PROTO-2: (154): Received Packet [From 1.2.3.4:4500/To 9.8.7.6:500/VRF i0:f0] 
(154): Initiator SPI : A1D8249CBDC4008D - Responder SPI : 8E4623ACA44823B8 Message id: 1
(154): IKEv2 IKE_AUTH Exchange REQUESTIKEv2-PROTO-3: (154): Next payload: ENCR, version: 2.0 (154): Exchange type: IKE_AUTH, flags: INITIATOR (154): Message id: 1, length: 432(154):  
Payload contents: 
(154): REAL Decrypted packet:(154): Data: 344 bytes
(154):  IDi(154):   Next payload: NOTIFY, reserved: 0x0, length: 12
(154):     Id type: IPv4 address, Reserved: 0x0 0x0
(154): 
(154):      b8 45 a9 a2
(154):  NOTIFY(INITIAL_CONTACT)(154):   Next payload: IDr, reserved: 0x0, length: 8
(154):     Security protocol id: Unknown - 0, spi size: 0, type: INITIAL_CONTACT
(154):  IDr(154):   Next payload: AUTH, reserved: 0x0, length: 12
(154):     Id type: IPv4 address, Reserved: 0x0 0x0
(154): 
(154):      a2 d4 ca 7e
(154):  AUTH(154):   Next payload: NOTIFY, reserved: 0x0, length: 72
(154):     Auth method PSK, reserved: 0x0, reserved 0x0
(154): Auth data: 64 bytes
(154):  NOTIFY(ESP_TFC_NO_SUPPORT)(154):   Next payload: SA, reserved: 0x0, length: 8
(154):     Security protocol id: Unknown - 0, spi size: 0, type: ESP_TFC_NO_SUPPORT
(154):  SA(154):   Next payload: TSi, reserved: 0x0, length: 156
(154):   last proposal: 0x2, reserved: 0x0, length: 40
  Proposal: 1, Protocol id: ESP, SPI size: 4, #trans: 3(154):     last transform: 0x3, reserved: 0x0: length: 12
    type: 1, reserved: 0x0, id: AES-CBC
(154):     last transform: 0x3, reserved: 0x0: length: 8
    type: 3, reserved: 0x0, id: SHA96
(154):     last transform: 0x0, reserved: 0x0: length: 8
    type: 5, reserved: 0x0, id: Don't use ESN
(154):   last proposal: 0x2, reserved: 0x0, length: 40
  Proposal: 2, Protocol id: ESP, SPI size: 4, #trans: 3(154):     last transform: 0x3, reserved: 0x0: length: 12
    type: 1, reserved: 0x0, id: AES-CBC
(154):     last transform: 0x3, reserved: 0x0: length: 8
    type: 3, reserved: 0x0, id: SHA512
(154):     last transform: 0x0, reserved: 0x0: length: 8
    type: 5, reserved: 0x0, id: Don't use ESN
(154):   last proposal: 0x2, reserved: 0x0, length: 36
  Proposal: 3, Protocol id: ESP, SPI size: 4, #trans: 3(154):     last transform: 0x3, reserved: 0x0: length: 8
    type: 1, reserved: 0x0, id: 3DES
(154):     last transform: 0x3, reserved: 0x0: length: 8
    type: 3, reserved: 0x0, id: SHA96
(154):     last transform: 0x0, reserved: 0x0: length: 8
    type: 5, reserved: 0x0, id: Don't use ESN
(154):   last proposal: 0x0, reserved: 0x0, length: 36
  Proposal: 4, Protocol id: ESP, SPI size: 4, #trans: 3(154):     last transform: 0x3, reserved: 0x0: length: 8
    type: 1, reserved: 0x0, id: 3DES
(154):     last transform: 0x3, reserved: 0x0: length: 8
    type: 3, reserved: 0x0, id: SHA512
(154):     last transform: 0x0, reserved: 0x0: length: 8
    type: 5, reserved: 0x0, id: Don't use ESN
(154):  TSi(154):   Next payload: TSr, reserved: 0x0, length: 24
(154):     Num of TSs: 1, reserved 0x0, reserved 0x0
(154):     TS type: TS_IPV4_ADDR_RANGE, proto id: 0, length: 16
(154):     start port: 0, end port: 65535
(154):     start addr: 192.168.244.0, end addr: 192.168.244.255
(154):  TSr(154):   Next payload: NOTIFY, reserved: 0x0, length: 24
(154):     Num of TSs: 1, reserved 0x0, reserved 0x0
(154):     TS type: TS_IPV4_ADDR_RANGE, proto id: 0, length: 16
(154):     start port: 0, end port: 65535
(154):     start addr: 192.168.242.0, end addr: 192.168.242.255
(154):  NOTIFY(Unknown - 16396)(154):   Next payload: NOTIFY, reserved: 0x0, length: 8
(154):     Security protocol id: Unknown - 0, spi size: 0, type: Unknown - 0
(154):  NOTIFY(Unknown - 16397)(154):   Next payload: NOTIFY, reserved: 0x0, length: 12
(154):     Security protocol id: Unknown - 0, spi size: 0, type: Unknown - 0
(154): 
(154):      c0 a8 f4 01
(154):  NOTIFY(Unknown - 16417)(154):   Next payload: NONE, reserved: 0x0, length: 8
(154):     Security protocol id: Unknown - 0, spi size: 0, type: Unknown - 0
(154):  
(154): Decrypted packet:(154): Data: 432 bytes

No public IP addresses included, and this connection succeeds. Thoughts?

EDIT: Here are pfSense logs for these two connection attempts. Aside from the different size of the packets sent, note the line 'establishing CHILD_SA con1{1}' in the failed attemps, versus 'establishing CHILD_SA con1' in the successful attempt. Does this indicate anything useful?


Dec 18 09:38:59 pf-victoria charon: 16[KNL] creating acquire job for policy 1.2.3.4/32|/0 === 9.8.7.6/32|/0 with reqid {1}
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>initiating IKE_SA con1[28] to 9.8.7.6
Dec 18 09:38:59 pf-victoria charon: 06[IKE] initiating IKE_SA con1[28] to 9.8.7.6
Dec 18 09:38:59 pf-victoria charon: 06[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) ]
Dec 18 09:38:59 pf-victoria charon: 06[NET] sending packet: from 1.2.3.4[500] to 9.8.7.6[500] (440 bytes)
Dec 18 09:38:59 pf-victoria charon: 06[NET] received packet: from 9.8.7.6[500] to 1.2.3.4[500] (585 bytes)
Dec 18 09:38:59 pf-victoria charon: 06[ENC] parsed IKE_SA_INIT response 0 [ SA KE No V V V N(NATD_S_IP) N(NATD_D_IP) V ]
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>received Cisco Delete Reason vendor ID
Dec 18 09:38:59 pf-victoria charon: 06[IKE] received Cisco Delete Reason vendor ID
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>received Cisco Copyright (c) 2009 vendor ID
Dec 18 09:38:59 pf-victoria charon: 06[IKE] received Cisco Copyright (c) 2009 vendor ID
Dec 18 09:38:59 pf-victoria charon: 06[ENC] received unknown vendor ID: 43:49:53:43:4f:2d:47:52:45:2d:4d:4f:44:45:02
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>received FRAGMENTATION vendor ID
Dec 18 09:38:59 pf-victoria charon: 06[IKE] received FRAGMENTATION vendor ID
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>authentication of '1.2.3.4' (myself) with pre-shared key
Dec 18 09:38:59 pf-victoria charon: 06[IKE] authentication of '1.2.3.4' (myself) with pre-shared key
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>establishing CHILD_SA con1{1}
Dec 18 09:38:59 pf-victoria charon: 06[IKE] establishing CHILD_SA con1{1}
Dec 18 09:38:59 pf-victoria charon: 06[ENC] generating IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(EAP_ONLY) ]
Dec 18 09:38:59 pf-victoria charon: 06[NET] sending packet: from 1.2.3.4[4500] to 9.8.7.6[4500] (464 bytes)
Dec 18 09:38:59 pf-victoria charon: 06[NET] received packet: from 9.8.7.6[4500] to 1.2.3.4[4500] (208 bytes)
Dec 18 09:38:59 pf-victoria charon: 06[ENC] parsed IKE_AUTH response 1 [ V IDr AUTH N(NO_PROP) ]
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>authentication of '9.8.7.6' with pre-shared key successful
Dec 18 09:38:59 pf-victoria charon: 06[IKE] authentication of '9.8.7.6' with pre-shared key successful
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>IKE_SA con1[28] established between 1.2.3.4[1.2.3.4]...9.8.7.6[9.8.7.6]
Dec 18 09:38:59 pf-victoria charon: 06[IKE] IKE_SA con1[28] established between 1.2.3.4[1.2.3.4]...9.8.7.6[9.8.7.6]
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>scheduling reauthentication in 27865s
Dec 18 09:38:59 pf-victoria charon: 06[IKE] scheduling reauthentication in 27865s
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>maximum IKE_SA lifetime 28405s
Dec 18 09:38:59 pf-victoria charon: 06[IKE] maximum IKE_SA lifetime 28405s
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>received NO_PROPOSAL_CHOSEN notify, no CHILD_SA built
Dec 18 09:38:59 pf-victoria charon: 06[IKE] received NO_PROPOSAL_CHOSEN notify, no CHILD_SA built
Dec 18 09:38:59 pf-victoria charon: 06[IKE] <con1|28>failed to establish CHILD_SA, keeping IKE_SA
Dec 18 09:38:59 pf-victoria charon: 06[IKE] failed to establish CHILD_SA, keeping IKE_SA

Dec 18 09:39:34 pf-victoria charon: 16[CFG] received stroke: initiate 'con1'
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>initiating IKE_SA con1[29] to 9.8.7.6
Dec 18 09:39:34 pf-victoria charon: 09[IKE] initiating IKE_SA con1[29] to 9.8.7.6
Dec 18 09:39:34 pf-victoria charon: 09[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) ]
Dec 18 09:39:34 pf-victoria charon: 09[NET] sending packet: from 1.2.3.4[500] to 9.8.7.6[500] (440 bytes)
Dec 18 09:39:34 pf-victoria charon: 09[NET] received packet: from 9.8.7.6[500] to 1.2.3.4[500] (585 bytes)
Dec 18 09:39:34 pf-victoria charon: 09[ENC] parsed IKE_SA_INIT response 0 [ SA KE No V V V N(NATD_S_IP) N(NATD_D_IP) V ]
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>received Cisco Delete Reason vendor ID
Dec 18 09:39:34 pf-victoria charon: 09[IKE] received Cisco Delete Reason vendor ID
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>received Cisco Copyright (c) 2009 vendor ID
Dec 18 09:39:34 pf-victoria charon: 09[IKE] received Cisco Copyright (c) 2009 vendor ID
Dec 18 09:39:34 pf-victoria charon: 09[ENC] received unknown vendor ID: 43:49:53:43:4f:2d:47:52:45:2d:4d:4f:44:45:02
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>received FRAGMENTATION vendor ID
Dec 18 09:39:34 pf-victoria charon: 09[IKE] received FRAGMENTATION vendor ID
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>authentication of '1.2.3.4' (myself) with pre-shared key
Dec 18 09:39:34 pf-victoria charon: 09[IKE] authentication of '1.2.3.4' (myself) with pre-shared key
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>establishing CHILD_SA con1
Dec 18 09:39:34 pf-victoria charon: 09[IKE] establishing CHILD_SA con1
Dec 18 09:39:34 pf-victoria charon: 09[ENC] generating IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(EAP_ONLY) ]
Dec 18 09:39:34 pf-victoria charon: 09[NET] sending packet: from 1.2.3.4[4500] to 9.8.7.6[4500] (432 bytes)
Dec 18 09:39:34 pf-victoria charon: 09[NET] received packet: from 9.8.7.6[4500] to 1.2.3.4[4500] (304 bytes)
Dec 18 09:39:34 pf-victoria charon: 09[ENC] parsed IKE_AUTH response 1 [ V IDr AUTH SA TSi TSr N(ESP_TFC_PAD_N) N(NON_FIRST_FRAG) ]
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>authentication of '9.8.7.6' with pre-shared key successful
Dec 18 09:39:34 pf-victoria charon: 09[IKE] authentication of '9.8.7.6' with pre-shared key successful
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>IKE_SA con1[29] established between 1.2.3.4[1.2.3.4]...9.8.7.6[9.8.7.6]
Dec 18 09:39:34 pf-victoria charon: 09[IKE] IKE_SA con1[29] established between 1.2.3.4[1.2.3.4]...9.8.7.6[9.8.7.6]
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>scheduling reauthentication in 28245s
Dec 18 09:39:34 pf-victoria charon: 09[IKE] scheduling reauthentication in 28245s
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>maximum IKE_SA lifetime 28785s
Dec 18 09:39:34 pf-victoria charon: 09[IKE] maximum IKE_SA lifetime 28785s
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
Dec 18 09:39:34 pf-victoria charon: 09[IKE] received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
Dec 18 09:39:34 pf-victoria charon: 09[IKE] <con1|29>CHILD_SA con1{1} established with SPIs c02da961_i c6c0ab47_o and TS 192.168.244.0/24|/0 === 192.168.242.0/24|/0 
Dec 18 09:39:34 pf-victoria charon: 09[IKE] CHILD_SA con1{1} established with SPIs c02da961_i c6c0ab47_o and TS 192.168.244.0/24|/0 === 192.168.242.0/24|/0</con1|29></con1|29></con1|29></con1|29></con1|29></con1|29></con1|29></con1|29></con1|29></con1|29></con1|29></con1|29></con1|28></con1|28></con1|28></con1|28></con1|28></con1|28></con1|28></con1|28></con1|28></con1|28></con1|28></con1|28>

miken32 · Dec 19, 2014, 10:52 PM

@cmb:

The source of the issue is definitely the "Crypto Map Policy not found for remote traffic selector" log from the ASA. As to why, probably a better question for a Cisco forum. Your crypto map looks like it matches what the ASA claims doesn't match.

Any input on this? It looks like the traffic selector being sent by StrongSwan is different based on how the tunnel is initiated, which seems like a bug. I'd open a bug but am not sure I could describe it in sufficient detail to ensure a resolution, as I've no experience with StrongSwan.

cmb · Dec 20, 2014, 2:45 AM

edit: no, misread that.

miken32 · Dec 19, 2014, 11:28 PM

@cmb:

That's this. https://redmine.pfsense.org/issues/4129

I only have the single phase 2 entry; does it still apply to me? Thanks.

cmb · Dec 20, 2014, 2:48 AM

No it doesn't in that case, I mis-read your last post. I'm doing some IPsec testing with an ASA right now, will see if that's replicable.

miken32 · Dec 23, 2014, 6:07 PM

@cmb:

No it doesn't in that case, I mis-read your last post. I'm doing some IPsec testing with an ASA right now, will see if that's replicable.

Any luck with this? Anything more I can do to help narrow it down?

eri-- · Dec 24, 2014, 7:05 AM

Did you test new snapshots?
There have been fixes put in place for various issues especially on IPsec.

miken32 · Jan 6, 2015, 5:59 PM

@ermal:

Did you test new snapshots?
There have been fixes put in place for various issues especially on IPsec.

No improvements with this morning's build. Tunnels have to be manually started or the wrong traffic selector is sent.

cmb · Jan 6, 2015, 8:13 PM

What's wrong about it? It looks like it's sending what you have configured and the ASA is rejecting it. The only issue with interoperability with Cisco IPsec that I'm aware of is this. https://redmine.pfsense.org/issues/4178 Which only applies to IKEv1 and isn't what you're seeing here.

miken32 · Jan 6, 2015, 10:29 PM

@cmb:

What's wrong about it? It looks like it's sending what you have configured and the ASA is rejecting it.

Please reread my earlier post at https://forum.pfsense.org/index.php?topic=84934.msg469407#msg469407. When pfSense tries to bring up the tunnel automatically, it sends a different traffic selector than when the tunnel is manually started from the status page.

cmb · Jan 7, 2015, 11:07 PM

The latest strongswan release (5.2.1->5.2.2) went into today's snapshots, please retry after upgrading to something from the 7th or newer and report back.