Things look like that:
When cluster is up and client is connected:
1/ output of "ipsecctl -v -sa" is perfectly in sync between nodes.
2/ output of "pfctll -sstates" is sync between nodes within 1s delay
(as expected)
3/ output of "ikectl sh sa" is *not* in sync between nodes. Passive
node has null output (I don't know if expected)
I run both sasyncd and iked with -vv, so logging is beefy.
Connection seen from ACTIVE side:
Mar 4 12:33:57 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: recv
IKE_SA_INIT req 0 peer 192.168.1.46:39248 local 192.168.1.160:500, 716
by
tes, policy 'win7'
Mar 4 12:33:57 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_sa_responder_dh: want dh CURVE25519, KE has ECP_256
Mar 4 12:33:57 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_resp_recv: failed to negotiate IKE SA
Mar 4 12:33:57 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_add_error: INVALID_KE_PAYLOAD
Mar 4 12:33:57 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: send
IKE_SA_INIT res 0 peer 192.168.1.46:39248 local 192.168.1.160:500, 38
byt
es
Mar 4 12:33:57 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: recv
IKE_SA_INIT req 0 peer 192.168.1.46:39248 local 192.168.1.160:500, 684
by
tes, policy 'win7'
Mar 4 12:33:57 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: send
IKE_SA_INIT res 0 peer 192.168.1.46:39248 local 192.168.1.160:500, 239
by
tes
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: recv
IKE_AUTH req 1 peer 192.168.1.46:43052 local 192.168.1.160:4500, 413
byte
s, policy 'win7'
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_pld_eap: REQUEST id 0 length 5 EAP-IDENTITY
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: send
IKE_AUTH res 1 peer 192.168.1.46:43052 local 192.168.1.160:4500, 1301
byt
es, NAT-T
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: recv
IKE_AUTH req 2 peer 192.168.1.46:43052 local 192.168.1.160:4500, 70
bytes
, policy 'win7'
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_pld_eap: RESPONSE id 0 length 9 EAP-IDENTITY
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_pld_eap: REQUEST id 1 length 31 EAP-MSCHAP_V2
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: eap_parse:
MSCHAP_V2 CHALLENGE id 1 length 26 valuesize 16 name '_iked' length
5
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: send
IKE_AUTH res 2 peer 192.168.1.46:43052 local 192.168.1.160:4500, 92
bytes
, NAT-T
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: recv
IKE_AUTH req 3 peer 192.168.1.46:43052 local 192.168.1.160:4500, 124
byte
s, policy 'win7'
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_pld_eap: RESPONSE id 1 length 63 EAP-MSCHAP_V2
Mar 4 12:33:58 ipsec1 iked[6487]: eap_parse: MSCHAP_V2 RESPONSE id 1
length 58 valuesize 49 name 'test' name-length 4
Mar 4 12:33:58 ipsec1 iked[6487]: ikev2_resp_ike_eap_mschap: 'test'
authenticated
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_pld_eap: REQUEST id 2 length 61 EAP-MSCHAP_V2
Mar 4 12:33:58 ipsec1 iked[6487]: eap_parse: MSCHAP_V2 SUCCESS
request id 1 length 56 message
'S=A8F1DF4F002779CC93AB39252353681F111196C
B M=Welcome' message-len 52
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: send
IKE_AUTH res 3 peer 192.168.1.46:43052 local 192.168.1.160:4500, 122
byte
s, NAT-T
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: recv
IKE_AUTH req 4 peer 192.168.1.46:43052 local 192.168.1.160:4500, 67
bytes
, policy 'win7'
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_pld_eap: RESPONSE id 2 length 6 EAP-MSCHAP_V2
Mar 4 12:33:58 ipsec1 iked[6487]: eap_parse: MSCHAP_V2 SUCCESS response
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_pld_eap: SUCCESS id 2 length 4
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: send
IKE_AUTH res 4 peer 192.168.1.46:43052 local 192.168.1.160:4500, 65
bytes
, NAT-T
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: recv
IKE_AUTH req 5 peer 192.168.1.46:43052 local 192.168.1.160:4500, 97
bytes
, policy 'win7'
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: assigned
address 10.1.0.190 to FQDN/test
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: send
IKE_AUTH res 5 peer 192.168.1.46:43052 local 192.168.1.160:4500, 213
byte
s, NAT-T
Mar 4 12:33:58 ipsec1 sasyncd[3474]: net_send_messages: msg
0x62f175f8000 len 336 ref 1 to peer 10.0.1.162
Mar 4 12:33:58 ipsec1 sasyncd[3474]: net_send_messages: freeing msg
0x62f175f8000
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_childsa_enable: loaded SPIs: 0xe56d3eef, 0x2f538456 (enc
aes-128-gcm)
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699:
ikev2_childsa_enable: loaded flows: ESP-10.0.0.0/24=10.1.0.190/32(0)
Mar 4 12:33:58 ipsec1 iked[6487]: spi=0x47c4ccf08d9d8699: established
peer 192.168.1.46:43052[FQDN/test] local 192.168.1.160:4500[FQDN/v
pn.my.domain] assigned 10.1.0.190 policy 'win7' as responder (enc
aes-128-gcm group curve25519 prf hmac-sha2-256)
Mar 4 12:33:58 ipsec1 sasyncd[3474]: net_send_messages: msg
0x62f175f4f60 len 336 ref 1 to peer 10.0.1.162
Mar 4 12:33:58 ipsec1 sasyncd[3474]: net_send_messages: freeing msg
0x62f175f4f60
Mar 4 12:33:58 ipsec1 sasyncd[3474]: net_send_messages: msg
0x62f175bb7d0 len 272 ref 1 to peer 10.0.1.162
Mar 4 12:33:58 ipsec1 sasyncd[3474]: net_send_messages: freeing msg
0x62f175bb7d0
Mar 4 12:33:58 ipsec1 sasyncd[3474]: net_send_messages: msg
0x62f175f4330 len 272 ref 1 to peer 10.0.1.162
Mar 4 12:33:58 ipsec1 sasyncd[3474]: net_send_messages: freeing msg
0x62f175f4330
--------------------------------------------------------
Connection seen from PASSIVE side:
Mar 4 12:35:17 ipsec2 sasyncd[20476]: net_handle_messages: got msg
type 1 len 280 from peer 10.0.1.161
Mar 4 12:35:17 ipsec2 sasyncd[20476]: pfkey_queue_message: pfkey ADD
len 280 seq 18
Mar 4 12:35:17 ipsec2 sasyncd[20476]: net_handle_messages: got msg
type 1 len 280 from peer 10.0.1.161
Mar 4 12:35:17 ipsec2 sasyncd[20476]: pfkey_queue_message: pfkey ADD
len 280 seq 19
Mar 4 12:35:17 ipsec2 sasyncd[20476]: net_handle_messages: got msg
type 1 len 224 from peer 10.0.1.161
Mar 4 12:35:17 ipsec2 sasyncd[20476]: pfkey_queue_message: pfkey
X_ADDFLOW len 224 seq 20
Mar 4 12:35:17 ipsec2 sasyncd[20476]: net_handle_messages: got msg
type 1 len 224 from peer 10.0.1.161
Mar 4 12:35:17 ipsec2 sasyncd[20476]: pfkey_queue_message: pfkey
X_ADDFLOW len 224 seq 21
--------------------------------------------------------
ipsecctl -v sa on BOTH sides (192.168.1.46 is my mobile WAN,
192.168.1.160 is CARP of ipsec, 10.1.0.190 is mobile tunnel IP,
10.0.0.0/24 is local LAN I'm granting access to):
FLOWS:
flow esp in from 10.1.0.190 to 10.0.0.0/24 peer 192.168.1.46 srcid
FQDN/vpn.my.domain dstid FQDN/test type require
flow esp out from 10.0.0.0/24 to 10.1.0.190 peer 192.168.1.46 srcid
FQDN/vpn.my.domain dstid FQDN/test type require
SAD:
esp tunnel from 192.168.1.160 to 192.168.1.46 spi 0x2f538456 enc aes-128-gcm
sa: spi 0x2f538456 auth gmac-aes-128 enc aes-gcm
state mature replay 64 flags 0x204<tunnel,udpencap>
lifetime_cur: alloc 0 bytes 0 add 1646393638 first 0
lifetime_hard: alloc 0 bytes 4294967296 add 10800 first 0
lifetime_soft: alloc 0 bytes 3809635991 add 9579 first 0
address_src: 192.168.1.160
address_dst: 192.168.1.46
identity_src: type fqdn id 0: FQDN/vpn.my.domain
identity_dst: type fqdn id 0: FQDN/test
udpencap: udpencap port 43052
tag: win7-FQDN/test
counter:
replay: rpl 1
esp tunnel from 192.168.1.46 to 192.168.1.160 spi 0xe56d3eef enc aes-128-gcm
sa: spi 0xe56d3eef auth gmac-aes-128 enc aes-gcm
state mature replay 64 flags 0x204<tunnel,udpencap>
lifetime_cur: alloc 0 bytes 0 add 1646393638 first 0
lifetime_hard: alloc 0 bytes 4294967296 add 10800 first 0
lifetime_soft: alloc 0 bytes 4024384356 add 10119 first 0
address_src: 192.168.1.46
address_dst: 192.168.1.160
identity_src: type fqdn id 0: FQDN/test
identity_dst: type fqdn id 0: FQDN/vpn.my.domain
udpencap: udpencap port 43052
tag: win7-FQDN/test
counter:
replay: rpl 1
--------------------------------------------------------
ikectl sh sa on ACTIVE only (PASSIVE is empty)
iked_sas: 0xf64ca0257b0 rspi 0xbb3d2768049c9289 ispi
0x47c4ccf08d9d8699
192.168.1.160:4500->192.168.1.46:43052<FQDN/test>[10.1.0.190]
ESTABLISHED r natt udpecap nexti 0x0 pol 0xf6453101000
sa_childsas: 0xf64ca022a00 ESP 0xe56d3eef in 192.168.1.46:43052 ->
192.168.1.160:4500 (LA) B=0x0 P=0xf64ca034200 @0xf64ca0257b0
sa_childsas: 0xf64ca034200 ESP 0x2f538456 out 192.168.1.160:4500 ->
192.168.1.46:43052 (L) B=0x0 P=0xf64ca022a00 @0xf64ca0257b0
sa_flows: 0xf64ca018400 ESP out 10.0.0.0/24 -> 10.1.0.190/32 [0]@-1
(L) @0xf64ca0257b0
sa_flows: 0xf64ca03a000 ESP in 10.1.0.190/32 -> 10.0.0.0/24 [0]@-1
(L) @0xf64ca0257b0
iked_activesas: 0xf64ca034200 ESP 0x2f538456 out 192.168.1.160:4500 ->
192.168.1.46:43052 (L) B=0x0 P=0xf64ca022a00 @0xf64ca0257b0
iked_activesas: 0xf64ca022a00 ESP 0xe56d3eef in 192.168.1.46:43052 ->
192.168.1.160:4500 (LA) B=0x0 P=0xf64ca034200 @0xf64ca0257b0
iked_flows: 0xf64ca03a000 ESP in 10.1.0.190/32 -> 10.0.0.0/24 [0]@-1
(L) @0xf64ca0257b0
iked_flows: 0xf64ca018400 ESP out 10.0.0.0/24 -> 10.1.0.190/32 [0]@-1
(L) @0xf64ca0257b0
iked_dstid_sas: 0xf64ca0257b0 rspi 0xbb3d2768049c9289 ispi
0x47c4ccf08d9d8699
192.168.1.160:4500->192.168.1.46:43052<FQDN/test>[10.1.0.190]
ESTABLISHED r natt udpecap nexti 0x0 pol 0xf6453101000
--------------------------------------------------------
Log on SLAVE after pausing MASTER:
Mar 4 12:40:49 ipsec2 sasyncd[20476]: carp_update_state: switching
state to MASTER
Mar 4 12:40:49 ipsec2 sasyncd[20476]: net_ctl: sending my state
MASTER to peer "10.0.1.161"
Mar 4 12:40:49 ipsec2 sasyncd[20476]: net_send_messages: msg
0x6d895bbc3b0 len 64 ref 1 to peer 10.0.1.161
Mar 4 12:40:49 ipsec2 sasyncd[20476]: net_send_messages: freeing msg
0x6d895bbc3b0
--------------------------------------------------------
Log on SLAVE after unpausing MASTER:
Mar 4 12:41:53 ipsec2 sasyncd[20476]: net_handle_messages: got msg
type 0 len 12 from peer 10.0.1.161
Mar 4 12:41:53 ipsec2 sasyncd[20476]: net_ctl: got ERROR from peer "10.0.1.161"
Mar 4 12:41:54 ipsec2 sasyncd[20476]: carp_update_state: switching
state to SLAVE
Mar 4 12:41:54 ipsec2 sasyncd[20476]: net_ctl: sending my state SLAVE
to peer "10.0.1.161"
Mar 4 12:41:54 ipsec2 sasyncd[20476]: net_send_messages: msg
0x6d895b95db0 len 64 ref 1 to peer 10.0.1.161
Mar 4 12:41:54 ipsec2 sasyncd[20476]: net_send_messages: freeing msg
0x6d895b95db0
Mar 4 12:41:54 ipsec2 sasyncd[20476]: net_handle_messages: got msg
type 0 len 12 from peer 10.0.1.161
Mar 4 12:41:54 ipsec2 sasyncd[20476]: net_ctl: got CTL_STATE ACK from
peer "10.0.1.161"
--
Paweł Kraszewski
