Aug 24 15:03:27 vc1_TPC1 ipsec_starter[7626]: Starting strongSwan 4.5.2 IPsec [starter]... Aug 24 15:03:27 vc1_TPC1 pluto[7639]: Starting IKEv1 pluto daemon (strongSwan 4.5.2) THREADS SMARTCARD VENDORID Aug 24 15:03:27 vc1_TPC1 pluto[7639]: listening on interfaces: Aug 24 15:03:27 vc1_TPC1 pluto[7639]: eth1 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: 169.254.0.70 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: fe80::21f:29ff:fe61:21ad Aug 24 15:03:27 vc1_TPC1 pluto[7639]: ethvc1 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: 10.58.228.92 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: fe80::f014:52ff:fe5e:ba58 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loaded plugins: test-vectors curl ldap aes des sha1 sha2 md5 random x509 pkcs1 pgp dnskey pem openssl gmp hmac xauth attr kernel-netlink resolve Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | inserting event EVENT_REINIT_SECRET, timeout in 3600 seconds Aug 24 15:03:27 vc1_TPC1 pluto[7639]: including NAT-Traversal patch (Version 0.6c) [disabled] Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | pkcs11 module '/usr/lib/opensc-pkcs11.so' loading... Aug 24 15:03:27 vc1_TPC1 pluto[7639]: failed to load pkcs11 module '/usr/lib/opensc-pkcs11.so' Aug 24 15:03:27 vc1_TPC1 ipsec_starter[7638]: pluto (7639) started after 20 ms Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loading ca certificates from '/etc/ipsec.d/cacerts' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loaded ca certificate from '/etc/ipsec.d/cacerts/caCert.der' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | authcert inserted Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loading aa certificates from '/etc/ipsec.d/aacerts' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loading aa certificates from '/etc/ipsec.d/aacerts' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loading ocsp certificates from '/etc/ipsec.d/ocspcerts' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: Changing to directory '/etc/ipsec.d/crls' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loading attribute certificates from '/etc/ipsec.d/acerts' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: spawning 4 worker threads Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | inserting event EVENT_LOG_DAILY, timeout in 32193 seconds Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | next event EVENT_REINIT_SECRET in 3600 seconds Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | *received whack message Aug 24 15:03:27 vc1_TPC1 pluto[7639]: listening for IKE messages Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | found lo with address 127.0.0.1 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | found ethvc1 with address 10.58.228.92 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | found eth1 with address 169.254.0.70 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: adding interface eth1/eth1 169.254.0.70:500 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: adding interface ethvc1/ethvc1 10.58.228.92:500 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: adding interface lo/lo 127.0.0.1:500 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | found lo with address 0000:0000:0000:0000:0000:0000:0000:0001 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: adding interface lo/lo ::1:500 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loading secrets from "/etc/ipsec.secrets" Aug 24 15:03:27 vc1_TPC1 pluto[7639]: "/etc/ipsec.secrets" line 9: file starts with indentation (continuation notation) Aug 24 15:03:27 vc1_TPC1 pluto[7639]: no secrets filename matched "/var/lib/strongswan/ipsec.secrets.inc" Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | next event EVENT_REINIT_SECRET in 3600 seconds Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | *received whack message Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loaded CA certificate from '/etc/ipsec.d/cacerts/caCert.der' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: added ca description "strongswan" Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | authname: 'C=CH, O=strongSwan, CN=strongSwan CA' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | authkey: 1e:fc:6e:71:5e:90:8f:7a:7d:3e:44:6b:32:10:03:a6:13:8d:9f:fa Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | authcert is already present and identical Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | next event EVENT_REINIT_SECRET in 3600 seconds Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | *received whack message Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | from whack: got --esp=aes128-sha1,3des-sha1 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | esp proposal: AES_CBC_128/HMAC_SHA1, 3DES_CBC/HMAC_SHA1, Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | from whack: got --ike=aes128-sha1-modp2048,3des-sha1-modp1536 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | ike proposal: AES_CBC_128/HMAC_SHA1/MODP_2048, 3DES_CBC/HMAC_SHA1/MODP_1536, Aug 24 15:03:27 vc1_TPC1 pluto[7639]: loaded host certificate from '/etc/ipsec.d/certs/VC1Cert.der' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: id '%any' not confirmed by certificate, defaulting to 'C=CH, O=strongSwan, CN=169.254.0.70' Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | certificate is valid Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | cert inserted Aug 24 15:03:27 vc1_TPC1 pluto[7639]: added connection description "kay" Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | 169.254.0.0/24===169.254.0.70[C=CH, O=strongSwan, CN=169.254.0.70]...169.254.1.70[C=CH, O=strongSwan, CN=169.254.1.70]===169.254.1.0/24 Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | ike_life: 10800s; ipsec_life: 3600s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 3; policy: PUBKEY+ENCRYPT+TUNNEL+PFS Aug 24 15:03:27 vc1_TPC1 pluto[7639]: | next event EVENT_REINIT_SECRET in 3600 seconds Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | *received 168 bytes from 169.254.1.70:500 on eth1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | *received 168 bytes from 169.254.1.70:500 on eth1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [strongSwan] Aug 24 15:03:40 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [XAUTH] Aug 24 15:03:40 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [XAUTH] Aug 24 15:03:40 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [Dead Peer Detection] Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | preparse_isakmp_policy: peer requests PUBKEY authentication Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | creating state object #1 at 0x21aa9e80 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | ICOOKIE: b0 22 8b 74 8a 9e 7f f2 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | RCOOKIE: 8a cc 2a 18 e0 6a 2d 44 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: "kay" #1: responding to Main Mode Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | ICOOKIE: b0 22 8b 74 8a 9e 7f f2 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | RCOOKIE: 8a cc 2a 18 e0 6a 2d 44 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | state object #1 found, in STATE_MAIN_R1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | ICOOKIE: b0 22 8b 74 8a 9e 7f f2 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | RCOOKIE: 8a cc 2a 18 e0 6a 2d 44 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | state object #1 found, in STATE_MAIN_R2 Aug 24 15:03:40 vc1_TPC1 pluto[7639]: "kay" #1: ignoring informational payload, type AUTHENTICATION_FAILED Aug 24 15:03:40 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #1 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | event after this is EVENT_REINIT_SECRET in 3576 seconds Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #1 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #1 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #1 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | ICOOKIE: b0 22 8b 74 8a 9e 7f f2 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | RCOOKIE: 8a cc 2a 18 e0 6a 2d 44 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | state object #1 found, in STATE_MAIN_R2 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: "kay" #1: next payload type of ISAKMP Hash Payload has an unknown value: 70 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: "kay" #1: malformed payload in packet Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #1 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | ICOOKIE: b0 22 8b 74 8a 9e 7f f2 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | RCOOKIE: 8a cc 2a 18 e0 6a 2d 44 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | state object #1 found, in STATE_MAIN_R2 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: "kay" #1: discarding duplicate packet; already STATE_MAIN_R2 Aug 24 15:03:51 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #1 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | ICOOKIE: b0 22 8b 74 8a 9e 7f f2 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | RCOOKIE: 8a cc 2a 18 e0 6a 2d 44 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | state object #1 found, in STATE_MAIN_R2 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | state object #1 found, in STATE_MAIN_R2 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: "kay" #1: discarding duplicate packet; already STATE_MAIN_R2 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 0 seconds for #1 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | event after this is EVENT_REINIT_SECRET in 3556 seconds Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #1 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #1 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 40 seconds for #1 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | ICOOKIE: b0 22 8b 74 8a 9e 7f f2 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | RCOOKIE: 8a cc 2a 18 e0 6a 2d 44 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | state object #1 found, in STATE_MAIN_R2 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: "kay" #1: next payload type of ISAKMP Hash Payload has an unknown value: 158 Aug 24 15:04:11 vc1_TPC1 pluto[7639]: "kay" #1: malformed payload in packet Aug 24 15:04:11 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 40 seconds for #1 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | *received whack message Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | creating state object #2 at 0x21aab498 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | creating state object #2 at 0x21aab498 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | state hash entry 30 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #2 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | Queuing pending Quick Mode with 169.254.1.70 "kay" Aug 24 15:04:12 vc1_TPC1 pluto[7639]: "kay" #2: initiating Main Mode Aug 24 15:04:12 vc1_TPC1 pluto[7639]: "kay" #2: initiating Main Mode Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | ike proposal: AES_CBC_128/HMAC_SHA1/MODP_2048, 3DES_CBC/HMAC_SHA1/MODP_1536, Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #2 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #2 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #2 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | *received 136 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | RCOOKIE: f3 1e f9 21 b4 e7 b9 38 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | state hash entry 11 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | state object not found Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | state hash entry 30 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: | state object #2 found, in STATE_MAIN_I1 Aug 24 15:04:12 vc1_TPC1 pluto[7639]: "kay" #2: received Vendor ID payload [strongSwan] Aug 24 15:04:12 vc1_TPC1 pluto[7639]: "kay" #2: received Vendor ID payload [XAUTH] Aug 24 15:04:12 vc1_TPC1 pluto[7639]: "kay" #2: received Vendor ID payload [Dead Peer Detection] Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | state hash entry 30 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | RCOOKIE: f3 1e f9 21 b4 e7 b9 38 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | RCOOKIE: f3 1e f9 21 b4 e7 b9 38 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | state hash entry 11 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #2 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #2 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | RCOOKIE: f3 1e f9 21 b4 e7 b9 38 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | state hash entry 11 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | state object #2 found, in STATE_MAIN_I2 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:04:13 vc1_TPC1 pluto[7639]: "kay" #2: we have a cert and are sending it upon request Aug 24 15:04:13 vc1_TPC1 pluto[7639]: "kay" #2: unable to locate my private key for signature Aug 24 15:04:13 vc1_TPC1 pluto[7639]: "kay" #2: unable to locate my private key for signature Aug 24 15:04:13 vc1_TPC1 pluto[7639]: "kay" #2: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: "kay" #2: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:04:13 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #2 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 28 seconds Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #2 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #2 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #2 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #2 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | RCOOKIE: f3 1e f9 21 b4 e7 b9 38 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | state hash entry 11 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | state object #2 found, in STATE_MAIN_I2 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:04:23 vc1_TPC1 pluto[7639]: "kay" #2: we have a cert and are sending it upon request Aug 24 15:04:23 vc1_TPC1 pluto[7639]: "kay" #2: we have a cert and are sending it upon request Aug 24 15:04:23 vc1_TPC1 pluto[7639]: "kay" #2: unable to locate my private key for signature Aug 24 15:04:23 vc1_TPC1 pluto[7639]: "kay" #2: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:04:23 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #2 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | ICOOKIE: fb ba ab fe b9 af 67 9f Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | RCOOKIE: f3 1e f9 21 b4 e7 b9 38 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | state hash entry 11 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | state object #2 found, in STATE_MAIN_I2 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:04:43 vc1_TPC1 pluto[7639]: "kay" #2: we have a cert and are sending it upon request Aug 24 15:04:43 vc1_TPC1 pluto[7639]: "kay" #2: unable to locate my private key for signature Aug 24 15:04:43 vc1_TPC1 pluto[7639]: "kay" #2: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 0 seconds for #2 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 8 seconds Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #2 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #2 Aug 24 15:04:43 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 8 seconds for #1 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 32 seconds Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #1 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #1 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: "kay" #1: max number of retransmissions (2) reached STATE_MAIN_R2 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | ICOOKIE: b0 22 8b 74 8a 9e 7f f2 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | RCOOKIE: 8a cc 2a 18 e0 6a 2d 44 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | state hash entry 25 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 32 seconds for #2 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | *received 168 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [strongSwan] Aug 24 15:04:51 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [XAUTH] Aug 24 15:04:51 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [Dead Peer Detection] Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | preparse_isakmp_policy: peer requests PUBKEY authentication Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | creating state object #3 at 0x21aaa978 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | RCOOKIE: ce 4c 5c 42 4f a2 51 99 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #3 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: "kay" #3: responding to Main Mode Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #3 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #3 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | RCOOKIE: ce 4c 5c 42 4f a2 51 99 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | state object #3 found, in STATE_MAIN_R1 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #3 Aug 24 15:04:51 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #3 Aug 24 15:04:52 vc1_TPC1 pluto[7639]: | Aug 24 15:04:52 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:04:52 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:04:52 vc1_TPC1 pluto[7639]: | RCOOKIE: ce 4c 5c 42 4f a2 51 99 Aug 24 15:04:52 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:04:52 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:04:52 vc1_TPC1 pluto[7639]: | state object #3 found, in STATE_MAIN_R2 Aug 24 15:04:52 vc1_TPC1 pluto[7639]: "kay" #3: ignoring informational payload, type AUTHENTICATION_FAILED Aug 24 15:04:52 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 9 seconds for #3 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | RCOOKIE: ce 4c 5c 42 4f a2 51 99 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | state object #3 found, in STATE_MAIN_R2 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: "kay" #3: discarding duplicate packet; already STATE_MAIN_R2 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 0 seconds for #3 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 22 seconds Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #3 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #3 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #3 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | RCOOKIE: ce 4c 5c 42 4f a2 51 99 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | state object #3 found, in STATE_MAIN_R2 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: "kay" #3: next payload type of ISAKMP Hash Payload has an unknown value: 208 Aug 24 15:05:01 vc1_TPC1 pluto[7639]: "kay" #3: malformed payload in packet Aug 24 15:05:01 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #3 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | RCOOKIE: ce 4c 5c 42 4f a2 51 99 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | state object #3 found, in STATE_MAIN_R2 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: "kay" #3: discarding duplicate packet; already STATE_MAIN_R2 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 0 seconds for #3 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 2 seconds Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #3 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #3 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 2 seconds for #2 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | RCOOKIE: ce 4c 5c 42 4f a2 51 99 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | state object #3 found, in STATE_MAIN_R2 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: "kay" #3: next payload type of ISAKMP Hash Payload has an unknown value: 204 Aug 24 15:05:21 vc1_TPC1 pluto[7639]: "kay" #3: malformed payload in packet Aug 24 15:05:21 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 2 seconds for #2 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 38 seconds Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #2 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #2: max number of retransmissions (2) reached STATE_MAIN_I2 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #2: starting keying attempt 2 of at most 3, but releasing whack Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | creating state object #4 at 0x21aacb40 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state hash entry 11 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #4 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #4: initiating Main Mode to replace #2 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | ike proposal: AES_CBC_128/HMAC_SHA1/MODP_2048, 3DES_CBC/HMAC_SHA1/MODP_1536, Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #4 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #4 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | *received 136 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | RCOOKIE: 86 81 e8 a4 2b f2 f2 41 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state hash entry 16 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state object not found Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state hash entry 11 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state object #4 found, in STATE_MAIN_I1 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #4: received Vendor ID payload [strongSwan] Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #4: received Vendor ID payload [XAUTH] Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #4: received Vendor ID payload [Dead Peer Detection] Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state hash entry 11 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | RCOOKIE: 86 81 e8 a4 2b f2 f2 41 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state hash entry 16 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #4 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #4 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | RCOOKIE: 86 81 e8 a4 2b f2 f2 41 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state hash entry 16 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state hash entry 16 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state object #4 found, in STATE_MAIN_I2 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state object #4 found, in STATE_MAIN_I2 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #4: we have a cert and are sending it upon request Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #4: we have a cert and are sending it upon request Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #4: unable to locate my private key for signature Aug 24 15:05:23 vc1_TPC1 pluto[7639]: "kay" #4: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #4 Aug 24 15:05:23 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #4 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 28 seconds Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #4 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #4 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #4 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #4 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | RCOOKIE: 86 81 e8 a4 2b f2 f2 41 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | state hash entry 16 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | state object #4 found, in STATE_MAIN_I2 Aug 24 15:05:33 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:05:34 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:05:34 vc1_TPC1 pluto[7639]: "kay" #4: we have a cert and are sending it upon request Aug 24 15:05:34 vc1_TPC1 pluto[7639]: "kay" #4: unable to locate my private key for signature Aug 24 15:05:34 vc1_TPC1 pluto[7639]: "kay" #4: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:05:34 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:05:34 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 19 seconds for #4 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 8 seconds Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #4 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #4 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 8 seconds for #3 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | RCOOKIE: 86 81 e8 a4 2b f2 f2 41 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | state hash entry 16 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | state object #4 found, in STATE_MAIN_I2 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:05:53 vc1_TPC1 pluto[7639]: "kay" #4: we have a cert and are sending it upon request Aug 24 15:05:53 vc1_TPC1 pluto[7639]: "kay" #4: we have a cert and are sending it upon request Aug 24 15:05:53 vc1_TPC1 pluto[7639]: "kay" #4: unable to locate my private key for signature Aug 24 15:05:53 vc1_TPC1 pluto[7639]: "kay" #4: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 8 seconds for #3 Aug 24 15:05:53 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 8 seconds for #3 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | *received 168 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | *received 168 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [strongSwan] Aug 24 15:06:01 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [XAUTH] Aug 24 15:06:01 vc1_TPC1 pluto[7639]: packet from 169.254.1.70:500: received Vendor ID payload [Dead Peer Detection] Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | preparse_isakmp_policy: peer requests PUBKEY authentication Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | creating state object #5 at 0x21aabfb0 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | RCOOKIE: a5 1a 25 9c 4d f6 f0 1a Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | state hash entry 27 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #5 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: "kay" #5: responding to Main Mode Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #5 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 0 seconds for #3 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 10 seconds Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #3 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: "kay" #3: max number of retransmissions (2) reached STATE_MAIN_R2 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | ICOOKIE: b5 97 d1 fc 98 49 66 d3 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | RCOOKIE: ce 4c 5c 42 4f a2 51 99 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | state hash entry 24 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #5 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | RCOOKIE: a5 1a 25 9c 4d f6 f0 1a Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | state hash entry 27 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | state object #5 found, in STATE_MAIN_R1 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #5 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #5 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | RCOOKIE: a5 1a 25 9c 4d f6 f0 1a Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | state hash entry 27 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | state object #5 found, in STATE_MAIN_R2 Aug 24 15:06:01 vc1_TPC1 pluto[7639]: "kay" #5: ignoring informational payload, type AUTHENTICATION_FAILED Aug 24 15:06:01 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #5 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | RCOOKIE: a5 1a 25 9c 4d f6 f0 1a Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | state hash entry 27 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | state object #5 found, in STATE_MAIN_R2 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: "kay" #5: discarding duplicate packet; already STATE_MAIN_R2 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 0 seconds for #5 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 22 seconds Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #5 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #5 Aug 24 15:06:11 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #5 Aug 24 15:06:12 vc1_TPC1 pluto[7639]: | Aug 24 15:06:12 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:12 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:06:12 vc1_TPC1 pluto[7639]: | RCOOKIE: a5 1a 25 9c 4d f6 f0 1a Aug 24 15:06:12 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:12 vc1_TPC1 pluto[7639]: | state hash entry 27 Aug 24 15:06:12 vc1_TPC1 pluto[7639]: | state object #5 found, in STATE_MAIN_R2 Aug 24 15:06:12 vc1_TPC1 pluto[7639]: "kay" #5: next payload type of ISAKMP Hash Payload has an unknown value: 140 Aug 24 15:06:12 vc1_TPC1 pluto[7639]: "kay" #5: malformed payload in packet Aug 24 15:06:12 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 19 seconds for #5 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | *received 308 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | RCOOKIE: a5 1a 25 9c 4d f6 f0 1a Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | state hash entry 27 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | state object #5 found, in STATE_MAIN_R2 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: "kay" #5: discarding duplicate packet; already STATE_MAIN_R2 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 0 seconds for #5 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 2 seconds Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #5 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #5 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 2 seconds for #4 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | *received 76 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | RCOOKIE: a5 1a 25 9c 4d f6 f0 1a Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | state hash entry 27 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | state object #5 found, in STATE_MAIN_R2 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: "kay" #5: next payload type of ISAKMP Hash Payload has an unknown value: 207 Aug 24 15:06:31 vc1_TPC1 pluto[7639]: "kay" #5: malformed payload in packet Aug 24 15:06:31 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 2 seconds for #4 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 38 seconds Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #4 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #4: max number of retransmissions (2) reached STATE_MAIN_I2 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #4: starting keying attempt 3 of at most 3 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | creating state object #6 at 0x21aacee8 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | creating state object #6 at 0x21aacee8 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state hash entry 12 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #6 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #6: initiating Main Mode to replace #4 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | ike proposal: AES_CBC_128/HMAC_SHA1/MODP_2048, 3DES_CBC/HMAC_SHA1/MODP_1536, Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #6 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | ICOOKIE: 60 46 63 a9 6d 05 2b 7c Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | RCOOKIE: 86 81 e8 a4 2b f2 f2 41 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state hash entry 16 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #6 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | *received 136 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | RCOOKIE: c1 85 56 a6 62 e9 0c c0 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state hash entry 19 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state object not found Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state hash entry 12 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state object #6 found, in STATE_MAIN_I1 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #6: received Vendor ID payload [strongSwan] Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #6: received Vendor ID payload [XAUTH] Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #6: received Vendor ID payload [Dead Peer Detection] Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | RCOOKIE: 00 00 00 00 00 00 00 00 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state hash entry 12 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | RCOOKIE: c1 85 56 a6 62 e9 0c c0 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state hash entry 19 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #6 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #6 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | RCOOKIE: c1 85 56 a6 62 e9 0c c0 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state hash entry 19 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state object #6 found, in STATE_MAIN_I2 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #6: we have a cert and are sending it upon request Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #6: unable to locate my private key for signature Aug 24 15:06:33 vc1_TPC1 pluto[7639]: "kay" #6: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:06:33 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 10 seconds for #6 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 28 seconds Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #6 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #6 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #6 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #6 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #6 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | RCOOKIE: c1 85 56 a6 62 e9 0c c0 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | state hash entry 19 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | state object #6 found, in STATE_MAIN_I2 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:06:43 vc1_TPC1 pluto[7639]: "kay" #6: we have a cert and are sending it upon request Aug 24 15:06:43 vc1_TPC1 pluto[7639]: "kay" #6: unable to locate my private key for signature Aug 24 15:06:43 vc1_TPC1 pluto[7639]: "kay" #6: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:06:43 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 20 seconds for #6 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 8 seconds Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #6 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #6 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 8 seconds for #5 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | *received 316 bytes from 169.254.1.70:500 on eth1 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | RCOOKIE: c1 85 56 a6 62 e9 0c c0 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | state hash entry 19 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | state object #6 found, in STATE_MAIN_I2 Aug 24 15:07:03 vc1_TPC1 pluto[7639]: | requested CA: %any Aug 24 15:07:04 vc1_TPC1 pluto[7639]: | our certificate policy is SEND_IF_ASKED Aug 24 15:07:04 vc1_TPC1 pluto[7639]: "kay" #6: we have a cert and are sending it upon request Aug 24 15:07:04 vc1_TPC1 pluto[7639]: "kay" #6: unable to locate my private key for signature Aug 24 15:07:04 vc1_TPC1 pluto[7639]: "kay" #6: sending encrypted notification AUTHENTICATION_FAILED to 169.254.1.70:500 Aug 24 15:07:04 vc1_TPC1 pluto[7639]: | state transition function for STATE_MAIN_I2 failed: AUTHENTICATION_FAILED Aug 24 15:07:04 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 7 seconds for #5 Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | event after this is EVENT_RETRANSMIT in 32 seconds Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #5 Aug 24 15:07:11 vc1_TPC1 pluto[7639]: "kay" #5: max number of retransmissions (2) reached STATE_MAIN_R2 Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | ICOOKIE: 94 9b bb 79 ed 4c d6 68 Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | RCOOKIE: a5 1a 25 9c 4d f6 f0 1a Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | state hash entry 27 Aug 24 15:07:11 vc1_TPC1 pluto[7639]: | next event EVENT_RETRANSMIT in 32 seconds for #6 Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | *time to handle event Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | event after this is EVENT_REINIT_SECRET in 3344 seconds Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | handling event EVENT_RETRANSMIT for 169.254.1.70 "kay" #6 Aug 24 15:07:43 vc1_TPC1 pluto[7639]: "kay" #6: max number of retransmissions (2) reached STATE_MAIN_I2 Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | ICOOKIE: bf 56 f6 40 b6 9a 78 49 Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | RCOOKIE: c1 85 56 a6 62 e9 0c c0 Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | peer: a9 fe 01 46 Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | state hash entry 19 Aug 24 15:07:43 vc1_TPC1 pluto[7639]: | next event EVENT_REINIT_SECRET in 3344 seconds