IPSec tunnels are not coming up since last update

luphi

thank you for the hint.

jimp

Nothing stands out there. They are both set to start with trap policies so they won't connect until traffic tries to pass. Have you tried passing traffic over the tunnel?

luphi

yes, I tried. That was showing me, the tunnels are down.
Is there a way to roll back to a version of let's say 2 weeks ago?

luphi

Not sure if that is important but I'm running a cluster.
All logs are of course from the primary, active node.

jimp

No, there isn't a way to roll back. And HA shouldn't matter unless your secondary is receiving the traffic and not the primary. Check the CARP status to be sure.

Are you certain your traffic that should enter the tunnel is doing so? Maybe it's being misrouted by something like a rule on LAN with a gateway set?

Do the tunnels connect if you click the button to connect them on the status page?

Does it show down on the other end?

luphi

all interface are in master state.
To be on the safe side, I took down the 2nd node.
Routing is okay.
Internet access is working fine
When I click the "connect" button, a tcpdump shows nothing on the Internet facing interface on port 500.

jimp

Do you have a default route in the routing table?

luphi

yes, I have.

jimp

Any state table entries for the remote peer address on any port? It could be using 4500 and not 500.

Might also help to see the output of:

swanctl --list-conns
swanctl --list-sas
swanctl --list-pols
setkey -D
setkey -DP
route -n get x.x.x.x (where x.x.x.x is the remote peer address)

luphi

# swanctl --list-conns
bypass: IKEv1/2, no reauthentication, rekeying every 14400s
  local:  %any
  remote: 127.0.0.1
  local unspecified authentication:
  remote unspecified authentication:
  bypass: PASS, no rekeying
    local:  172.23.1.0/24|/0
    remote: 172.23.1.0/24|/0
# swanctl --list-sas
# swanctl --list-pols
bypass/bypass, PASS
  local:  172.23.1.0/24|/0
  remote: 172.23.1.0/24|/0
# setkey -D
No SAD entries.
# setkey -DP
172.23.1.0/24[any] 172.23.1.0/24[any] any
	in none
	created: Jan  2 15:59:26 2020  lastused: Jan  3 10:01:52 2020
	lifetime: 9223372036854775807(s) validtime: 0(s)
	spid=2 seq=1 pid=24554 scope=global 
	refcnt=2
172.23.1.0/24[any] 172.23.1.0/24[any] any
	out none
	created: Jan  2 15:59:26 2020  lastused: Jan  3 10:01:52 2020
	lifetime: 9223372036854775807(s) validtime: 0(s)
	spid=1 seq=0 pid=24554 scope=global 
	refcnt=3

routing is ok, pointing to the Internet router

jimp

Interesting. The connections are not loaded at all, neither are the policies. But the LAN bypass is.

What does this show:
swanctl --load-conns --file /var/etc/ipsec/swanctl.conf

luphi

We are getting closer...

 # swanctl --load-conns --file /var/etc/ipsec/swanctl.conf
loaded connection 'bypass'
loading connection 'con1000' failed: invalid value for: proposals, config discarded
loading connection 'con2000' failed: invalid value for: proposals, config discarded
loaded 1 of 3 connections, 2 failed to load, 0 unloaded

luphi

When I check the GUI (VPN -> IPsec -> Tunnels -> Edit Phase 1),
the "Phase1 proposal (Encryption Algorithm)" box shown twice:

jimp

That's a known issue that I just pushed a fix for: https://redmine.pfsense.org/issues/10151

luphi

thought, it might be related to my issue

jimp

Doesn't appear to be. Looks like it's something with the way the P1 proposal is being formed with certain combinations of options. I finally found one tunnel on one of my VMs that is doing the same thing.

Looks like what actually broke it is https://redmine.pfsense.org/issues/9726

Not working: proposals = aes128gcm128-curve448
Working: proposals = aes128gcm128-aesxcbc-curve448

I reverted the change from the PR on there and it came up and started working again.

luphi

Mh, shouldn't the GUI avoid setting invalid combinations?
Anyway, I changed some valid combination and now I get

#  swanctl --load-conns --file /var/etc/ipsec/swanctl.conf
loaded connection 'bypass'
loaded connection 'con1000'
loaded connection 'con2000'
successfully loaded 3 connections, 0 unloaded

but the tunnels are still not coming up
Still nothing in tcpdump (filtering only on peer gw ip)

jimp

That's the issue with the commit. It is a valid combination, but it wasn't working due to that change.

Whatever problem that change was trying to solve needs a better solution.

luphi

Phase1 seems to work now, but still issues with phase2:
I can't figure it out

Jan  3 16:01:52 eagle1 charon[92988]: 00[DMN] Starting IKE charon daemon (strongSwan 5.8.2, FreeBSD 12.0-RELEASE-p10, amd64)
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] PKCS11 module '<name>' lacks library path
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loaded PKCS#11 v2.20 library 'opensc' (/usr/local/lib/opensc-pkcs11.so)
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG]   OpenSC Project: OpenSC smartcard framework v0.19
Jan  3 16:01:52 eagle1 charon[92988]: 00[KNL] unable to set UDP_ENCAP: Invalid argument
Jan  3 16:01:52 eagle1 charon[92988]: 00[NET] enabling UDP decapsulation for IPv6 on port 4500 failed
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loading unbound resolver config from '/etc/resolv.conf'
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loading unbound trust anchors from '/usr/local/etc/ipsec.d/dnssec.keys'
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] ipseckey plugin is disabled
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loading ca certificates from '/usr/local/etc/ipsec.d/cacerts'
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loading aa certificates from '/usr/local/etc/ipsec.d/aacerts'
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loading ocsp signer certificates from '/usr/local/etc/ipsec.d/ocspcerts'
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loading attribute certificates from '/usr/local/etc/ipsec.d/acerts'
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loading crls from '/usr/local/etc/ipsec.d/crls'
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loading secrets from '/usr/local/etc/ipsec.secrets'
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] opening triplet file /usr/local/etc/ipsec.d/triplets.dat failed: No such file or directory
Jan  3 16:01:52 eagle1 charon[92988]: 00[CFG] loaded 0 RADIUS server configurations
Jan  3 16:01:52 eagle1 charon[92988]: 00[LIB] loaded plugins: charon unbound pkcs11 aes des blowfish rc2 sha2 sha1 md4 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey ipseckey pem openssl fips-prf curve25519 xcbc cmac hmac drbg curl attr kernel-pfkey kernel-pfroute resolve socket-default stroke vici updown eap-identity eap-sim eap-md5 eap-mschapv2 eap-dynamic eap-radius eap-tls eap-ttls eap-peap xauth-generic xauth-eap xauth-pam whitelist addrblock counters
Jan  3 16:01:52 eagle1 charon[92988]: 00[JOB] spawning 16 worker threads
Jan  3 16:01:53 eagle1 charon[92988]: 07[CFG] vici client 1 connected
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] vici client 1 requests: get-keys
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] vici client 1 requests: get-shared
Jan  3 16:01:53 eagle1 charon[92988]: 07[CFG] vici client 1 requests: load-shared
Jan  3 16:01:53 eagle1 charon[92988]: 07[CFG] loaded IKE shared key with id 'ike-0' for: '%any', 'dxclab'
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] vici client 1 requests: load-shared
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] loaded IKE shared key with id 'ike-1' for: '%any', 'ssck'
Jan  3 16:01:53 eagle1 charon[92988]: 15[CFG] vici client 1 requests: get-authorities
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] vici client 1 requests: get-pools
Jan  3 16:01:53 eagle1 charon[92988]: 15[CFG] vici client 1 requests: get-conns
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] vici client 1 requests: load-conn
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]  conn bypass:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   child bypass:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_time = 3600
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_time = 3960
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_time = 360
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    updown = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    hostaccess = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    ipcomp = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mode = PASS
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    policies = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    policies_fwd_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    dpd_action = clear
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    start_action = hold
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    close_action = clear
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    reqid = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    tfc = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    priority = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    interface = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    if_id_in = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    if_id_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_in = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_in_sa = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_out = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    set_mark_in = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    set_mark_out = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    inactivity = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    proposals = ESP:AES_CBC_128/AES_CBC_192/AES_CBC_256/HMAC_SHA2_256_128/HMAC_SHA2_384_192/HMAC_SHA2_512_256/HMAC_SHA1_96/AES_XCBC_96/NO_EXT_SEQ
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    local_ts = 172.23.1.0/24|/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    remote_ts = 172.23.1.0/24|/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    hw_offload = no
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    sha256_96 = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_df = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_ecn = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_dscp = out
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   version = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local_addrs = %any
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote_addrs = 127.0.0.1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local_port = 500
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote_port = 500
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   send_certreq = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   send_cert = CERT_SEND_IF_ASKED
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   ppk_id = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   ppk_required = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   mobike = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   aggressive = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dscp = 0x00
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   encap = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dpd_delay = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dpd_timeout = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   fragmentation = 2
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   childless = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   unique = UNIQUE_NO
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   keyingtries = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   reauth_time = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   rekey_time = 14400
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   over_time = 1440
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   rand_time = 1440
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   proposals = IKE:AES_CBC_128/AES_CBC_192/AES_CBC_256/CAMELLIA_CBC_128/CAMELLIA_CBC_192/CAMELLIA_CBC_256/3DES_CBC/HMAC_SHA2_256_128/HMAC_SHA2_384_192/HMAC_SHA2_512_256/HMAC_SHA1_96/AES_XCBC_96/AES_CMAC_96/PRF_HMAC_SHA2_256/PRF_HMAC_SHA2_384/PRF_HMAC_SHA2_512/PRF_AES128_XCBC/PRF_AES128_CMAC/PRF_HMAC_SHA1/ECP_256/ECP_384/ECP_521/ECP_256_BP/ECP_384_BP/ECP_512_BP/CURVE_25519/CURVE_448/MODP_3072/MODP_4096/MODP_6144/MODP_8192/MODP_2048, IKE:AES_GCM_16_128/AES_GCM_16_192/AES_GCM_16_256/CHACHA20_POLY1305/AES_GCM_12_128/AES_GCM_12_192/AES_GCM_12_256/AES_GCM_8_128/AES_GCM_8_192/AES_GCM_8_256/PRF_HMAC_SHA2_256/PRF_HMAC_SHA2_384/PRF_HMAC_SHA2_512/PRF_AES128_XCBC/PRF_AES128_CMAC/PRF_HMAC_SHA1/ECP_256/ECP_384/ECP_521/ECP_256_BP/ECP_384_BP/ECP_512_BP/CURVE_25519/CURVE_448/MODP_3072/MODP_4096/MODP_6144/MODP_8192/MODP_2048
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   if_id_in = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   if_id_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] added vici connection: bypass
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] installing 'bypass'
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] vici client 1 requests: load-conn
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]  conn con1000:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   child con1000:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_time = 3600
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_time = 3600
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_time = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    updown = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    hostaccess = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    ipcomp = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mode = TUNNEL
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    policies = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    policies_fwd_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    dpd_action = restart
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    start_action = hold
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    close_action = clear
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    reqid = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    tfc = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    priority = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    interface = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    if_id_in = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    if_id_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_in = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_in_sa = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_out = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    set_mark_in = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    set_mark_out = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    inactivity = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    proposals = ESP:AES_CBC_256/AES_XCBC_96/MODP_8192/NO_EXT_SEQ
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    local_ts = 172.23.0.0/19|/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    remote_ts = 145.16.214.0/24|/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    hw_offload = no
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    sha256_96 = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_df = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_ecn = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_dscp = out
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   version = 2
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local_addrs = 172.23.5.254
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote_addrs = 87.190.254.122
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local_port = 500
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote_port = 500
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   send_certreq = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   send_cert = CERT_SEND_IF_ASKED
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   ppk_id = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   ppk_required = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   mobike = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   aggressive = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dscp = 0x00
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   encap = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dpd_delay = 5
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dpd_timeout = 20
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   fragmentation = 2
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   childless = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   unique = UNIQUE_REPLACE
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   keyingtries = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   reauth_time = 25920
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   rekey_time = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   over_time = 2880
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   rand_time = 2880
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   proposals = IKE:AES_CBC_256/AES_XCBC_96/PRF_AES128_XCBC/MODP_8192
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   if_id_in = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   if_id_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    class = pre-shared key
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    id = luphi
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    class = pre-shared key
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    id = dxclab
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] added vici connection: con1000
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] installing 'con1000'
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] configured proposals: ESP:AES_CBC_256/AES_XCBC_96/NO_EXT_SEQ
Jan  3 16:01:53 eagle1 charon[92988]: 14[CHD] CHILD_SA con1000{1} state change: CREATED => ROUTED
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] vici client 1 requests: load-conn
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]  conn con2000:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   child con2000:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_time = 3600
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_time = 3600
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_time = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_bytes = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rekey_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    life_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    rand_packets = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    updown = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    hostaccess = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    ipcomp = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mode = TUNNEL
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    policies = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    policies_fwd_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    dpd_action = restart
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    start_action = hold
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    close_action = clear
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    reqid = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    tfc = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    priority = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    interface = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    if_id_in = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    if_id_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_in = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_in_sa = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    mark_out = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    set_mark_in = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    set_mark_out = 0/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    inactivity = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    proposals = ESP:AES_CBC_256/AES_XCBC_96/MODP_8192/NO_EXT_SEQ
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    local_ts = 172.23.0.0/19|/0 172.23.0.0/19|/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    remote_ts = 10.42.0.0/20|/0 10.0.1.0/24|/0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    hw_offload = no
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    sha256_96 = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_df = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_ecn = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    copy_dscp = out
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   version = 2
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local_addrs = 172.23.5.254
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote_addrs = ssck.ddns.net
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local_port = 500
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote_port = 500
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   send_certreq = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   send_cert = CERT_SEND_IF_ASKED
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   ppk_id = (null)
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   ppk_required = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   mobike = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   aggressive = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dscp = 0x00
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   encap = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dpd_delay = 10
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   dpd_timeout = 60
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   fragmentation = 2
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   childless = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   unique = UNIQUE_REPLACE
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   keyingtries = 1
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   reauth_time = 25920
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   rekey_time = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   over_time = 2880
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   rand_time = 2880
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   proposals = IKE:AES_CBC_256/AES_XCBC_96/PRF_AES128_XCBC/MODP_8192
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   if_id_in = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   if_id_out = 0
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   local:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    class = pre-shared key
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    id = luphi
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]   remote:
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    class = pre-shared key
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG]    id = ssck
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] added vici connection: con2000
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] installing 'con2000'
Jan  3 16:01:53 eagle1 charon[92988]: 14[CFG] configured proposals: ESP:AES_CBC_256/AES_XCBC_96/NO_EXT_SEQ
Jan  3 16:01:53 eagle1 charon[92988]: 14[CHD] CHILD_SA con2000{2} state change: CREATED => ROUTED
Jan  3 16:01:53 eagle1 charon[92988]: 13[CFG] vici client 1 disconnected
Jan  3 16:01:53 eagle1 charon[92988]: 13[KNL] creating acquire job for policy 172.23.5.254/32|/0 === 93.245.202.216/32|/0 with reqid {2}
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing IKE_VENDOR task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing IKE_INIT task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing IKE_NATD task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing IKE_CERT_PRE task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing IKE_AUTH task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing IKE_CERT_POST task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing IKE_CONFIG task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing IKE_AUTH_LIFETIME task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing CHILD_CREATE task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> activating new tasks
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating IKE_VENDOR task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating IKE_INIT task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating IKE_NATD task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating IKE_CERT_PRE task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating IKE_AUTH task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating IKE_CERT_POST task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating IKE_CONFIG task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating CHILD_CREATE task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating IKE_AUTH_LIFETIME task
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> initiating IKE_SA con2000[1] to 93.245.202.216
Jan  3 16:01:53 eagle1 charon[92988]: 12[IKE] <con2000|1> IKE_SA con2000[1] state change: CREATED => CONNECTING
Jan  3 16:01:53 eagle1 charon[92988]: 12[CFG] <con2000|1> configured proposals: IKE:AES_CBC_256/AES_XCBC_96/PRF_AES128_XCBC/MODP_8192
Jan  3 16:01:53 eagle1 charon[92988]: 12[CFG] <con2000|1> sending supported signature hash algorithms: sha256 sha384 sha512 identity
Jan  3 16:01:53 eagle1 charon[92988]: 12[ENC] <con2000|1> generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Jan  3 16:01:53 eagle1 charon[92988]: 12[NET] <con2000|1> sending packet: from 172.23.5.254[500] to 93.245.202.216[500] (1232 bytes)
Jan  3 16:01:54 eagle1 charon[92988]: 12[NET] <con2000|1> received packet: from 93.245.202.216[500] to 172.23.5.254[500] (1232 bytes)
Jan  3 16:01:54 eagle1 charon[92988]: 12[ENC] <con2000|1> parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(MULT_AUTH) ]
Jan  3 16:01:54 eagle1 charon[92988]: 12[IKE] <con2000|1> received FRAGMENTATION_SUPPORTED notify
Jan  3 16:01:54 eagle1 charon[92988]: 12[IKE] <con2000|1> received SIGNATURE_HASH_ALGORITHMS notify
Jan  3 16:01:54 eagle1 charon[92988]: 12[CFG] <con2000|1> selecting proposal:
Jan  3 16:01:54 eagle1 charon[92988]: 12[CFG] <con2000|1>   proposal matches
Jan  3 16:01:54 eagle1 charon[92988]: 12[CFG] <con2000|1> received proposals: IKE:AES_CBC_256/AES_XCBC_96/PRF_AES128_XCBC/MODP_8192
Jan  3 16:01:54 eagle1 charon[92988]: 12[CFG] <con2000|1> configured proposals: IKE:AES_CBC_256/AES_XCBC_96/PRF_AES128_XCBC/MODP_8192
Jan  3 16:01:54 eagle1 charon[92988]: 12[CFG] <con2000|1> selected proposal: IKE:AES_CBC_256/AES_XCBC_96/PRF_AES128_XCBC/MODP_8192
Jan  3 16:01:54 eagle1 charon[92988]: 12[CFG] <con2000|1> received supported signature hash algorithms: sha256 sha384 sha512 identity
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> local host is behind NAT, sending keep alives
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> remote host is behind NAT
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> reinitiating already active tasks
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1>   IKE_CERT_PRE task
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1>   IKE_AUTH task
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> authentication of 'luphi' (myself) with pre-shared key
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> successfully created shared key MAC
Jan  3 16:01:55 eagle1 charon[92988]: 12[CFG] <con2000|1> proposing traffic selectors for us:
Jan  3 16:01:55 eagle1 charon[92988]: 12[CFG] <con2000|1>  172.23.0.0/19|/0
Jan  3 16:01:55 eagle1 charon[92988]: 12[CFG] <con2000|1>  172.23.0.0/19|/0
Jan  3 16:01:55 eagle1 charon[92988]: 12[CFG] <con2000|1> proposing traffic selectors for other:
Jan  3 16:01:55 eagle1 charon[92988]: 12[CFG] <con2000|1>  10.42.0.0/20|/0
Jan  3 16:01:55 eagle1 charon[92988]: 12[CFG] <con2000|1>  10.0.1.0/24|/0
Jan  3 16:01:55 eagle1 charon[92988]: 12[CFG] <con2000|1> configured proposals: ESP:AES_CBC_256/AES_XCBC_96/NO_EXT_SEQ
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> establishing CHILD_SA con2000{3} reqid 2
Jan  3 16:01:55 eagle1 charon[92988]: 12[ENC] <con2000|1> generating IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(ESP_TFC_PAD_N) SA TSi TSr N(MULT_AUTH) N(EAP_ONLY) N(MSG_ID_SYN_SUP) ]
Jan  3 16:01:55 eagle1 charon[92988]: 12[NET] <con2000|1> sending packet: from 172.23.5.254[4500] to 93.245.202.216[4500] (268 bytes)
Jan  3 16:01:55 eagle1 charon[92988]: 12[NET] <con2000|1> received packet: from 93.245.202.216[4500] to 172.23.5.254[4500] (124 bytes)
Jan  3 16:01:55 eagle1 charon[92988]: 12[ENC] <con2000|1> parsed IKE_AUTH response 1 [ IDr AUTH N(AUTH_LFT) N(NO_PROP) ]
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> authentication of 'ssck' with pre-shared key successful
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> IKE_SA con2000[1] established between 172.23.5.254[luphi]...93.245.202.216[ssck]
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> IKE_SA con2000[1] state change: CONNECTING => ESTABLISHED
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> scheduling reauthentication in 24475s
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> maximum IKE_SA lifetime 27355s
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> received NO_PROPOSAL_CHOSEN notify, no CHILD_SA built
Jan  3 16:01:55 eagle1 charon[92988]: 12[CFG] <con2000|1> configured proposals: ESP:AES_CBC_256/AES_XCBC_96/MODP_8192/NO_EXT_SEQ
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> failed to establish CHILD_SA, keeping IKE_SA
Jan  3 16:01:55 eagle1 charon[92988]: 12[CHD] <con2000|1> CHILD_SA con2000{3} state change: CREATED => DESTROYING
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> received AUTH_LIFETIME of 28232s, reauthentication already scheduled in 24475s
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> activating new tasks
Jan  3 16:01:55 eagle1 charon[92988]: 12[IKE] <con2000|1> nothing to initiate
Jan  3 16:01:55 eagle1 charon[92988]: 10[CFG] vici client 2 connected
Jan  3 16:01:55 eagle1 charon[92988]: 09[CFG] vici client 2 registered for: list-sa
Jan  3 16:01:55 eagle1 charon[92988]: 09[CFG] vici client 2 requests: list-sas
Jan  3 16:01:55 eagle1 charon[92988]: 09[CFG] vici client 2 disconnected
Jan  3 16:01:57 eagle1 charon[92988]: 10[CFG] vici client 3 connected
Jan  3 16:01:57 eagle1 charon[92988]: 10[CFG] vici client 3 registered for: list-sa
Jan  3 16:01:57 eagle1 charon[92988]: 12[CFG] vici client 3 requests: list-sas
Jan  3 16:01:57 eagle1 charon[92988]: 10[CFG] vici client 3 disconnected
Jan  3 16:01:59 eagle1 charon[92988]: 12[KNL] creating acquire job for policy 172.23.5.254/32|/0 === 93.245.202.216/32|/0 with reqid {2}
Jan  3 16:01:59 eagle1 charon[92988]: 12[IKE] <con2000|1> queueing CHILD_CREATE task
Jan  3 16:01:59 eagle1 charon[92988]: 12[IKE] <con2000|1> activating new tasks
Jan  3 16:01:59 eagle1 charon[92988]: 12[IKE] <con2000|1>   activating CHILD_CREATE task
Jan  3 16:01:59 eagle1 charon[92988]: 12[CFG] <con2000|1> proposing traffic selectors for us:
Jan  3 16:01:59 eagle1 charon[92988]: 12[CFG] <con2000|1>  172.23.0.0/19|/0
Jan  3 16:01:59 eagle1 charon[92988]: 12[CFG] <con2000|1>  172.23.0.0/19|/0
Jan  3 16:01:59 eagle1 charon[92988]: 12[CFG] <con2000|1> proposing traffic selectors for other:
Jan  3 16:01:59 eagle1 charon[92988]: 12[CFG] <con2000|1>  10.42.0.0/20|/0
Jan  3 16:01:59 eagle1 charon[92988]: 12[CFG] <con2000|1>  10.0.1.0/24|/0
Jan  3 16:01:59 eagle1 charon[92988]: 12[CFG] <con2000|1> configured proposals: ESP:AES_CBC_256/AES_XCBC_96/MODP_8192/NO_EXT_SEQ
Jan  3 16:01:59 eagle1 charon[92988]: 12[IKE] <con2000|1> establishing CHILD_SA con2000{4} reqid 2
Jan  3 16:01:59 eagle1 charon[92988]: 12[ENC] <con2000|1> generating CREATE_CHILD_SA request 2 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
Jan  3 16:01:59 eagle1 charon[92988]: 12[ENC] <con2000|1> splitting IKE message (1260 bytes) into 2 fragments
Jan  3 16:01:59 eagle1 charon[92988]: 12[ENC] <con2000|1> generating CREATE_CHILD_SA request 2 [ EF(1/2) ]
Jan  3 16:01:59 eagle1 charon[92988]: 12[ENC] <con2000|1> generating CREATE_CHILD_SA request 2 [ EF(2/2) ]
Jan  3 16:01:59 eagle1 charon[92988]: 12[NET] <con2000|1> sending packet: from 172.23.5.254[4500] to 93.245.202.216[4500] (1248 bytes)
Jan  3 16:01:59 eagle1 charon[92988]: 12[NET] <con2000|1> sending packet: from 172.23.5.254[4500] to 93.245.202.216[4500] (80 bytes)
Jan  3 16:02:00 eagle1 charon[92988]: 12[NET] <con2000|1> received packet: from 93.245.202.216[4500] to 172.23.5.254[4500] (76 bytes)
Jan  3 16:02:00 eagle1 charon[92988]: 12[ENC] <con2000|1> parsed CREATE_CHILD_SA response 2 [ N(NO_PROP) ]
Jan  3 16:02:00 eagle1 charon[92988]: 12[IKE] <con2000|1> received NO_PROPOSAL_CHOSEN notify, no CHILD_SA built
Jan  3 16:02:00 eagle1 charon[92988]: 12[CFG] <con2000|1> configured proposals: ESP:AES_CBC_256/AES_XCBC_96/MODP_8192/NO_EXT_SEQ
Jan  3 16:02:00 eagle1 charon[92988]: 12[IKE] <con2000|1> failed to establish CHILD_SA, keeping IKE_SA
Jan  3 16:02:00 eagle1 charon[92988]: 12[CHD] <con2000|1> CHILD_SA con2000{4} state change: CREATED => DESTROYING
Jan  3 16:02:00 eagle1 charon[92988]: 12[IKE] <con2000|1> activating new tasks
Jan  3 16:02:00 eagle1 charon[92988]: 12[IKE] <con2000|1> nothing to initiate
Jan  3 16:02:02 eagle1 charon[92988]: 08[CFG] vici client 4 connected
Jan  3 16:02:02 eagle1 charon[92988]: 08[CFG] vici client 4 registered for: list-sa
Jan  3 16:02:02 eagle1 charon[92988]: 08[CFG] vici client 4 requests: list-sas
Jan  3 16:02:02 eagle1 charon[92988]: 08[CFG] vici client 4 disconnected

luphi

When I try to edit p1 proposal, the key-length is always empty