Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Wrong route installed on FreeBSD? #1807

Closed
rionda opened this issue Jul 24, 2023 · 10 comments
Closed

Wrong route installed on FreeBSD? #1807

rionda opened this issue Jul 24, 2023 · 10 comments
Labels

Comments

@rionda
Copy link

rionda commented Jul 24, 2023

System:

  • OS: FreeBSD 14.0-CURRENT #0 main-n264135-510fd8313800
  • strongSwan version(s): strongswan-5.9.10_1 from FreeBSD pkg
  • Tested/confirmed with the latest version: no

Describe the bug

Strongswan installs what seems a wrong route to the remote network specified in the remote traffic selector.

To Reproduce

  1. Initiate the IPSec connection with swanctl -i -c myvpn-lan (see config below). Get virtual ip 171.24.1.1, belonging to remote lan is 172.24.0.0/16, specified through remote_ts)
  2. Try to ping an known-to-be-up host on the remote lan (ping 172.24.2.1)
  3. Get "Host is down". No packets are seen when tcpdumping on enc0, thus no packets seem to be leaving the host through the VPN.
  4. Inspect the routing table with nestat -rn4W. Notice an unexpected route to the remote LAN, which did not exist before (output given below).

Workaround: manually remote the route added by strongswan (route delete 172.24.0.0/16), add new route to remote LAN using tun0 as interface (route add 172.24.0.0/16 -interface tun0). Pinging 172.24.2.1 now works. Output given below.

Expected behavior
Pinging should work.

(I'm also a bit surprised that a route is needed: I thought the policies visible through setkey -D -P were supposed to be enough).

Additional context

My client config:

connections {
    myvpn {
        version = 2
        remote_addrs = myremoteserver
        vips = 0.0.0.0
        rekey_time = 2h
        dpd_delay = 30s
        proposals = aes256gcm128-prfsha512-curve25519-modp4096,aes256gcm128-prfsha384-ecp521-modp4096

        local {
            id = myclient
            certs = myclient-cert.der
        }

        remote {
            id = myremoteserver
            cacerts = myca-cert.der
        }

        children {
            myvpn-lan {
                ipcomp = yes
                rekey_bytes = 536870912 # 512 MB
                esp_proposals = aes256gcm128-prfsha512-prfsha384-curve25519-ecp521-modp4096-esn
                remote_ts = 172.24.0.0/16
            }
        }
    }

}

The routing table on my client before initiating the ipsec connection with swanctl -i -c myvpn-lan:

myclient ~ % netstat -rn4W 
Routing tables

Internet:
Destination        Gateway            Flags   Nhop#    Mtu      Netif Expire
default            192.168.1.5        UGS         4   1500      wlan0
127.0.0.1          link#2             UH          1  16384        lo0
192.168.1.0/24     link#3             U           2   1500      wlan0
192.168.1.10       link#2             UHS         3  16384        lo0

The ifconfig on my client before initiating the ipsec connection:

myclient ~ % ifconfig
em0: flags=8802<BROADCAST,SIMPLEX,MULTICAST> metric 0 mtu 1500
	options=481249b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,LRO,WOL_MAGIC,VLAN_HWFILTER,HWSTATS,MEXTPG>
	ether 64:00:6a:5c:58:9c
	media: Ethernet autoselect
	status: no carrier
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
lo0: flags=1008049<UP,LOOPBACK,RUNNING,MULTICAST,LOWER_UP> metric 0 mtu 16384
	options=680003<RXCSUM,TXCSUM,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
	inet 127.0.0.1 netmask 0xff000000
	inet6 ::1 prefixlen 128
	inet6 fe80::1%lo0 prefixlen 64 scopeid 0x2
	groups: lo
	nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
wlan0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
	options=0
	ether 10:4a:7d:cf:6f:52
	inet 192.168.1.10 netmask 0xffffff00 broadcast 192.168.1.255
	groups: wlan
	ssid myssid channel 3 (2422 MHz 11g) bssid 3c:37:86:7f:50:7c
	regdomain FCC country US authmode WPA2/802.11i privacy ON
	deftxkey UNDEF AES-CCM 2:128-bit txpower 30 bmiss 10 scanvalid 60
	protmode CTS wme roaming MANUAL bintval 200
	parent interface: iwm0
	media: IEEE 802.11 Wireless Ethernet OFDM/54Mbps mode 11g
	status: associated
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
enc0: flags=1000041<UP,RUNNING,LOWER_UP> metric 0 mtu 1536
	options=0
	groups: enc
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>                                              

The log collected from charon when initializing the remote connection:

Mon, 2023-07-24, 08:35:03 13[CFG2] vici client 1 disconnected
Mon, 2023-07-24, 08:35:40 04[CFG2] vici client 2 connected
Mon, 2023-07-24, 08:35:40 04[CFG2] vici client 2 registered for: control-log
Mon, 2023-07-24, 08:35:40 04[CFG2] vici client 2 requests: initiate
Mon, 2023-07-24, 08:35:40 04[CFG1] vici initiate CHILD_SA 'myvpn-lan'
Mon, 2023-07-24, 08:35:40 13[MGR2] checkout IKE_SA by config
Mon, 2023-07-24, 08:35:40 13[MGR2] created IKE_SA (unnamed)[1]
Mon, 2023-07-24, 08:35:40 17[LIB2] created thread 17 [12599c44d000]
Mon, 2023-07-24, 08:35:41 13[KNL2] <myvpn|1> using 192.168.1.10 as address to reach myremoteserverip
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_VENDOR task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_INIT task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_NATD task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_CERT_PRE task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_AUTH task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_CERT_POST task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_CONFIG task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_AUTH_LIFETIME task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_MOBIKE task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing IKE_ESTABLISH task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> queueing CHILD_CREATE task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> activating new tasks
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_VENDOR task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_INIT task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_NATD task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_CERT_PRE task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_AUTH task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_CERT_POST task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_CONFIG task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_AUTH_LIFETIME task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_MOBIKE task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating IKE_ESTABLISH task
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1>   activating CHILD_CREATE task
Mon, 2023-07-24, 08:35:41 13[IKE0] <myvpn|1> initiating IKE_SA myvpn[1] to myremoteserverip
Mon, 2023-07-24, 08:35:41 13[IKE2] <myvpn|1> IKE_SA myvpn[1] state change: CREATED => CONNECTING
Mon, 2023-07-24, 08:35:41 13[CFG2] <myvpn|1> configured proposals: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/CURVE_25519/MODP_4096, IKE:AES_GCM_16_256/PRF_HMAC_SHA2_384/ECP_521/MODP_4096
Mon, 2023-07-24, 08:35:41 13[CFG2] <myvpn|1> sending supported signature hash algorithms: sha256 sha384 sha512 identity
Mon, 2023-07-24, 08:35:41 13[ENC1] <myvpn|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) ]
Mon, 2023-07-24, 08:35:41 13[NET1] <myvpn|1> sending packet: from 192.168.1.10[500] to myremoteserverip[500] (284 bytes)
Mon, 2023-07-24, 08:35:41 13[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 0000000000000000_r
Mon, 2023-07-24, 08:35:41 05[NET2] sending packet: from 192.168.1.10[500] to myremoteserverip[500]
Mon, 2023-07-24, 08:35:41 13[MGR2] <myvpn|1> checkin of IKE_SA successful
Mon, 2023-07-24, 08:35:41 16[NET2] received packet: from myremoteserverip[500] to 192.168.1.10[500]
Mon, 2023-07-24, 08:35:41 16[NET2] waiting for data on sockets
Mon, 2023-07-24, 08:35:41 11[MGR2] checkout IKEv2 SA by message with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:41 11[MGR2] IKE_SA myvpn[1] successfully checked out
Mon, 2023-07-24, 08:35:41 11[NET1] <myvpn|1> received packet: from myremoteserverip[500] to 192.168.1.10[500] (265 bytes)
Mon, 2023-07-24, 08:35:41 11[ENC1] <myvpn|1> parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(FRAG_SUP) N(HASH_ALG) N(CHDLESS_SUP) N(MULT_AUTH) ]
Mon, 2023-07-24, 08:35:41 11[IKE2] <myvpn|1> received FRAGMENTATION_SUPPORTED notify
Mon, 2023-07-24, 08:35:41 11[IKE2] <myvpn|1> received SIGNATURE_HASH_ALGORITHMS notify
Mon, 2023-07-24, 08:35:41 11[IKE2] <myvpn|1> received CHILDLESS_IKEV2_SUPPORTED notify
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1> selecting proposal:
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1>   proposal matches
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1> received proposals: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/CURVE_25519
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1> configured proposals: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/CURVE_25519/MODP_4096, IKE:AES_GCM_16_256/PRF_HMAC_SHA2_384/ECP_521/MODP_4096
Mon, 2023-07-24, 08:35:41 11[CFG1] <myvpn|1> selected proposal: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/CURVE_25519
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1> received supported signature hash algorithms: sha256 sha384 sha512 identity
Mon, 2023-07-24, 08:35:41 11[IKE1] <myvpn|1> local host is behind NAT, sending keep alives
Mon, 2023-07-24, 08:35:41 11[IKE1] <myvpn|1> received cert request for "C=US, ST=mystate, L=mytown, O=myorg, CN=myca"
Mon, 2023-07-24, 08:35:41 11[IKE2] <myvpn|1> reinitiating already active tasks
Mon, 2023-07-24, 08:35:41 11[IKE2] <myvpn|1>   IKE_CERT_PRE task
Mon, 2023-07-24, 08:35:41 11[IKE2] <myvpn|1>   IKE_AUTH task
Mon, 2023-07-24, 08:35:41 11[IKE1] <myvpn|1> sending cert request for "C=US, ST=mystate, L=mytown, O=myorg, CN=myca"
Mon, 2023-07-24, 08:35:41 11[IKE1] <myvpn|1> authentication of 'myclient' (myself) with RSA_EMSA_PKCS1_SHA2_384 successful
Mon, 2023-07-24, 08:35:41 11[IKE1] <myvpn|1> sending end entity cert "C=US, ST=mystate, L=mytown, O=myorg, CN=myclient"
Mon, 2023-07-24, 08:35:41 11[IKE2] <myvpn|1> building INTERNAL_IP4_DNS attribute
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1> proposing traffic selectors for us:
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1>  0.0.0.0/0
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1> proposing traffic selectors for other:
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1>  172.24.0.0/16
Mon, 2023-07-24, 08:35:41 11[CFG2] <myvpn|1> configured proposals: ESP:AES_GCM_16_256/EXT_SEQ
Mon, 2023-07-24, 08:35:41 11[IKE0] <myvpn|1> establishing CHILD_SA myvpn-lan{1}
Mon, 2023-07-24, 08:35:41 11[KNL2] <myvpn|1> got SPI c586b8e0
Mon, 2023-07-24, 08:35:41 11[KNL2] <myvpn|1> getting CPI
Mon, 2023-07-24, 08:35:41 11[KNL2] <myvpn|1> got CPI d462
Mon, 2023-07-24, 08:35:41 11[ENC1] <myvpn|1> generating IKE_AUTH request 1 [ IDi CERT N(INIT_CONTACT) CERTREQ IDr AUTH CPRQ(ADDR DNS) N(IPCOMP_SUP) N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(NO_ADD_ADDR) N(MULT_AUTH) N(EAP_ONLY) N(MSG_ID_SYN_SUP) ]
Mon, 2023-07-24, 08:35:41 11[ENC1] <myvpn|1> splitting IKE message (2256 bytes) into 2 fragments
Mon, 2023-07-24, 08:35:41 11[ENC1] <myvpn|1> generating IKE_AUTH request 1 [ EF(1/2) ]
Mon, 2023-07-24, 08:35:41 11[ENC1] <myvpn|1> generating IKE_AUTH request 1 [ EF(2/2) ]
Mon, 2023-07-24, 08:35:41 11[NET1] <myvpn|1> sending packet: from 192.168.1.10[4500] to myremoteserverip[4500] (1248 bytes)
Mon, 2023-07-24, 08:35:41 11[NET1] <myvpn|1> sending packet: from 192.168.1.10[4500] to myremoteserverip[4500] (1073 bytes)
Mon, 2023-07-24, 08:35:41 05[NET2] sending packet: from 192.168.1.10[4500] to myremoteserverip[4500]
Mon, 2023-07-24, 08:35:41 11[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:41 11[MGR2] <myvpn|1> checkin of IKE_SA successful
Mon, 2023-07-24, 08:35:41 05[NET2] sending packet: from 192.168.1.10[4500] to myremoteserverip[4500]
Mon, 2023-07-24, 08:35:42 16[NET2] received packet: from myremoteserverip[4500] to 192.168.1.10[4500]
Mon, 2023-07-24, 08:35:42 16[NET2] waiting for data on sockets
Mon, 2023-07-24, 08:35:42 11[MGR2] checkout IKEv2 SA by message with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:42 11[MGR2] IKE_SA myvpn[1] successfully checked out
Mon, 2023-07-24, 08:35:42 11[NET1] <myvpn|1> received packet: from myremoteserverip[4500] to 192.168.1.10[4500] (1248 bytes)
Mon, 2023-07-24, 08:35:42 11[ENC1] <myvpn|1> parsed IKE_AUTH response 1 [ EF(1/2) ]
Mon, 2023-07-24, 08:35:42 11[ENC1] <myvpn|1> received fragment #1 of 2, waiting for complete IKE message
Mon, 2023-07-24, 08:35:42 11[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:42 11[MGR2] <myvpn|1> checkin of IKE_SA successful
Mon, 2023-07-24, 08:35:42 16[NET2] received packet: from myremoteserverip[4500] to 192.168.1.10[4500]
Mon, 2023-07-24, 08:35:42 16[NET2] waiting for data on sockets
Mon, 2023-07-24, 08:35:42 09[MGR2] checkout IKEv2 SA by message with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:42 09[MGR2] IKE_SA myvpn[1] successfully checked out
Mon, 2023-07-24, 08:35:42 09[NET1] <myvpn|1> received packet: from myremoteserverip[4500] to 192.168.1.10[4500] (1113 bytes)
Mon, 2023-07-24, 08:35:42 09[ENC1] <myvpn|1> parsed IKE_AUTH response 1 [ EF(2/2) ]
Mon, 2023-07-24, 08:35:42 09[ENC1] <myvpn|1> received fragment #2 of 2, reassembled fragmented IKE message (2296 bytes)
Mon, 2023-07-24, 08:35:42 09[ENC1] <myvpn|1> parsed IKE_AUTH response 1 [ IDr CERT AUTH CPRP(ADDR DNS) N(IPCOMP_SUP) N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) ]
Mon, 2023-07-24, 08:35:42 09[LIB2] <myvpn|1> builder L0 CRED_CERTIFICATE - X509 of plugin 'x509'
Mon, 2023-07-24, 08:35:42 09[LIB2] <myvpn|1> builder L0 CRED_CERTIFICATE - X509 of plugin 'x509'
Mon, 2023-07-24, 08:35:42 09[LIB2] <myvpn|1> builder L1 CRED_PUBLIC_KEY - ANY of plugin 'pkcs1'
Mon, 2023-07-24, 08:35:42 09[LIB2] <myvpn|1> builder L2 CRED_PUBLIC_KEY - RSA of plugin 'pkcs1'
Mon, 2023-07-24, 08:35:42 09[LIB2] <myvpn|1> builder L3 CRED_PUBLIC_KEY - RSA of plugin 'pkcs1'
Mon, 2023-07-24, 08:35:42 09[LIB2] <myvpn|1> builder L3 CRED_PUBLIC_KEY - RSA of plugin 'pgp'
Mon, 2023-07-24, 08:35:42 09[LIB2] <myvpn|1> builder L3 CRED_PUBLIC_KEY - RSA of plugin 'dnskey'
Mon, 2023-07-24, 08:35:42 09[LIB2] <myvpn|1> builder L3 CRED_PUBLIC_KEY - RSA of plugin 'openssl'
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> received end entity cert "C=US, ST=mystate, L=mytown, O=myorg, CN=my"
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> received IPCOMP_SUPPORTED notify
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> received ESP_TFC_PADDING_NOT_SUPPORTED notify
Mon, 2023-07-24, 08:35:42 09[CFG1] <myvpn|1>   using certificate "C=US, ST=mystate, L=mytown, O=myorg, CN=my"
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1>   certificate "C=US, ST=mystate, L=mytown, O=myorg, CN=my" key: 4096 bit RSA
Mon, 2023-07-24, 08:35:42 09[CFG1] <myvpn|1>   using trusted ca certificate "C=US, ST=mystate, L=mytown, O=myorg, CN=myca"
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1>   certificate "C=US, ST=mystate, L=mytown, O=myorg, CN=myca" key: 4096 bit RSA
Mon, 2023-07-24, 08:35:42 09[CFG1] <myvpn|1>   reached self-signed root ca with a path length of 0
Mon, 2023-07-24, 08:35:42 09[CFG1] <myvpn|1> checking certificate status of "C=US, ST=mystate, L=mytown, O=myorg, CN=my"
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1> ocsp check skipped, no ocsp found
Mon, 2023-07-24, 08:35:42 09[CFG1] <myvpn|1> certificate status is not available
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> authentication of 'myremoteserver' with RSA_EMSA_PKCS1_SHA2_384 successful
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> processing INTERNAL_IP4_ADDRESS attribute
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> processing INTERNAL_IP4_DNS attribute
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> installing DNS server 172.24.2.1 via resolvconf
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> 192.168.1.10 is on interface wlan0
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> installing new virtual IP 172.24.1.1
Mon, 2023-07-24, 08:35:42 09[LIB1] <myvpn|1> created TUN device: tun0
Mon, 2023-07-24, 08:35:42 08[KNL1] interface tun0 appeared
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> 172.24.1.1 is not a local address or the interface is down
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> 172.24.1.1 is not a local address or the interface is down
Mon, 2023-07-24, 08:35:42 08[KNL1] interface tun0 activated
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> peer supports MOBIKE
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> got additional MOBIKE peer address: 10.108.4.14
Mon, 2023-07-24, 08:35:42 09[IKE0] <myvpn|1> IKE_SA myvpn[1] established between 192.168.1.10[myclient]...myremoteserverip[myremoteserver]
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> IKE_SA myvpn[1] state change: CONNECTING => ESTABLISHED
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> scheduling rekeying in 6728s
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> maximum IKE_SA lifetime 7448s
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1> selecting proposal:
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1>   proposal matches
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1> received proposals: ESP:AES_GCM_16_256/EXT_SEQ
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1> configured proposals: ESP:AES_GCM_16_256/CURVE_25519/ECP_521/MODP_4096/EXT_SEQ
Mon, 2023-07-24, 08:35:42 09[CFG1] <myvpn|1> selected proposal: ESP:AES_GCM_16_256/EXT_SEQ
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1> selecting traffic selectors for us:
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1>  config: 172.24.1.1/32, received: 172.24.1.1/32 => match: 172.24.1.1/32
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1> selecting traffic selectors for other:
Mon, 2023-07-24, 08:35:42 09[CFG2] <myvpn|1>  config: 172.24.0.0/16, received: 172.24.0.0/16 => match: 172.24.0.0/16
Mon, 2023-07-24, 08:35:42 09[CHD2] <myvpn|1> CHILD_SA myvpn-lan{1} state change: CREATED => INSTALLING
Mon, 2023-07-24, 08:35:42 09[CHD2] <myvpn|1>   using AES_GCM_16 for encryption
Mon, 2023-07-24, 08:35:42 09[CHD2] <myvpn|1> adding inbound ESP SA
Mon, 2023-07-24, 08:35:42 09[CHD2] <myvpn|1>   SPI 0xc586b8e0, src myremoteserverip dst 192.168.1.10
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> deleting SAD entry with SPI 0000d462
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> deleted SAD entry with SPI 0000d462
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> adding SAD entry with SPI 0000d462 and reqid {1}
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> deleting SAD entry with SPI c586b8e0
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> deleted SAD entry with SPI c586b8e0
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> adding SAD entry with SPI c586b8e0 and reqid {1}
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1>   using extended sequence numbers (ESN)
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1>   using encryption algorithm AES_GCM_16 with key size 288
Mon, 2023-07-24, 08:35:42 09[CHD2] <myvpn|1> adding outbound ESP SA
Mon, 2023-07-24, 08:35:42 09[CHD2] <myvpn|1>   SPI 0xc9dcfedd, src 192.168.1.10 dst myremoteserverip
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> adding SAD entry with SPI 00009fb5 and reqid {1}
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> adding SAD entry with SPI c9dcfedd and reqid {1}
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1>   using extended sequence numbers (ESN)
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1>   using encryption algorithm AES_GCM_16 with key size 288
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> adding policy 172.24.0.0/16 === 172.24.1.1/32 in
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> adding policy 172.24.1.1/32 === 172.24.0.0/16 out
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> getting a local address in traffic selector 172.24.1.1/32
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> using host 172.24.1.1
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> using 192.168.1.5 as nexthop to reach myremoteserverip
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> installing route: 172.24.0.0/16 via 192.168.1.5 src 172.24.1.1 dev wlan0
Mon, 2023-07-24, 08:35:42 09[IKE0] <myvpn|1> CHILD_SA myvpn-lan{1} established with SPIs c586b8e0_i c9dcfedd_o and TS 172.24.1.1/32 === 172.24.0.0/16
Mon, 2023-07-24, 08:35:42 09[CHD2] <myvpn|1> CHILD_SA myvpn-lan{1} state change: INSTALLING => INSTALLED
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> activating new tasks
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> nothing to initiate
Mon, 2023-07-24, 08:35:42 09[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:42 09[MGR2] <myvpn|1> checkin of IKE_SA successful
Mon, 2023-07-24, 08:35:42 07[CFG2] vici client 2 disconnected
Mon, 2023-07-24, 08:35:42 09[KNL2] creating roam job due to address/link change
Mon, 2023-07-24, 08:35:42 09[MGR2] checkout IKEv2 SA with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:42 09[MGR2] IKE_SA myvpn[1] successfully checked out
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> using 192.168.1.10 as address to reach myremoteserverip
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> keeping connection path 192.168.1.10 - myremoteserverip
Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> sending address list update using MOBIKE
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> queueing IKE_MOBIKE task
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> activating new tasks
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1>   activating IKE_MOBIKE task
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> using 192.168.1.10 as address to reach myremoteserverip
Mon, 2023-07-24, 08:35:42 09[ENC1] <myvpn|1> generating INFORMATIONAL request 2 [ N(ADD_4_ADDR) ]
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> using 192.168.1.10 as address to reach myremoteserverip
Mon, 2023-07-24, 08:35:42 09[NET1] <myvpn|1> sending packet: from 192.168.1.10[4500] to myremoteserverip[4500] (69 bytes)
Mon, 2023-07-24, 08:35:42 09[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:42 09[MGR2] <myvpn|1> checkin of IKE_SA successful
Mon, 2023-07-24, 08:35:42 05[NET2] sending packet: from 192.168.1.10[4500] to myremoteserverip[4500]
Mon, 2023-07-24, 08:35:42 16[NET2] received packet: from myremoteserverip[4500] to 192.168.1.10[4500]
Mon, 2023-07-24, 08:35:42 16[NET2] waiting for data on sockets
Mon, 2023-07-24, 08:35:42 09[MGR2] checkout IKEv2 SA by message with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:42 09[MGR2] IKE_SA myvpn[1] successfully checked out
Mon, 2023-07-24, 08:35:42 09[NET1] <myvpn|1> received packet: from myremoteserverip[4500] to 192.168.1.10[4500] (57 bytes)
Mon, 2023-07-24, 08:35:42 09[ENC1] <myvpn|1> parsed INFORMATIONAL response 2 [ ]
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> activating new tasks
Mon, 2023-07-24, 08:35:42 09[IKE2] <myvpn|1> nothing to initiate
Mon, 2023-07-24, 08:35:42 09[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:42 09[MGR2] <myvpn|1> checkin of IKE_SA successful
Mon, 2023-07-24, 08:35:45 09[MGR2] checkout IKEv2 SA with SPIs e4a7bf29f0ac7601_i 0000000000000000_r
Mon, 2023-07-24, 08:35:45 09[MGR2] IKE_SA myvpn[1] successfully checked out
Mon, 2023-07-24, 08:35:45 09[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:45 09[MGR2] <myvpn|1> checkin of IKE_SA successful
Mon, 2023-07-24, 08:35:45 07[MGR2] checkout IKEv2 SA with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:45 07[MGR2] IKE_SA myvpn[1] successfully checked out
Mon, 2023-07-24, 08:35:45 07[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:45 07[MGR2] <myvpn|1> checkin of IKE_SA successful
Mon, 2023-07-24, 08:35:46 07[MGR2] checkout IKEv2 SA with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:46 07[MGR2] IKE_SA myvpn[1] successfully checked out
Mon, 2023-07-24, 08:35:46 07[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs e4a7bf29f0ac7601_i 880431e6013f7583_r
Mon, 2023-07-24, 08:35:46 07[MGR2] <myvpn|1> checkin of IKE_SA successful

The ifconfig on my client after having established the remote connection:

myclient ~ % ifconfig
em0: flags=8802<BROADCAST,SIMPLEX,MULTICAST> metric 0 mtu 1500
	options=481249b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,LRO,WOL_MAGIC,VLAN_HWFILTER,HWSTATS,MEXTPG>
	ether 64:00:6a:5c:58:9c
	media: Ethernet autoselect
	status: no carrier
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
lo0: flags=1008049<UP,LOOPBACK,RUNNING,MULTICAST,LOWER_UP> metric 0 mtu 16384
	options=680003<RXCSUM,TXCSUM,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
	inet 127.0.0.1 netmask 0xff000000
	inet6 ::1 prefixlen 128
	inet6 fe80::1%lo0 prefixlen 64 scopeid 0x2
	groups: lo
	nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
wlan0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
	options=0
	ether 10:4a:7d:cf:6f:52
	inet 192.168.1.10 netmask 0xffffff00 broadcast 192.168.1.255
	groups: wlan
	ssid myssid channel 3 (2422 MHz 11g) bssid 3c:37:86:7f:50:7c
	regdomain FCC country US authmode WPA2/802.11i privacy ON
	deftxkey UNDEF AES-CCM 2:128-bit txpower 30 bmiss 10 scanvalid 60
	protmode CTS wme roaming MANUAL bintval 200
	parent interface: iwm0
	media: IEEE 802.11 Wireless Ethernet OFDM/48Mbps mode 11g
	status: associated
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
enc0: flags=1000041<UP,RUNNING,LOWER_UP> metric 0 mtu 1536
	options=0
	groups: enc
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
tun0: flags=1008051<UP,POINTOPOINT,RUNNING,MULTICAST,LOWER_UP> metric 0 mtu 1400
	options=80000<LINKSTATE>
	inet 172.24.1.1 --> 172.24.1.1 netmask 0xffffffff
	groups: tun
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
	Opened by PID 10788

The routing table on my client after having established the remote connection:

myclient ~ % netstat -rn4W 
Routing tables

Internet:
Destination        Gateway            Flags   Nhop#    Mtu      Netif Expire
default            192.168.1.5        UGS         4   1500      wlan0
127.0.0.1          link#2             UH          1  16384        lo0
172.24.0.0/16      link#3             US          6   1500      wlan0
172.24.1.1         link#4             UH          5   1400       tun0
192.168.1.0/24     link#3             U           2   1500      wlan0
192.168.1.10       link#2             UHS         3  16384        lo0

The line

172.24.0.0/16      link#3             US          6   1500      wlan0

seems weird to me.

The output of setkey -DP on the client after having established the remote connection:

myclient ~ % sudo setkey -D -P
172.24.0.0/16[any] 172.24.1.1[any] any
	in ipsec
	ipcomp/tunnel/myremoteserverip-192.168.1.10/use
	esp/transport//unique:1
	created: Jul 24 08:35:46 2023  lastused: Jul 24 09:12:15 2023
	lifetime: 9223372036854775807(s) validtime: 0(s)
	spid=3 seq=1 pid=69389 scope=global 
	refcnt=1
172.24.1.1[any] 172.24.0.0/16[any] any
	out ipsec
	ipcomp/tunnel/192.168.1.10-myremoteserverip/unique:1
	esp/transport//unique:1
	created: Jul 24 08:35:46 2023  lastused: Jul 24 09:12:07 2023
	lifetime: 9223372036854775807(s) validtime: 0(s)
	spid=4 seq=0 pid=69389 scope=global 
	refcnt=1

The output of ping 172.24.2.1

myclient ~ % ping 172.24.2.1
PING 172.24.2.1 (172.24.2.1): 56 data bytes
ping: sendto: Host is down
^C
--- 172.24.2.1 ping statistics ---
6 packets transmitted, 0 packets received, 100.0% packet loss

The commands given to workaround the issues, and their output

myclient ~ % sudo route delete 172.24.0.0/16
delete net 172.24.0.0
myclient ~ % sudo route add 172.24.0.0/16 -interface tun0
add net 172.24.0.0: gateway tun0
myclient ~ % netstat -rn4W
Routing tables

Internet:
Destination        Gateway            Flags   Nhop#    Mtu      Netif Expire
default            192.168.1.5        UGS         4   1500      wlan0
127.0.0.1          link#2             UH          1  16384        lo0
172.24.0.0/16      link#4             US          6   1400       tun0
172.24.1.1         link#4             UH          5   1400       tun0
192.168.1.0/24     link#3             U           2   1500      wlan0
192.168.1.10       link#2             UHS         3  16384        lo0
myclient ~ % ping 172.24.2.1
PING 172.24.2.1 (172.24.2.1): 56 data bytes
64 bytes from 172.24.2.1: icmp_seq=0 ttl=64 time=31.745 ms
64 bytes from 172.24.2.1: icmp_seq=1 ttl=64 time=25.604 ms
64 bytes from 172.24.2.1: icmp_seq=2 ttl=64 time=23.694 ms
64 bytes from 172.24.2.1: icmp_seq=3 ttl=64 time=25.397 ms
64 bytes from 172.24.2.1: icmp_seq=4 ttl=64 time=23.529 ms
64 bytes from 172.24.2.1: icmp_seq=5 ttl=64 time=30.080 ms
64 bytes from 172.24.2.1: icmp_seq=6 ttl=64 time=25.801 ms
64 bytes from 172.24.2.1: icmp_seq=7 ttl=64 time=22.290 ms
64 bytes from 172.24.2.1: icmp_seq=8 ttl=64 time=29.521 ms
^C
--- 172.24.2.1 ping statistics ---
9 packets transmitted, 9 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 22.290/26.407/31.745/3.097 ms
@tobiasbrunner
Copy link
Member

(I'm also a bit surprised that a route is needed: I thought the policies visible through setkey -D -P were supposed to be enough).

The route is needed exactly in order for packets to match the policy as it forces the virtual IP (the local traffic selector in the policy) as source IP when sending packets to the destination (remote traffic selector). On Linux, we use routes with preferred source IP, on FreeBSD/macOS, we use routes via TUN devices instead (which are only used to force the source IP, not to actually send any traffic through).

Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> getting a local address in traffic selector 172.24.1.1/32
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> using host 172.24.1.1
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> using 192.168.1.5 as nexthop to reach myremoteserverip
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> installing route: 172.24.0.0/16 via 192.168.1.5 src 172.24.1.1 dev wlan0

This looks like the virtual IP is not treated as such. If it was, you'd see a message saying virtual IP 172.24.1.1 is on interface tun0 and the route would go via tun0.

Mon, 2023-07-24, 08:35:42 09[IKE1] <myvpn|1> installing new virtual IP 172.24.1.1
Mon, 2023-07-24, 08:35:42 09[LIB1] <myvpn|1> created TUN device: tun0
Mon, 2023-07-24, 08:35:42 08[KNL1] interface tun0 appeared
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> 172.24.1.1 is not a local address or the interface is down
Mon, 2023-07-24, 08:35:42 09[KNL2] <myvpn|1> 172.24.1.1 is not a local address or the interface is down
Mon, 2023-07-24, 08:35:42 08[KNL1] interface tun0 activated

At a first glance this looks fine. That is, the interface is known, as is the IP address on it (otherwise, we'd see an error saying virtual IP 172.24.1.1 did not appear on tun0).

However, after waiting for the virtual IP address to appear on an interface, we mark the address as virtual in the internal address list so it can later be treated differently (as described above). The problem is that the event that handles changes of interface flags (in this case that the interface is activated) clears and repopulates the internal address list for that interface. If this happens after the address has already been marked, that virtual IP status is currently lost.

I've pushed a possible fix for this to the 1807-pfroute-vip branch.

@rionda
Copy link
Author

rionda commented Jul 25, 2023

(I'm also a bit surprised that a route is needed: I thought the policies visible through setkey -D -P were supposed to be enough).

The route is needed exactly in order for packets to match the policy as it forces the virtual IP (the local traffic selector in the policy) as source IP when sending packets to the destination (remote traffic selector). On Linux, we use routes with preferred source IP, on FreeBSD/macOS, we use routes via TUN devices instead (which are only used to force the source IP, not to actually send any traffic through).

I see. I don't think I could infer this from the docs, so thank you for the explanation.

As a side note, is there a way to select the source ip address used by the responder for the inner packets?
When I ping the roadwarrior from the responder, the inner packets from the responder come with an ip address that does not belong to the private lan (rather, they come with the public ip address of the responder).

[snip logs]
[snip other replies]
At a first glance this looks fine. That is, the interface is known, as is the IP address on it (otherwise, we'd see an error saying virtual IP 172.24.1.1 did not appear on tun0).

However, after waiting for the virtual IP address to appear on an interface, we mark the address as virtual in the internal address list so it can later be treated differently (as described above). The problem is that the event that handles changes of interface flags (in this case that the interface is activated) clears and repopulates the internal address list for that interface. If this happens after the address has already been marked, that virtual IP status is currently lost.

Thank you for the thorough explanation. Glad to hear it wasn't a misconfiguration on my side.

I've pushed a possible fix for this to the 1807-pfroute-vip branch.

Thanks, I'll give it a try later today.

@tobiasbrunner
Copy link
Member

As a side note, is there a way to select the source ip address used by the responder for the inner packets?

Depends on the platform, the existing routes and interfaces etc. If the server is running FreeBSD as well, you might have to enable charon.plugins.kernel-pfkey.route_via_internal in strongswan.conf.

Also, since the virtual IPs are from your remote LAN, are you using the farp plugin?

@rionda
Copy link
Author

rionda commented Jul 25, 2023

As a side note, is there a way to select the source ip address used by the responder for the inner packets?

Depends on the platform, the existing routes and interfaces etc. If the server is running FreeBSD as well, you might have to enable charon.plugins.kernel-pfkey.route_via_internal in strongswan.conf.

Yes, it is running FreeBSD. I'll give it a shot.

Also, since the virtual IPs are from your remote LAN, are you using the farp plugin?

Not yet, but it is on my list of things to setup.

@rionda
Copy link
Author

rionda commented Jul 25, 2023

I've pushed a possible fix for this to the 1807-pfroute-vip branch.

Thanks, I'll give it a try later today.

I compiled it, and run charon and swanctl from the build directory. I don't see any difference: the route is still installed "through" wlan0. Log from charon follows:

Tue, 2023-07-25, 15:54:55 13[CFG2] vici client 2 connected
Tue, 2023-07-25, 15:54:55 15[CFG2] vici client 2 registered for: control-log
Tue, 2023-07-25, 15:54:55 15[CFG2] vici client 2 requests: initiate
Tue, 2023-07-25, 15:54:55 15[CFG1] vici initiate CHILD_SA 'myvpn-lan'
Tue, 2023-07-25, 15:54:55 12[MGR2] checkout IKE_SA by config
Tue, 2023-07-25, 15:54:55 12[MGR2] created IKE_SA (unnamed)[1]
Tue, 2023-07-25, 15:54:55 17[LIB2] created thread 17 [fd0d3054000]
Tue, 2023-07-25, 15:54:57 12[KNL2] <myvpn|1> using 192.168.1.10 as address to reach myremoteserverip
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_VENDOR task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_INIT task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_NATD task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_CERT_PRE task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_AUTH task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_CERT_POST task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_CONFIG task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_AUTH_LIFETIME task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_MOBIKE task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing IKE_ESTABLISH task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> queueing CHILD_CREATE task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> activating new tasks
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_VENDOR task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_INIT task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_NATD task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_CERT_PRE task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_AUTH task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_CERT_POST task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_CONFIG task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_AUTH_LIFETIME task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_MOBIKE task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating IKE_ESTABLISH task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   activating CHILD_CREATE task
Tue, 2023-07-25, 15:54:57 12[IKE0] <myvpn|1> initiating IKE_SA myvpn[1] to myremoteserverip
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> IKE_SA myvpn[1] state change: CREATED => CONNECTING
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> configured proposals: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/CURVE_25519/MODP_4096, IKE:AES_GCM_16_256/PRF_HMAC_SHA2_384/ECP_521/MODP_4096
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> sending supported signature hash algorithms: sha256 sha384 sha512 identity
Tue, 2023-07-25, 15:54:57 12[ENC1] <myvpn|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) ]
Tue, 2023-07-25, 15:54:57 12[NET1] <myvpn|1> sending packet: from 192.168.1.10[500] to myremoteserverip[500] (284 bytes)
Tue, 2023-07-25, 15:54:57 12[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i 0000000000000000_r
Tue, 2023-07-25, 15:54:57 12[MGR2] <myvpn|1> checkin of IKE_SA successful
Tue, 2023-07-25, 15:54:57 04[NET2] sending packet: from 192.168.1.10[500] to myremoteserverip[500]
Tue, 2023-07-25, 15:54:57 03[NET2] received packet: from myremoteserverip[500] to 192.168.1.10[500]
Tue, 2023-07-25, 15:54:57 03[NET2] waiting for data on sockets
Tue, 2023-07-25, 15:54:57 12[MGR2] checkout IKEv2 SA by message with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 12[MGR2] IKE_SA myvpn[1] successfully checked out
Tue, 2023-07-25, 15:54:57 12[NET1] <myvpn|1> received packet: from myremoteserverip[500] to 192.168.1.10[500] (265 bytes)
Tue, 2023-07-25, 15:54:57 12[ENC1] <myvpn|1> parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(FRAG_SUP) N(HASH_ALG) N(CHDLESS_SUP) N(MULT_AUTH) ]
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> received FRAGMENTATION_SUPPORTED notify
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> received SIGNATURE_HASH_ALGORITHMS notify
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> received CHILDLESS_IKEV2_SUPPORTED notify
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> selecting proposal:
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1>   proposal matches
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> received proposals: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/CURVE_25519
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> configured proposals: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/CURVE_25519/MODP_4096, IKE:AES_GCM_16_256/PRF_HMAC_SHA2_384/ECP_521/MODP_4096
Tue, 2023-07-25, 15:54:57 12[CFG1] <myvpn|1> selected proposal: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/CURVE_25519
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> received supported signature hash algorithms: sha256 sha384 sha512 identity
Tue, 2023-07-25, 15:54:57 12[IKE1] <myvpn|1> local host is behind NAT, sending keep alives
Tue, 2023-07-25, 15:54:57 12[IKE1] <myvpn|1> received cert request for "C=US, ST=mystate, L=mytown, O=myorg, CN=myca"
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> reinitiating already active tasks
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   IKE_CERT_PRE task
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1>   IKE_AUTH task
Tue, 2023-07-25, 15:54:57 12[IKE1] <myvpn|1> sending cert request for "C=US, ST=mystate, L=mytown, O=myorg, CN=myca"
Tue, 2023-07-25, 15:54:57 12[IKE1] <myvpn|1> authentication of 'myclient' (myself) with RSA_EMSA_PKCS1_SHA2_384 successful
Tue, 2023-07-25, 15:54:57 12[IKE1] <myvpn|1> sending end entity cert "C=US, ST=mystate, L=mytown, O=myorg, CN=myclient"
Tue, 2023-07-25, 15:54:57 12[IKE2] <myvpn|1> building INTERNAL_IP4_DNS attribute
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> proposing traffic selectors for us:
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1>  0.0.0.0/0
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> proposing traffic selectors for other:
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1>  172.24.0.0/16
Tue, 2023-07-25, 15:54:57 12[CFG2] <myvpn|1> configured proposals: ESP:AES_GCM_16_256/EXT_SEQ
Tue, 2023-07-25, 15:54:57 12[IKE0] <myvpn|1> establishing CHILD_SA myvpn-lan{1}
Tue, 2023-07-25, 15:54:57 12[KNL2] <myvpn|1> got SPI cf67761d
Tue, 2023-07-25, 15:54:57 12[KNL2] <myvpn|1> getting CPI
Tue, 2023-07-25, 15:54:57 12[KNL2] <myvpn|1> got CPI 6a72
Tue, 2023-07-25, 15:54:57 12[ENC1] <myvpn|1> generating IKE_AUTH request 1 [ IDi CERT N(INIT_CONTACT) CERTREQ IDr AUTH CPRQ(ADDR DNS) N(IPCOMP_SUP) N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(NO_ADD_ADDR) N(MULT_AUTH) N(EAP_ONLY) N(MSG_ID_SYN_SUP) ]
Tue, 2023-07-25, 15:54:57 12[ENC1] <myvpn|1> splitting IKE message (2256 bytes) into 2 fragments
Tue, 2023-07-25, 15:54:57 12[ENC1] <myvpn|1> generating IKE_AUTH request 1 [ EF(1/2) ]
Tue, 2023-07-25, 15:54:57 12[ENC1] <myvpn|1> generating IKE_AUTH request 1 [ EF(2/2) ]
Tue, 2023-07-25, 15:54:57 12[NET1] <myvpn|1> sending packet: from 192.168.1.10[4500] to myremoteserverip[4500] (1248 bytes)
Tue, 2023-07-25, 15:54:57 12[NET1] <myvpn|1> sending packet: from 192.168.1.10[4500] to myremoteserverip[4500] (1073 bytes)
Tue, 2023-07-25, 15:54:57 04[NET2] sending packet: from 192.168.1.10[4500] to myremoteserverip[4500]
Tue, 2023-07-25, 15:54:57 12[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 12[MGR2] <myvpn|1> checkin of IKE_SA successful
Tue, 2023-07-25, 15:54:57 04[NET2] sending packet: from 192.168.1.10[4500] to myremoteserverip[4500]
Tue, 2023-07-25, 15:54:57 03[NET2] received packet: from myremoteserverip[4500] to 192.168.1.10[4500]
Tue, 2023-07-25, 15:54:57 03[NET2] waiting for data on sockets
Tue, 2023-07-25, 15:54:57 12[MGR2] checkout IKEv2 SA by message with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 03[NET2] received packet: from myremoteserverip[4500] to 192.168.1.10[4500]
Tue, 2023-07-25, 15:54:57 12[MGR2] IKE_SA myvpn[1] successfully checked out
Tue, 2023-07-25, 15:54:57 03[NET2] waiting for data on sockets
Tue, 2023-07-25, 15:54:57 12[NET1] <myvpn|1> received packet: from myremoteserverip[4500] to 192.168.1.10[4500] (1248 bytes)
Tue, 2023-07-25, 15:54:57 11[MGR2] checkout IKEv2 SA by message with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 12[ENC1] <myvpn|1> parsed IKE_AUTH response 1 [ EF(1/2) ]
Tue, 2023-07-25, 15:54:57 12[ENC1] <myvpn|1> received fragment #1 of 2, waiting for complete IKE message
Tue, 2023-07-25, 15:54:57 12[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 12[MGR2] <myvpn|1> checkin of IKE_SA successful
Tue, 2023-07-25, 15:54:57 11[MGR2] IKE_SA myvpn[1] successfully checked out
Tue, 2023-07-25, 15:54:57 11[NET1] <myvpn|1> received packet: from myremoteserverip[4500] to 192.168.1.10[4500] (1113 bytes)
Tue, 2023-07-25, 15:54:57 11[ENC1] <myvpn|1> parsed IKE_AUTH response 1 [ EF(2/2) ]
Tue, 2023-07-25, 15:54:57 11[ENC1] <myvpn|1> received fragment #2 of 2, reassembled fragmented IKE message (2296 bytes)
Tue, 2023-07-25, 15:54:57 11[ENC1] <myvpn|1> parsed IKE_AUTH response 1 [ IDr CERT AUTH CPRP(ADDR DNS) N(IPCOMP_SUP) N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) ]
Tue, 2023-07-25, 15:54:57 11[LIB2] <myvpn|1> builder L0 CRED_CERTIFICATE - X509 of plugin 'x509'
Tue, 2023-07-25, 15:54:57 11[LIB2] <myvpn|1> builder L0 CRED_CERTIFICATE - X509 of plugin 'x509'
Tue, 2023-07-25, 15:54:57 11[LIB2] <myvpn|1> builder L1 CRED_PUBLIC_KEY - ANY of plugin 'pkcs1'
Tue, 2023-07-25, 15:54:57 11[LIB2] <myvpn|1> builder L2 CRED_PUBLIC_KEY - RSA of plugin 'pkcs1'
Tue, 2023-07-25, 15:54:57 11[LIB2] <myvpn|1> builder L3 CRED_PUBLIC_KEY - RSA of plugin 'pkcs1'
Tue, 2023-07-25, 15:54:57 11[LIB2] <myvpn|1> builder L3 CRED_PUBLIC_KEY - RSA of plugin 'pgp'
Tue, 2023-07-25, 15:54:57 11[LIB2] <myvpn|1> builder L3 CRED_PUBLIC_KEY - RSA of plugin 'dnskey'
Tue, 2023-07-25, 15:54:57 11[LIB2] <myvpn|1> builder L3 CRED_PUBLIC_KEY - RSA of plugin 'openssl'
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> received end entity cert "C=US, ST=mystate, L=mytown, O=myorg, CN=myremoteserver"
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> received IPCOMP_SUPPORTED notify
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> received ESP_TFC_PADDING_NOT_SUPPORTED notify
Tue, 2023-07-25, 15:54:57 11[CFG1] <myvpn|1>   using certificate "C=US, ST=mystate, L=mytown, O=myorg, CN=myremoteserver"
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1>   certificate "C=US, ST=mystate, L=mytown, O=myorg, CN=myremoteserver" key: 4096 bit RSA
Tue, 2023-07-25, 15:54:57 11[CFG1] <myvpn|1>   using trusted ca certificate "C=US, ST=mystate, L=mytown, O=myorg, CN=myca"
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1>   certificate "C=US, ST=mystate, L=mytown, O=myorg, CN=myca" key: 4096 bit RSA
Tue, 2023-07-25, 15:54:57 11[CFG1] <myvpn|1>   reached self-signed root ca with a path length of 0
Tue, 2023-07-25, 15:54:57 11[CFG1] <myvpn|1> checking certificate status of "C=US, ST=mystate, L=mytown, O=myorg, CN=myremoteserver"
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1> ocsp check skipped, no ocsp found
Tue, 2023-07-25, 15:54:57 11[CFG1] <myvpn|1> certificate status is not available
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> authentication of 'myremoteserver' with RSA_EMSA_PKCS1_SHA2_384 successful
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> processing INTERNAL_IP4_ADDRESS attribute
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> processing INTERNAL_IP4_DNS attribute
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> installing DNS server 172.24.2.1 via resolvconf
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> 192.168.1.10 is on interface wlan0
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> installing new virtual IP 172.24.1.1
Tue, 2023-07-25, 15:54:57 11[LIB1] <myvpn|1> created TUN device: tun0
Tue, 2023-07-25, 15:54:57 12[KNL1] interface tun0 appeared
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> 172.24.1.1 is not a local address or the interface is down
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> 172.24.1.1 is not a local address or the interface is down
Tue, 2023-07-25, 15:54:57 12[KNL1] interface tun0 activated
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> peer supports MOBIKE
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> got additional MOBIKE peer address: 10.108.4.14
Tue, 2023-07-25, 15:54:57 11[IKE0] <myvpn|1> IKE_SA myvpn[1] established between 192.168.1.10[myclient]...myremoteserverip[myremoteserver]
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> IKE_SA myvpn[1] state change: CONNECTING => ESTABLISHED
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> scheduling rekeying in 6574s
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> maximum IKE_SA lifetime 7294s
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1> selecting proposal:
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1>   proposal matches
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1> received proposals: ESP:AES_GCM_16_256/EXT_SEQ
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1> configured proposals: ESP:AES_GCM_16_256/CURVE_25519/ECP_521/MODP_4096/EXT_SEQ
Tue, 2023-07-25, 15:54:57 11[CFG1] <myvpn|1> selected proposal: ESP:AES_GCM_16_256/EXT_SEQ
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1> selecting traffic selectors for us:
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1>  config: 172.24.1.1/32, received: 172.24.1.1/32 => match: 172.24.1.1/32
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1> selecting traffic selectors for other:
Tue, 2023-07-25, 15:54:57 11[CFG2] <myvpn|1>  config: 172.24.0.0/16, received: 172.24.0.0/16 => match: 172.24.0.0/16
Tue, 2023-07-25, 15:54:57 11[CHD2] <myvpn|1> CHILD_SA myvpn-lan{1} state change: CREATED => INSTALLING
Tue, 2023-07-25, 15:54:57 11[CHD2] <myvpn|1>   using AES_GCM_16 for encryption
Tue, 2023-07-25, 15:54:57 11[CHD2] <myvpn|1> adding inbound ESP SA
Tue, 2023-07-25, 15:54:57 11[CHD2] <myvpn|1>   SPI 0xcf67761d, src myremoteserverip dst 192.168.1.10
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> deleting SAD entry with SPI 00006a72
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> deleted SAD entry with SPI 00006a72
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> adding SAD entry with SPI 00006a72 and reqid {1}
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> deleting SAD entry with SPI cf67761d
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> deleted SAD entry with SPI cf67761d
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> adding SAD entry with SPI cf67761d and reqid {1}
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1>   using extended sequence numbers (ESN)
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1>   using encryption algorithm AES_GCM_16 with key size 288
Tue, 2023-07-25, 15:54:57 11[CHD2] <myvpn|1> adding outbound ESP SA
Tue, 2023-07-25, 15:54:57 11[CHD2] <myvpn|1>   SPI 0xce09146b, src 192.168.1.10 dst myremoteserverip
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> adding SAD entry with SPI 00003769 and reqid {1}
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> adding SAD entry with SPI ce09146b and reqid {1}
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1>   using extended sequence numbers (ESN)
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1>   using encryption algorithm AES_GCM_16 with key size 288
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> adding policy 172.24.0.0/16 === 172.24.1.1/32 in
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> adding policy 172.24.1.1/32 === 172.24.0.0/16 out
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> getting a local address in traffic selector 172.24.1.1/32
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> using host 172.24.1.1
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> using 192.168.1.5 as nexthop to reach myremoteserverip
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> installing route: 172.24.0.0/16 via 192.168.1.5 src 172.24.1.1 dev wlan0
Tue, 2023-07-25, 15:54:57 11[IKE0] <myvpn|1> CHILD_SA myvpn-lan{1} established with SPIs cf67761d_i ce09146b_o and TS 172.24.1.1/32 === 172.24.0.0/16
Tue, 2023-07-25, 15:54:57 11[CHD2] <myvpn|1> CHILD_SA myvpn-lan{1} state change: INSTALLING => INSTALLED
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> activating new tasks
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> nothing to initiate
Tue, 2023-07-25, 15:54:57 11[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 11[MGR2] <myvpn|1> checkin of IKE_SA successful
Tue, 2023-07-25, 15:54:57 08[CFG2] vici client 2 disconnected
Tue, 2023-07-25, 15:54:57 11[KNL2] creating roam job due to address/link change
Tue, 2023-07-25, 15:54:57 11[MGR2] checkout IKEv2 SA with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 11[MGR2] IKE_SA myvpn[1] successfully checked out
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> using 192.168.1.10 as address to reach myremoteserverip
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> keeping connection path 192.168.1.10 - myremoteserverip
Tue, 2023-07-25, 15:54:57 11[IKE1] <myvpn|1> sending address list update using MOBIKE
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> queueing IKE_MOBIKE task
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> activating new tasks
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1>   activating IKE_MOBIKE task
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> using 192.168.1.10 as address to reach myremoteserverip
Tue, 2023-07-25, 15:54:57 11[ENC1] <myvpn|1> generating INFORMATIONAL request 2 [ N(ADD_4_ADDR) ]
Tue, 2023-07-25, 15:54:57 11[KNL2] <myvpn|1> using 192.168.1.10 as address to reach myremoteserverip
Tue, 2023-07-25, 15:54:57 11[NET1] <myvpn|1> sending packet: from 192.168.1.10[4500] to myremoteserverip[4500] (69 bytes)
Tue, 2023-07-25, 15:54:57 11[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 11[MGR2] <myvpn|1> checkin of IKE_SA successful
Tue, 2023-07-25, 15:54:57 04[NET2] sending packet: from 192.168.1.10[4500] to myremoteserverip[4500]
Tue, 2023-07-25, 15:54:57 03[NET2] received packet: from myremoteserverip[4500] to 192.168.1.10[4500]
Tue, 2023-07-25, 15:54:57 03[NET2] waiting for data on sockets
Tue, 2023-07-25, 15:54:57 11[MGR2] checkout IKEv2 SA by message with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 11[MGR2] IKE_SA myvpn[1] successfully checked out
Tue, 2023-07-25, 15:54:57 11[NET1] <myvpn|1> received packet: from myremoteserverip[4500] to 192.168.1.10[4500] (57 bytes)
Tue, 2023-07-25, 15:54:57 11[ENC1] <myvpn|1> parsed INFORMATIONAL response 2 [ ]
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> activating new tasks
Tue, 2023-07-25, 15:54:57 11[IKE2] <myvpn|1> nothing to initiate
Tue, 2023-07-25, 15:54:57 11[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:54:57 11[MGR2] <myvpn|1> checkin of IKE_SA successful
Tue, 2023-07-25, 15:55:01 11[MGR2] checkout IKEv2 SA with SPIs fcfc635528403727_i 0000000000000000_r
Tue, 2023-07-25, 15:55:01 11[MGR2] IKE_SA myvpn[1] successfully checked out
Tue, 2023-07-25, 15:55:01 11[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:55:01 11[MGR2] <myvpn|1> checkin of IKE_SA successful
Tue, 2023-07-25, 15:55:01 11[MGR2] checkout IKEv2 SA with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:55:01 11[MGR2] IKE_SA myvpn[1] successfully checked out
Tue, 2023-07-25, 15:55:01 11[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:55:01 11[MGR2] <myvpn|1> checkin of IKE_SA successful
Tue, 2023-07-25, 15:55:01 11[MGR2] checkout IKEv2 SA with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:55:01 11[MGR2] IKE_SA myvpn[1] successfully checked out
Tue, 2023-07-25, 15:55:01 11[MGR2] <myvpn|1> checkin IKEv2 SA myvpn[1] with SPIs fcfc635528403727_i a9569b3c4bf0a9ee_r
Tue, 2023-07-25, 15:55:01 11[MGR2] <myvpn|1> checkin of IKE_SA successful

@rionda
Copy link
Author

rionda commented Jul 25, 2023

I should also note that I get the following message when trying to terminate the connection:

myclient ~/strongswan/src [1807-pfroute-vip△] % sudo swanctl/swanctl -t -c myvpn-lan
[IKE] closing CHILD_SA trismegistusvpn-lan{1} with SPIs cb55248b_i (0 bytes) c6571e2b_o (0 bytes) and TS 172.24.1.1/32 === 172.24.0.0/16
terminate failed: terminating SA failed

and the tun0 interface is not destroyed. This even when I don't change the route for the workaround.

@tobiasbrunner
Copy link
Member

I compiled it, and run charon and swanctl from the build directory.

That won't work as the kernel-pfroute plugin will just be dynamically loaded from the default location (i.e. you won't get the new code). Only for the unit tests (make check) are the plugins from the build directory getting used. So either install the new build, or try building the libraries monolithically (--enable-monolithic, so plugins are compiled into the libraries, I think those should then be loaded from the build directory thanks to rpath).

I should also note that I get the following message when trying to terminate the connection:

Note that with -c you are only terminating the CHILD_SA. Use -i to terminate the IKE_SA.

That CHILD_SA is apparently in a state that doesn't allow a proper delete.

and the tun0 interface is not destroyed.

The virtual IP and with it the TUN device are properties of the IKE_SA.

@rionda
Copy link
Author

rionda commented Jul 26, 2023

I compiled it, and run charon and swanctl from the build directory.

That won't work as the kernel-pfroute plugin will just be dynamically loaded from the default location (i.e. you won't get the new code). Only for the unit tests (make check) are the plugins from the build directory getting used. So either install the new build, or try building the libraries monolithically (--enable-monolithic, so plugins are compiled into the libraries, I think those should then be loaded from the build directory thanks to rpath).

Hah, that's exactly why I mentioned running from the build directory, so you could tell me if what I did was wrong. I'll try again this afternoon.

I should also note that I get the following message when trying to terminate the connection:

Note that with -c you are only terminating the CHILD_SA. Use -i to terminate the IKE_SA.

Okay, thanks!

That CHILD_SA is apparently in a state that doesn't allow a proper delete.

and the tun0 interface is not destroyed.

The virtual IP and with it the TUN device are properties of the IKE_SA.

Got it!

@rionda
Copy link
Author

rionda commented Jul 26, 2023

I installed the version from the 1807-pfroute-vip branch, and the route is correctly added to be "through" tun0.

Everything seems to be working correctly.

@tobiasbrunner
Copy link
Member

Great, thanks for testing. I've pushed the fix to master.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants