Oct 29 20:05:23 fw ipsec__plutorun: Starting Pluto subsystem... Oct 29 20:05:23 fw pluto[25973]: Starting Pluto (Openswan Version 2.4.5 X.509-1.5.4 PLUTO_SENDS_VENDORID PLUTO_USES_KEYRR; Vendor ID OEnMCu\177xOp@c) Oct 29 20:05:23 fw pluto[25973]: Setting NAT-Traversal port-4500 floating to on Oct 29 20:05:23 fw pluto[25973]: port floating activation criteria nat_t=1/port_fload=1 Oct 29 20:05:23 fw pluto[25973]: including NAT-Traversal patch (Version 0.6c) Oct 29 20:05:23 fw pluto[25973]: | opening /dev/urandom Oct 29 20:05:23 fw pluto[25973]: | inserting event EVENT_REINIT_SECRET, timeout in 3600 seconds Oct 29 20:05:23 fw pluto[25973]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds Oct 29 20:05:23 fw pluto[25973]: ike_alg_register_enc(): Activating OAKLEY_AES_CBC: Ok (ret=0) Oct 29 20:05:23 fw pluto[25973]: starting up 1 cryptographic helpers Oct 29 20:05:23 fw pluto[25973]: started helper pid=25974 (fd:6) Oct 29 20:05:23 fw pluto[25973]: Using KLIPS IPsec interface code on 2.6.16-1.2122_qb2smp Oct 29 20:05:23 fw pluto[25973]: | inserting event EVENT_SHUNT_SCAN, timeout in 120 seconds Oct 29 20:05:23 fw pluto[25974]: | opening /dev/urandom Oct 29 20:05:23 fw pluto[25973]: Changing to directory '/etc/ipsec.d/cacerts' Oct 29 20:05:23 fw pluto[25973]: Changing to directory '/etc/ipsec.d/aacerts' Oct 29 20:05:23 fw pluto[25973]: Changing to directory '/etc/ipsec.d/ocspcerts' Oct 29 20:05:23 fw pluto[25973]: Changing to directory '/etc/ipsec.d/crls' Oct 29 20:05:23 fw pluto[25973]: Warning: empty directory Oct 29 20:05:23 fw pluto[25973]: | inserting event EVENT_LOG_DAILY, timeout in 14077 seconds Oct 29 20:05:23 fw pluto[25973]: | next event EVENT_SHUNT_SCAN in 120 seconds Oct 29 20:05:24 fw pluto[25974]: ! helper 0 waiting on fd: 7 Oct 29 20:05:24 fw pluto[25973]: | Oct 29 20:05:24 fw pluto[25973]: | *received whack message Oct 29 20:05:24 fw pluto[25973]: | Added new connection l2tp_1 with policy PSK+ENCRYPT+TUNNEL Oct 29 20:05:24 fw pluto[25973]: | from whack: got --esp=3des-md5-96 Oct 29 20:05:24 fw pluto[25973]: | esp string values: 3_000-1, flags=strict Oct 29 20:05:24 fw pluto[25973]: | counting wild cards for (none) is 15 Oct 29 20:05:24 fw pluto[25973]: | counting wild cards for (none) is 15 Oct 29 20:05:24 fw pluto[25973]: | based upon policy, the connection is a template. Oct 29 20:05:24 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=1 Oct 29 20:05:24 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=2 Oct 29 20:05:24 fw pluto[25973]: added connection description "l2tp_1" Oct 29 20:05:24 fw pluto[25973]: | 192.168.16.254:17/1701...%any:17/1701 Oct 29 20:05:24 fw pluto[25973]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 3; policy: PSK+ENCRYPT+TUNNEL Oct 29 20:05:24 fw pluto[25973]: | next event EVENT_SHUNT_SCAN in 119 seconds Oct 29 20:05:24 fw pluto[25973]: | Oct 29 20:05:24 fw pluto[25973]: | *received whack message Oct 29 20:05:24 fw pluto[25973]: | Added new connection l2tp_2 with policy PSK+ENCRYPT+DONTREKEY Oct 29 20:05:24 fw pluto[25973]: | from whack: got --esp=3des-md5-2048 Oct 29 20:05:24 fw pluto[25973]: | esp string values: 3_000-1, flags=strict Oct 29 20:05:24 fw pluto[25973]: | counting wild cards for (none) is 15 Oct 29 20:05:24 fw pluto[25973]: | counting wild cards for (none) is 15 Oct 29 20:05:24 fw pluto[25973]: | based upon policy, the connection is a template. Oct 29 20:05:24 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=1 Oct 29 20:05:24 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=2 Oct 29 20:05:24 fw pluto[25973]: added connection description "l2tp_2" Oct 29 20:05:24 fw pluto[25973]: | 10.254.254.2:17/1701...%any:17/1701 Oct 29 20:05:24 fw pluto[25973]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 3; policy: PSK+ENCRYPT+DONTREKEY Oct 29 20:05:24 fw pluto[25973]: | next event EVENT_SHUNT_SCAN in 119 seconds Oct 29 20:05:24 fw pluto[25973]: | Oct 29 20:05:24 fw pluto[25973]: | *received whack message Oct 29 20:05:24 fw pluto[25973]: | Added new connection l2tp_3 with policy PSK+ENCRYPT+TUNNEL Oct 29 20:05:24 fw pluto[25973]: | from whack: got --esp=3des-md5-96 Oct 29 20:05:24 fw pluto[25973]: | esp string values: 3_000-1, flags=strict Oct 29 20:05:24 fw pluto[25973]: | counting wild cards for (none) is 15 Oct 29 20:05:24 fw pluto[25973]: | counting wild cards for (none) is 15 Oct 29 20:05:24 fw pluto[25973]: | based upon policy, the connection is a template. Oct 29 20:05:24 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=1 Oct 29 20:05:24 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=2 Oct 29 20:05:24 fw pluto[25973]: added connection description "l2tp_3" Oct 29 20:05:24 fw pluto[25973]: | 10.254.253.2:17/1701...%any:17/1701 Oct 29 20:05:24 fw pluto[25973]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 3; policy: PSK+ENCRYPT+TUNNEL Oct 29 20:05:24 fw pluto[25973]: | next event EVENT_SHUNT_SCAN in 119 seconds Oct 29 20:05:24 fw pluto[25973]: | Oct 29 20:05:24 fw pluto[25973]: | *received whack message Oct 29 20:05:24 fw pluto[25973]: | Added new connection l2tp_4 with policy PSK+ENCRYPT+TUNNEL Oct 29 20:05:24 fw pluto[25973]: | from whack: got --esp=3des-md5-96 Oct 29 20:05:24 fw pluto[25973]: | esp string values: 3_000-1, flags=strict Oct 29 20:05:24 fw pluto[25973]: | counting wild cards for (none) is 15 Oct 29 20:05:24 fw pluto[25973]: | counting wild cards for (none) is 15 Oct 29 20:05:24 fw pluto[25973]: | based upon policy, the connection is a template. Oct 29 20:05:24 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=1 Oct 29 20:05:24 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=2 Oct 29 20:05:24 fw pluto[25973]: added connection description "l2tp_4" Oct 29 20:05:24 fw pluto[25973]: | 192.168.252.44:17/1701...%any:17/1701 Oct 29 20:05:24 fw pluto[25973]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 3; policy: PSK+ENCRYPT+TUNNEL Oct 29 20:05:24 fw pluto[25973]: | next event EVENT_SHUNT_SCAN in 119 seconds Oct 29 20:05:24 fw pluto[25973]: | Oct 29 20:05:24 fw pluto[25973]: | *received whack message Oct 29 20:05:24 fw pluto[25973]: listening for IKE messages Oct 29 20:05:24 fw pluto[25973]: | found lo with address 127.0.0.1 Oct 29 20:05:24 fw pluto[25973]: | found ipsec0 with address 10.254.254.2 Oct 29 20:05:24 fw pluto[25973]: | found eth0 with address 192.168.16.254 Oct 29 20:05:24 fw pluto[25973]: | found eth1 with address 10.254.254.2 Oct 29 20:05:24 fw pluto[25973]: | found eth2 with address 10.254.253.2 Oct 29 20:05:24 fw pluto[25973]: | found eth3 with address 192.168.252.44 Oct 29 20:05:24 fw pluto[25973]: | IP interface eth3 192.168.252.44 has no matching ipsec* interface -- ignored Oct 29 20:05:24 fw pluto[25973]: | IP interface eth2 10.254.253.2 has no matching ipsec* interface -- ignored Oct 29 20:05:24 fw pluto[25973]: adding interface ipsec0/eth1 10.254.254.2:500 Oct 29 20:05:24 fw pluto[25973]: adding interface ipsec0/eth1 10.254.254.2:4500 Oct 29 20:05:24 fw pluto[25973]: | IP interface eth0 192.168.16.254 has no matching ipsec* interface -- ignored Oct 29 20:05:24 fw pluto[25973]: | IP interface lo 127.0.0.1 has no matching ipsec* interface -- ignored Oct 29 20:05:24 fw pluto[25973]: | could not open /proc/net/if_inet6 Oct 29 20:05:24 fw pluto[25973]: loading secrets from "/etc/ipsec.secrets" Oct 29 20:05:24 fw pluto[25973]: | loaded private key for keyid: PPK_RSA:AQO1iESYC Oct 29 20:05:24 fw pluto[25973]: | next event EVENT_SHUNT_SCAN in 119 seconds Oct 29 20:05:39 fw pluto[25973]: | Oct 29 20:05:39 fw pluto[25973]: | *received 312 bytes from 85.159.160.201:30957 on eth1 (port=500) Oct 29 20:05:39 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:39 fw pluto[25973]: | initiator cookie: Oct 29 20:05:39 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:39 fw pluto[25973]: | responder cookie: Oct 29 20:05:39 fw pluto[25973]: | 00 00 00 00 00 00 00 00 Oct 29 20:05:39 fw pluto[25973]: | next payload type: ISAKMP_NEXT_SA Oct 29 20:05:39 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:39 fw pluto[25973]: | exchange type: ISAKMP_XCHG_IDPROT Oct 29 20:05:39 fw pluto[25973]: | flags: none Oct 29 20:05:39 fw pluto[25973]: | message ID: 00 00 00 00 Oct 29 20:05:39 fw pluto[25973]: | length: 312 Oct 29 20:05:39 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2) Oct 29 20:05:39 fw pluto[25973]: | ***parse ISAKMP Security Association Payload: Oct 29 20:05:40 fw pluto[25973]: | next payload type: ISAKMP_NEXT_VID Oct 29 20:05:40 fw pluto[25973]: | length: 200 Oct 29 20:05:40 fw pluto[25973]: | DOI: ISAKMP_DOI_IPSEC Oct 29 20:05:40 fw pluto[25973]: | ***parse ISAKMP Vendor ID Payload: Oct 29 20:05:40 fw pluto[25973]: | next payload type: ISAKMP_NEXT_VID Oct 29 20:05:40 fw pluto[25973]: | length: 24 Oct 29 20:05:40 fw pluto[25973]: | ***parse ISAKMP Vendor ID Payload: Oct 29 20:05:40 fw pluto[25973]: | next payload type: ISAKMP_NEXT_VID Oct 29 20:05:40 fw pluto[25973]: | length: 20 Oct 29 20:05:40 fw pluto[25973]: | ***parse ISAKMP Vendor ID Payload: Oct 29 20:05:40 fw pluto[25973]: | next payload type: ISAKMP_NEXT_VID Oct 29 20:05:40 fw pluto[25973]: | length: 20 Oct 29 20:05:40 fw pluto[25973]: | ***parse ISAKMP Vendor ID Payload: Oct 29 20:05:40 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:40 fw pluto[25973]: | length: 20 Oct 29 20:05:40 fw pluto[25973]: packet from 85.159.160.201:30957: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000004] Oct 29 20:05:40 fw pluto[25973]: packet from 85.159.160.201:30957: ignoring Vendor ID payload [FRAGMENTATION] Oct 29 20:05:40 fw pluto[25973]: packet from 85.159.160.201:30957: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] method set to=106 Oct 29 20:05:40 fw pluto[25973]: packet from 85.159.160.201:30957: ignoring Vendor ID payload [Vid-Initial-Contact] Oct 29 20:05:40 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=3 Oct 29 20:05:40 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=4 Oct 29 20:05:40 fw pluto[25973]: | instantiated "l2tp_2" for 85.159.160.201 Oct 29 20:05:40 fw pluto[25973]: | creating state object #1 at 0x978dc08 Oct 29 20:05:40 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:05:40 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:40 fw pluto[25973]: | RCOOKIE: d0 84 d2 20 c8 66 c6 56 Oct 29 20:05:40 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:40 fw pluto[25973]: | state hash entry 20 Oct 29 20:05:40 fw pluto[25973]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #1 Oct 29 20:05:40 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #1: responding to Main Mode from unknown peer 85.159.160.201 Oct 29 20:05:40 fw pluto[25973]: | ****parse IPsec DOI SIT: Oct 29 20:05:40 fw pluto[25973]: | IPsec DOI SIT: SIT_IDENTITY_ONLY Oct 29 20:05:40 fw pluto[25973]: | ****parse ISAKMP Proposal Payload: Oct 29 20:05:40 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:40 fw pluto[25973]: | length: 188 Oct 29 20:05:40 fw pluto[25973]: | proposal number: 1 Oct 29 20:05:40 fw pluto[25973]: | protocol ID: PROTO_ISAKMP Oct 29 20:05:40 fw pluto[25973]: | SPI size: 0 Oct 29 20:05:40 fw pluto[25973]: | number of transforms: 5 Oct 29 20:05:40 fw pluto[25973]: | *****parse ISAKMP Transform Payload (ISAKMP): Oct 29 20:05:40 fw pluto[25973]: | next payload type: ISAKMP_NEXT_T Oct 29 20:05:40 fw pluto[25973]: | length: 36 Oct 29 20:05:40 fw pluto[25973]: | transform number: 1 Oct 29 20:05:40 fw pluto[25973]: | transform ID: KEY_IKE Oct 29 20:05:40 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:40 fw pluto[25973]: | af+type: OAKLEY_ENCRYPTION_ALGORITHM Oct 29 20:05:40 fw pluto[25973]: | length/value: 5 Oct 29 20:05:40 fw pluto[25973]: | [5 is OAKLEY_3DES_CBC] Oct 29 20:05:40 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:40 fw pluto[25973]: | af+type: OAKLEY_HASH_ALGORITHM Oct 29 20:05:40 fw pluto[25973]: | length/value: 2 Oct 29 20:05:40 fw pluto[25973]: | [2 is OAKLEY_SHA1] Oct 29 20:05:40 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:40 fw pluto[25973]: | af+type: OAKLEY_GROUP_DESCRIPTION Oct 29 20:05:40 fw pluto[25973]: | length/value: 14 Oct 29 20:05:40 fw pluto[25973]: | [14 is OAKLEY_GROUP_MODP2048] Oct 29 20:05:40 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:40 fw pluto[25973]: | af+type: OAKLEY_AUTHENTICATION_METHOD Oct 29 20:05:40 fw pluto[25973]: | length/value: 1 Oct 29 20:05:40 fw pluto[25973]: | [1 is OAKLEY_PRESHARED_KEY] Oct 29 20:05:40 fw pluto[25973]: | started looking for secret for 10.254.254.2->85.159.160.201 of kind PPK_PSK Oct 29 20:05:40 fw pluto[25973]: | instantiating him to 0.0.0.0 Oct 29 20:05:40 fw pluto[25973]: | actually looking for secret for 10.254.254.2->0.0.0.0 of kind PPK_PSK Oct 29 20:05:40 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:40 fw pluto[25973]: | 2: compared PSK 192.168.252.44 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:40 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:40 fw pluto[25973]: | 2: compared PSK 10.254.253.2 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:40 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:40 fw pluto[25973]: | 2: compared PSK 10.254.254.2 to 10.254.254.2 / 85.159.160.201 -> 6 Oct 29 20:05:40 fw pluto[25973]: | best_match 0>6 best=0x978ccb8 (line=18) Oct 29 20:05:40 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:40 fw pluto[25973]: | 2: compared PSK 192.168.16.254 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:40 fw pluto[25973]: | concluding with best_match=6 best=0x978ccb8 (lineno=18) Oct 29 20:05:40 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:40 fw pluto[25973]: | af+type: OAKLEY_LIFE_TYPE Oct 29 20:05:40 fw pluto[25973]: | length/value: 1 Oct 29 20:05:40 fw pluto[25973]: | [1 is OAKLEY_LIFE_SECONDS] Oct 29 20:05:40 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:40 fw pluto[25973]: | af+type: OAKLEY_LIFE_DURATION (variable length) Oct 29 20:05:40 fw pluto[25973]: | length/value: 4 Oct 29 20:05:40 fw pluto[25973]: | long duration: 28800 Oct 29 20:05:40 fw pluto[25973]: | Oakley Transform 1 accepted Oct 29 20:05:40 fw pluto[25973]: | complete state transition with STF_OK Oct 29 20:05:40 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #1: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1 Oct 29 20:05:40 fw pluto[25973]: | sending reply packet to 85.159.160.201:30957 (from port=500) Oct 29 20:05:40 fw pluto[25973]: | sending 140 bytes for STATE_MAIN_R0 through eth1:500 to 85.159.160.201:30957: Oct 29 20:05:40 fw pluto[25973]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1 Oct 29 20:05:40 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #1: STATE_MAIN_R1: sent MR1, expecting MI2 Oct 29 20:05:40 fw pluto[25973]: | modecfg pull: noquirk policy:push not-client Oct 29 20:05:40 fw pluto[25973]: | phase 1 is done, looking for phase 1 to unpend Oct 29 20:05:40 fw pluto[25973]: | next event EVENT_RETRANSMIT in 10 seconds for #1 Oct 29 20:05:41 fw pluto[25973]: | Oct 29 20:05:41 fw pluto[25973]: | *received 312 bytes from 85.159.160.201:30957 on eth1 (port=500) Oct 29 20:05:41 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:41 fw pluto[25973]: | initiator cookie: Oct 29 20:05:41 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:41 fw pluto[25973]: | responder cookie: Oct 29 20:05:41 fw pluto[25973]: | 00 00 00 00 00 00 00 00 Oct 29 20:05:41 fw pluto[25973]: | next payload type: ISAKMP_NEXT_SA Oct 29 20:05:41 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:41 fw pluto[25973]: | exchange type: ISAKMP_XCHG_IDPROT Oct 29 20:05:41 fw pluto[25973]: | flags: none Oct 29 20:05:41 fw pluto[25973]: | message ID: 00 00 00 00 Oct 29 20:05:41 fw pluto[25973]: | length: 312 Oct 29 20:05:41 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2) Oct 29 20:05:41 fw pluto[25973]: | ***parse ISAKMP Security Association Payload: Oct 29 20:05:41 fw pluto[25973]: | next payload type: ISAKMP_NEXT_VID Oct 29 20:05:41 fw pluto[25973]: | length: 200 Oct 29 20:05:41 fw pluto[25973]: | DOI: ISAKMP_DOI_IPSEC Oct 29 20:05:41 fw pluto[25973]: | ***parse ISAKMP Vendor ID Payload: Oct 29 20:05:41 fw pluto[25973]: | next payload type: ISAKMP_NEXT_VID Oct 29 20:05:41 fw pluto[25973]: | length: 24 Oct 29 20:05:41 fw pluto[25973]: | ***parse ISAKMP Vendor ID Payload: Oct 29 20:05:41 fw pluto[25973]: | next payload type: ISAKMP_NEXT_VID Oct 29 20:05:41 fw pluto[25973]: | length: 20 Oct 29 20:05:41 fw pluto[25973]: | ***parse ISAKMP Vendor ID Payload: Oct 29 20:05:41 fw pluto[25973]: | next payload type: ISAKMP_NEXT_VID Oct 29 20:05:41 fw pluto[25973]: | length: 20 Oct 29 20:05:41 fw pluto[25973]: | ***parse ISAKMP Vendor ID Payload: Oct 29 20:05:41 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:41 fw pluto[25973]: | length: 20 Oct 29 20:05:41 fw pluto[25973]: packet from 85.159.160.201:30957: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000004] Oct 29 20:05:41 fw pluto[25973]: packet from 85.159.160.201:30957: ignoring Vendor ID payload [FRAGMENTATION] Oct 29 20:05:41 fw pluto[25973]: packet from 85.159.160.201:30957: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] method set to=106 Oct 29 20:05:41 fw pluto[25973]: packet from 85.159.160.201:30957: ignoring Vendor ID payload [Vid-Initial-Contact] Oct 29 20:05:41 fw pluto[25973]: | creating state object #2 at 0x978e260 Oct 29 20:05:41 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:05:41 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:41 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:41 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:41 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:41 fw pluto[25973]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #2 Oct 29 20:05:41 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #2: responding to Main Mode from unknown peer 85.159.160.201 Oct 29 20:05:41 fw pluto[25973]: | ****parse IPsec DOI SIT: Oct 29 20:05:41 fw pluto[25973]: | IPsec DOI SIT: SIT_IDENTITY_ONLY Oct 29 20:05:41 fw pluto[25973]: | ****parse ISAKMP Proposal Payload: Oct 29 20:05:41 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:41 fw pluto[25973]: | length: 188 Oct 29 20:05:41 fw pluto[25973]: | proposal number: 1 Oct 29 20:05:41 fw pluto[25973]: | protocol ID: PROTO_ISAKMP Oct 29 20:05:41 fw pluto[25973]: | SPI size: 0 Oct 29 20:05:41 fw pluto[25973]: | number of transforms: 5 Oct 29 20:05:41 fw pluto[25973]: | *****parse ISAKMP Transform Payload (ISAKMP): Oct 29 20:05:41 fw pluto[25973]: | next payload type: ISAKMP_NEXT_T Oct 29 20:05:41 fw pluto[25973]: | length: 36 Oct 29 20:05:41 fw pluto[25973]: | transform number: 1 Oct 29 20:05:41 fw pluto[25973]: | transform ID: KEY_IKE Oct 29 20:05:41 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:41 fw pluto[25973]: | af+type: OAKLEY_ENCRYPTION_ALGORITHM Oct 29 20:05:41 fw pluto[25973]: | length/value: 5 Oct 29 20:05:41 fw pluto[25973]: | [5 is OAKLEY_3DES_CBC] Oct 29 20:05:41 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:41 fw pluto[25973]: | af+type: OAKLEY_HASH_ALGORITHM Oct 29 20:05:41 fw pluto[25973]: | length/value: 2 Oct 29 20:05:41 fw pluto[25973]: | [2 is OAKLEY_SHA1] Oct 29 20:05:41 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:41 fw pluto[25973]: | af+type: OAKLEY_GROUP_DESCRIPTION Oct 29 20:05:41 fw pluto[25973]: | length/value: 14 Oct 29 20:05:41 fw pluto[25973]: | [14 is OAKLEY_GROUP_MODP2048] Oct 29 20:05:41 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:41 fw pluto[25973]: | af+type: OAKLEY_AUTHENTICATION_METHOD Oct 29 20:05:41 fw pluto[25973]: | length/value: 1 Oct 29 20:05:41 fw pluto[25973]: | [1 is OAKLEY_PRESHARED_KEY] Oct 29 20:05:41 fw pluto[25973]: | started looking for secret for 10.254.254.2->85.159.160.201 of kind PPK_PSK Oct 29 20:05:41 fw pluto[25973]: | instantiating him to 0.0.0.0 Oct 29 20:05:41 fw pluto[25973]: | actually looking for secret for 10.254.254.2->0.0.0.0 of kind PPK_PSK Oct 29 20:05:41 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:41 fw pluto[25973]: | 2: compared PSK 192.168.252.44 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:41 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:41 fw pluto[25973]: | 2: compared PSK 10.254.253.2 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:41 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:41 fw pluto[25973]: | 2: compared PSK 10.254.254.2 to 10.254.254.2 / 85.159.160.201 -> 6 Oct 29 20:05:41 fw pluto[25973]: | best_match 0>6 best=0x978ccb8 (line=18) Oct 29 20:05:41 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:41 fw pluto[25973]: | 2: compared PSK 192.168.16.254 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:41 fw pluto[25973]: | concluding with best_match=6 best=0x978ccb8 (lineno=18) Oct 29 20:05:41 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:41 fw pluto[25973]: | af+type: OAKLEY_LIFE_TYPE Oct 29 20:05:41 fw pluto[25973]: | length/value: 1 Oct 29 20:05:41 fw pluto[25973]: | [1 is OAKLEY_LIFE_SECONDS] Oct 29 20:05:41 fw pluto[25973]: | ******parse ISAKMP Oakley attribute: Oct 29 20:05:41 fw pluto[25973]: | af+type: OAKLEY_LIFE_DURATION (variable length) Oct 29 20:05:41 fw pluto[25973]: | length/value: 4 Oct 29 20:05:41 fw pluto[25973]: | long duration: 28800 Oct 29 20:05:41 fw pluto[25973]: | Oakley Transform 1 accepted Oct 29 20:05:41 fw pluto[25973]: | complete state transition with STF_OK Oct 29 20:05:41 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #2: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1 Oct 29 20:05:41 fw pluto[25973]: | sending reply packet to 85.159.160.201:30957 (from port=500) Oct 29 20:05:41 fw pluto[25973]: | sending 140 bytes for STATE_MAIN_R0 through eth1:500 to 85.159.160.201:30957: Oct 29 20:05:41 fw pluto[25973]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #2 Oct 29 20:05:41 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #2: STATE_MAIN_R1: sent MR1, expecting MI2 Oct 29 20:05:41 fw pluto[25973]: | modecfg pull: noquirk policy:push not-client Oct 29 20:05:41 fw pluto[25973]: | phase 1 is done, looking for phase 1 to unpend Oct 29 20:05:41 fw pluto[25973]: | next event EVENT_RETRANSMIT in 9 seconds for #1 Oct 29 20:05:42 fw pluto[25973]: | Oct 29 20:05:42 fw pluto[25973]: | *received 360 bytes from 85.159.160.201:30957 on eth1 (port=500) Oct 29 20:05:42 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:42 fw pluto[25973]: | initiator cookie: Oct 29 20:05:42 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:42 fw pluto[25973]: | responder cookie: Oct 29 20:05:42 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:42 fw pluto[25973]: | next payload type: ISAKMP_NEXT_KE Oct 29 20:05:42 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:42 fw pluto[25973]: | exchange type: ISAKMP_XCHG_IDPROT Oct 29 20:05:42 fw pluto[25973]: | flags: none Oct 29 20:05:42 fw pluto[25973]: | message ID: 00 00 00 00 Oct 29 20:05:42 fw pluto[25973]: | length: 360 Oct 29 20:05:42 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2) Oct 29 20:05:42 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:42 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:42 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:42 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:42 fw pluto[25973]: | peer and cookies match on #2, provided msgid 00000000 vs 00000000 Oct 29 20:05:42 fw pluto[25973]: | state object #2 found, in STATE_MAIN_R1 Oct 29 20:05:42 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:05:42 fw pluto[25973]: | ***parse ISAKMP Key Exchange Payload: Oct 29 20:05:42 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONCE Oct 29 20:05:42 fw pluto[25973]: | length: 260 Oct 29 20:05:42 fw pluto[25973]: | ***parse ISAKMP Nonce Payload: Oct 29 20:05:42 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NAT-D Oct 29 20:05:42 fw pluto[25973]: | length: 24 Oct 29 20:05:42 fw pluto[25973]: | ***parse ISAKMP NAT-D Payload: Oct 29 20:05:42 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NAT-D Oct 29 20:05:42 fw pluto[25973]: | length: 24 Oct 29 20:05:42 fw pluto[25973]: | ***parse ISAKMP NAT-D Payload: Oct 29 20:05:43 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:43 fw pluto[25973]: | length: 24 Oct 29 20:05:43 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #2: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike-02/03: both are NATed Oct 29 20:05:43 fw pluto[25973]: | inserting event EVENT_NAT_T_KEEPALIVE, timeout in 20 seconds Oct 29 20:05:43 fw pluto[25973]: | 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1 Oct 29 20:05:43 fw pluto[25973]: | asking helper 0 to do build_kenonce op on seq: 1 Oct 29 20:05:43 fw pluto[25973]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #2 Oct 29 20:05:43 fw pluto[25974]: ! helper -1 doing build_kenonce op id: 1 Oct 29 20:05:43 fw pluto[25973]: | complete state transition with STF_SUSPEND Oct 29 20:05:43 fw pluto[25973]: | next event EVENT_RETRANSMIT in 7 seconds for #1 Oct 29 20:05:43 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:05:43 fw pluto[25973]: | started looking for secret for 10.254.254.2->85.159.160.201 of kind PPK_PSK Oct 29 20:05:43 fw pluto[25973]: | instantiating him to 0.0.0.0 Oct 29 20:05:43 fw pluto[25973]: | actually looking for secret for 10.254.254.2->0.0.0.0 of kind PPK_PSK Oct 29 20:05:43 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:43 fw pluto[25973]: | 2: compared PSK 192.168.252.44 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:43 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:43 fw pluto[25973]: | 2: compared PSK 10.254.253.2 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:43 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:43 fw pluto[25973]: | 2: compared PSK 10.254.254.2 to 10.254.254.2 / 85.159.160.201 -> 6 Oct 29 20:05:43 fw pluto[25973]: | best_match 0>6 best=0x978ccb8 (line=18) Oct 29 20:05:43 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:43 fw pluto[25973]: | 2: compared PSK 192.168.16.254 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:43 fw pluto[25973]: | concluding with best_match=6 best=0x978ccb8 (lineno=18) Oct 29 20:05:43 fw pluto[25973]: | complete state transition with STF_OK Oct 29 20:05:43 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #2: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2 Oct 29 20:05:43 fw pluto[25973]: | sending reply packet to 85.159.160.201:30957 (from port=500) Oct 29 20:05:43 fw pluto[25973]: | sending 356 bytes for STATE_MAIN_R1 through eth1:500 to 85.159.160.201:30957: Oct 29 20:05:43 fw pluto[25973]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #2 Oct 29 20:05:43 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #2: STATE_MAIN_R2: sent MR2, expecting MI3 Oct 29 20:05:43 fw pluto[25973]: | modecfg pull: noquirk policy:push not-client Oct 29 20:05:43 fw pluto[25973]: | phase 1 is done, looking for phase 1 to unpend Oct 29 20:05:43 fw pluto[25973]: | next event EVENT_RETRANSMIT in 7 seconds for #1 Oct 29 20:05:44 fw pluto[25973]: | Oct 29 20:05:44 fw pluto[25973]: | *received 360 bytes from 85.159.160.201:30957 on eth1 (port=500) Oct 29 20:05:44 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:44 fw pluto[25973]: | initiator cookie: Oct 29 20:05:44 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:44 fw pluto[25973]: | responder cookie: Oct 29 20:05:44 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:44 fw pluto[25973]: | next payload type: ISAKMP_NEXT_KE Oct 29 20:05:44 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:44 fw pluto[25973]: | exchange type: ISAKMP_XCHG_IDPROT Oct 29 20:05:44 fw pluto[25973]: | flags: none Oct 29 20:05:44 fw pluto[25973]: | message ID: 00 00 00 00 Oct 29 20:05:44 fw pluto[25973]: | length: 360 Oct 29 20:05:44 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2) Oct 29 20:05:44 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:44 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:44 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:44 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:44 fw pluto[25973]: | peer and cookies match on #2, provided msgid 00000000 vs 00000000 Oct 29 20:05:44 fw pluto[25973]: | state object #2 found, in STATE_MAIN_R2 Oct 29 20:05:44 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:05:44 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #2: discarding duplicate packet; already STATE_MAIN_R2 Oct 29 20:05:44 fw pluto[25973]: | next event EVENT_RETRANSMIT in 6 seconds for #1 Oct 29 20:05:44 fw pluto[25973]: | Oct 29 20:05:44 fw pluto[25973]: | *received 68 bytes from 85.159.160.201:30510 on eth1 (port=4500) Oct 29 20:05:44 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:44 fw pluto[25973]: | initiator cookie: Oct 29 20:05:44 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:44 fw pluto[25973]: | responder cookie: Oct 29 20:05:44 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:44 fw pluto[25973]: | next payload type: ISAKMP_NEXT_ID Oct 29 20:05:44 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:44 fw pluto[25973]: | exchange type: ISAKMP_XCHG_IDPROT Oct 29 20:05:44 fw pluto[25973]: | flags: ISAKMP_FLAG_ENCRYPTION Oct 29 20:05:44 fw pluto[25973]: | message ID: 00 00 00 00 Oct 29 20:05:44 fw pluto[25973]: | length: 68 Oct 29 20:05:44 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2) Oct 29 20:05:44 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:44 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:44 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:44 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:44 fw pluto[25973]: | peer and cookies match on #2, provided msgid 00000000 vs 00000000 Oct 29 20:05:44 fw pluto[25973]: | state object #2 found, in STATE_MAIN_R2 Oct 29 20:05:44 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:05:44 fw pluto[25973]: | ***parse ISAKMP Identification Payload: Oct 29 20:05:44 fw pluto[25973]: | next payload type: ISAKMP_NEXT_HASH Oct 29 20:05:44 fw pluto[25973]: | length: 14 Oct 29 20:05:44 fw pluto[25973]: | ID type: ID_FQDN Oct 29 20:05:44 fw pluto[25973]: | DOI specific A: 0 Oct 29 20:05:44 fw pluto[25973]: | DOI specific B: 0 Oct 29 20:05:44 fw pluto[25973]: | ***parse ISAKMP Hash Payload: Oct 29 20:05:44 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:44 fw pluto[25973]: | length: 24 Oct 29 20:05:44 fw pluto[25973]: | removing 2 bytes of padding Oct 29 20:05:44 fw pluto[25973]: "l2tp_2"[1] 85.159.160.201 #2: Main mode peer ID is ID_FQDN: '@QB-R40' Oct 29 20:05:44 fw pluto[25973]: | started looking for secret for 10.254.254.2->85.159.160.201 of kind PPK_PSK Oct 29 20:05:44 fw pluto[25973]: | instantiating him to 0.0.0.0 Oct 29 20:05:44 fw pluto[25973]: | actually looking for secret for 10.254.254.2->0.0.0.0 of kind PPK_PSK Oct 29 20:05:44 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:44 fw pluto[25973]: | 2: compared PSK 192.168.252.44 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:44 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:44 fw pluto[25973]: | 2: compared PSK 10.254.253.2 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:44 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:44 fw pluto[25973]: | 2: compared PSK 10.254.254.2 to 10.254.254.2 / 85.159.160.201 -> 6 Oct 29 20:05:44 fw pluto[25973]: | best_match 0>6 best=0x978ccb8 (line=18) Oct 29 20:05:44 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:44 fw pluto[25973]: | 2: compared PSK 192.168.16.254 to 10.254.254.2 / 85.159.160.201 -> 2 Oct 29 20:05:44 fw pluto[25973]: | concluding with best_match=6 best=0x978ccb8 (lineno=18) Oct 29 20:05:44 fw pluto[25973]: | started looking for secret for 10.254.254.2->(none) of kind PPK_PSK Oct 29 20:05:44 fw pluto[25973]: | replace him to 0.0.0.0 Oct 29 20:05:44 fw pluto[25973]: | actually looking for secret for 10.254.254.2->0.0.0.0 of kind PPK_PSK Oct 29 20:05:44 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / (none) -> 2 Oct 29 20:05:44 fw pluto[25973]: | 2: compared PSK 192.168.252.44 to 10.254.254.2 / (none) -> 2 Oct 29 20:05:44 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / (none) -> 2 Oct 29 20:05:44 fw pluto[25973]: | 2: compared PSK 10.254.253.2 to 10.254.254.2 / (none) -> 2 Oct 29 20:05:44 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / (none) -> 2 Oct 29 20:05:44 fw pluto[25973]: | 2: compared PSK 10.254.254.2 to 10.254.254.2 / (none) -> 6 Oct 29 20:05:44 fw pluto[25973]: | best_match 0>6 best=0x978ccb8 (line=18) Oct 29 20:05:44 fw pluto[25973]: | 1: compared PSK 0.0.0.0 to 10.254.254.2 / (none) -> 2 Oct 29 20:05:44 fw pluto[25973]: | 2: compared PSK 192.168.16.254 to 10.254.254.2 / (none) -> 2 Oct 29 20:05:44 fw pluto[25973]: | concluding with best_match=6 best=0x978ccb8 (lineno=18) Oct 29 20:05:44 fw pluto[25973]: | offered CA: '%none' Oct 29 20:05:44 fw pluto[25973]: | switched from "l2tp_2" to "l2tp_2" Oct 29 20:05:44 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=5 Oct 29 20:05:44 fw pluto[25973]: | alg_info_addref() alg_info->ref_cnt=6 Oct 29 20:05:44 fw pluto[25973]: | instantiated "l2tp_2" for 85.159.160.201 Oct 29 20:05:44 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:05:44 fw pluto[25973]: | thinking about whether to send my certificate: Oct 29 20:05:44 fw pluto[25973]: | I have RSA key: OAKLEY_PRESHARED_KEY cert.type: CERT_NONE Oct 29 20:05:44 fw pluto[25973]: | sendcert: CERT_ALWAYSSEND and I did not get a certificate request Oct 29 20:05:44 fw pluto[25973]: | so do not send cert. Oct 29 20:05:44 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #2: I did not send a certificate because I do not have one. Oct 29 20:05:44 fw pluto[25973]: | complete state transition with STF_OK Oct 29 20:05:44 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #2: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3 Oct 29 20:05:44 fw pluto[25973]: | sending reply packet to 85.159.160.201:30957 (from port=500) Oct 29 20:05:44 fw pluto[25973]: | NAT-T: new mapping 85.159.160.201:30957/30510) Oct 29 20:05:44 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:05:44 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:05:44 fw pluto[25973]: | sending 68 bytes for STATE_MAIN_R2 through eth1:4500 to 85.159.160.201:30510: Oct 29 20:05:44 fw pluto[25973]: | inserting event EVENT_SA_EXPIRE, timeout in 28800 seconds for #2 Oct 29 20:05:44 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #2: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp2048} Oct 29 20:05:44 fw pluto[25973]: | modecfg pull: noquirk policy:push not-client Oct 29 20:05:44 fw pluto[25973]: | phase 1 is done, looking for phase 1 to unpend Oct 29 20:05:44 fw pluto[25973]: | next event EVENT_RETRANSMIT in 6 seconds for #1 Oct 29 20:05:44 fw pluto[25973]: | Oct 29 20:05:44 fw pluto[25973]: | *received 68 bytes from 85.159.160.201:30510 on eth1 (port=4500) Oct 29 20:05:44 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:44 fw pluto[25973]: | initiator cookie: Oct 29 20:05:44 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:44 fw pluto[25973]: | responder cookie: Oct 29 20:05:44 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:44 fw pluto[25973]: | next payload type: ISAKMP_NEXT_ID Oct 29 20:05:44 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:44 fw pluto[25973]: | exchange type: ISAKMP_XCHG_IDPROT Oct 29 20:05:45 fw pluto[25973]: | flags: ISAKMP_FLAG_ENCRYPTION Oct 29 20:05:45 fw pluto[25973]: | message ID: 00 00 00 00 Oct 29 20:05:45 fw pluto[25973]: | length: 68 Oct 29 20:05:45 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2) Oct 29 20:05:45 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:45 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:45 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:45 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:45 fw pluto[25973]: | peer and cookies match on #2, provided msgid 00000000 vs 00000000 Oct 29 20:05:45 fw pluto[25973]: | state object #2 found, in STATE_MAIN_R3 Oct 29 20:05:45 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:05:45 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #2: retransmitting in response to duplicate packet; already STATE_MAIN_R3 Oct 29 20:05:45 fw pluto[25973]: | sending 68 bytes for retransmit in response to duplicate through eth1:4500 to 85.159.160.201:30510: Oct 29 20:05:45 fw pluto[25973]: | next event EVENT_RETRANSMIT in 5 seconds for #1 Oct 29 20:05:45 fw pluto[25973]: | Oct 29 20:05:45 fw pluto[25973]: | *received 300 bytes from 85.159.160.201:30510 on eth1 (port=4500) Oct 29 20:05:45 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:45 fw pluto[25973]: | initiator cookie: Oct 29 20:05:45 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:45 fw pluto[25973]: | responder cookie: Oct 29 20:05:45 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:45 fw pluto[25973]: | next payload type: ISAKMP_NEXT_HASH Oct 29 20:05:45 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:45 fw pluto[25973]: | exchange type: ISAKMP_XCHG_QUICK Oct 29 20:05:45 fw pluto[25973]: | flags: ISAKMP_FLAG_ENCRYPTION Oct 29 20:05:45 fw pluto[25973]: | message ID: ec 3d 22 d6 Oct 29 20:05:45 fw pluto[25973]: | length: 300 Oct 29 20:05:45 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_QUICK (32) Oct 29 20:05:45 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:45 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:45 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:45 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:45 fw pluto[25973]: | peer and cookies match on #2, provided msgid ec3d22d6 vs 00000000 Oct 29 20:05:45 fw pluto[25973]: | state object not found Oct 29 20:05:45 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:45 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:45 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:45 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:45 fw pluto[25973]: | peer and cookies match on #2, provided msgid 00000000 vs 00000000 Oct 29 20:05:45 fw pluto[25973]: | state object #2 found, in STATE_MAIN_R3 Oct 29 20:05:45 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:05:45 fw pluto[25973]: | ***parse ISAKMP Hash Payload: Oct 29 20:05:45 fw pluto[25973]: | next payload type: ISAKMP_NEXT_SA Oct 29 20:05:45 fw pluto[25973]: | length: 24 Oct 29 20:05:45 fw pluto[25973]: | ***parse ISAKMP Security Association Payload: Oct 29 20:05:45 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONCE Oct 29 20:05:45 fw pluto[25973]: | length: 184 Oct 29 20:05:45 fw pluto[25973]: | DOI: ISAKMP_DOI_IPSEC Oct 29 20:05:45 fw pluto[25973]: | ***parse ISAKMP Nonce Payload: Oct 29 20:05:45 fw pluto[25973]: | next payload type: ISAKMP_NEXT_ID Oct 29 20:05:45 fw pluto[25973]: | length: 24 Oct 29 20:05:45 fw pluto[25973]: | ***parse ISAKMP Identification Payload (IPsec DOI): Oct 29 20:05:45 fw pluto[25973]: | next payload type: ISAKMP_NEXT_ID Oct 29 20:05:45 fw pluto[25973]: | length: 14 Oct 29 20:05:45 fw pluto[25973]: | ID type: ID_FQDN Oct 29 20:05:45 fw pluto[25973]: | Protocol ID: 17 Oct 29 20:05:45 fw pluto[25973]: | port: 1701 Oct 29 20:05:45 fw pluto[25973]: | ***parse ISAKMP Identification Payload (IPsec DOI): Oct 29 20:05:45 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NAT-OA Oct 29 20:05:45 fw pluto[25973]: | length: 12 Oct 29 20:05:45 fw pluto[25973]: | ID type: ID_IPV4_ADDR Oct 29 20:05:45 fw pluto[25973]: | Protocol ID: 17 Oct 29 20:05:45 fw pluto[25973]: | port: 1701 Oct 29 20:05:45 fw pluto[25973]: | ***parse ISAKMP NAT-OA Payload: Oct 29 20:05:45 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:45 fw pluto[25973]: | length: 12 Oct 29 20:05:45 fw pluto[25973]: | ID type: ID_IPV4_ADDR Oct 29 20:05:45 fw pluto[25973]: | removing 2 bytes of padding Oct 29 20:05:45 fw pluto[25973]: | our client is 192.117.136.11 Oct 29 20:05:45 fw pluto[25973]: | our client protocol/port is 17/1701 Oct 29 20:05:45 fw pluto[25973]: | using (something) old for transport mode connection "l2tp_2" Oct 29 20:05:45 fw pluto[25973]: | duplicating state object #2 Oct 29 20:05:45 fw pluto[25973]: | creating state object #3 at 0x978fc48 Oct 29 20:05:45 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:05:45 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:45 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:45 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:45 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:45 fw pluto[25973]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #3 Oct 29 20:05:45 fw pluto[25973]: | NAT-OA: 00 00 00 0c 01 00 00 00 0a 95 1c 21 Oct 29 20:05:45 fw pluto[25973]: | ****parse IPsec DOI SIT: Oct 29 20:05:45 fw pluto[25973]: | IPsec DOI SIT: SIT_IDENTITY_ONLY Oct 29 20:05:45 fw pluto[25973]: | ****parse ISAKMP Proposal Payload: Oct 29 20:05:45 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:45 fw pluto[25973]: | length: 172 Oct 29 20:05:45 fw pluto[25973]: | proposal number: 1 Oct 29 20:05:45 fw pluto[25973]: | protocol ID: PROTO_IPSEC_ESP Oct 29 20:05:45 fw pluto[25973]: | SPI size: 4 Oct 29 20:05:46 fw pluto[25973]: | number of transforms: 4 Oct 29 20:05:46 fw pluto[25973]: | parsing 4 raw bytes of ISAKMP Proposal Payload into SPI Oct 29 20:05:46 fw pluto[25973]: | SPI 94 e0 e5 d2 Oct 29 20:05:46 fw pluto[25973]: | *****parse ISAKMP Transform Payload (ESP): Oct 29 20:05:46 fw pluto[25973]: | next payload type: ISAKMP_NEXT_T Oct 29 20:05:46 fw pluto[25973]: | length: 40 Oct 29 20:05:46 fw pluto[25973]: | transform number: 1 Oct 29 20:05:46 fw pluto[25973]: | transform ID: ESP_3DES Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: SA_LIFE_TYPE Oct 29 20:05:46 fw pluto[25973]: | length/value: 1 Oct 29 20:05:46 fw pluto[25973]: | [1 is SA_LIFE_TYPE_SECONDS] Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: SA_LIFE_DURATION (variable length) Oct 29 20:05:46 fw pluto[25973]: | length/value: 4 Oct 29 20:05:46 fw pluto[25973]: | long duration: 3600 Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: SA_LIFE_TYPE Oct 29 20:05:46 fw pluto[25973]: | length/value: 2 Oct 29 20:05:46 fw pluto[25973]: | [2 is SA_LIFE_TYPE_KBYTES] Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: SA_LIFE_DURATION (variable length) Oct 29 20:05:46 fw pluto[25973]: | length/value: 4 Oct 29 20:05:46 fw pluto[25973]: | long duration: 250000 Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: ENCAPSULATION_MODE Oct 29 20:05:46 fw pluto[25973]: | length/value: 61444 Oct 29 20:05:46 fw pluto[25973]: | [61444 is ENCAPSULATION_MODE_UDP_TRANSPORT] Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: AUTH_ALGORITHM Oct 29 20:05:46 fw pluto[25973]: | length/value: 1 Oct 29 20:05:46 fw pluto[25973]: | [1 is AUTH_ALGORITHM_HMAC_MD5] Oct 29 20:05:46 fw pluto[25973]: | 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1 Oct 29 20:05:46 fw pluto[25973]: | asking helper 0 to do build_nonce op on seq: 2 Oct 29 20:05:46 fw pluto[25973]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #3 Oct 29 20:05:46 fw pluto[25974]: ! helper -1 doing build_nonce op id: 2 Oct 29 20:05:46 fw pluto[25973]: | complete state transition with STF_SUSPEND Oct 29 20:05:46 fw pluto[25973]: | next event EVENT_RETRANSMIT in 4 seconds for #1 Oct 29 20:05:46 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:05:46 fw pluto[25973]: | ****parse IPsec DOI SIT: Oct 29 20:05:46 fw pluto[25973]: | IPsec DOI SIT: SIT_IDENTITY_ONLY Oct 29 20:05:46 fw pluto[25973]: | ****parse ISAKMP Proposal Payload: Oct 29 20:05:46 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:46 fw pluto[25973]: | length: 172 Oct 29 20:05:46 fw pluto[25973]: | proposal number: 1 Oct 29 20:05:46 fw pluto[25973]: | protocol ID: PROTO_IPSEC_ESP Oct 29 20:05:46 fw pluto[25973]: | SPI size: 4 Oct 29 20:05:46 fw pluto[25973]: | number of transforms: 4 Oct 29 20:05:46 fw pluto[25973]: | parsing 4 raw bytes of ISAKMP Proposal Payload into SPI Oct 29 20:05:46 fw pluto[25973]: | SPI 94 e0 e5 d2 Oct 29 20:05:46 fw pluto[25973]: | *****parse ISAKMP Transform Payload (ESP): Oct 29 20:05:46 fw pluto[25973]: | next payload type: ISAKMP_NEXT_T Oct 29 20:05:46 fw pluto[25973]: | length: 40 Oct 29 20:05:46 fw pluto[25973]: | transform number: 1 Oct 29 20:05:46 fw pluto[25973]: | transform ID: ESP_3DES Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: SA_LIFE_TYPE Oct 29 20:05:46 fw pluto[25973]: | length/value: 1 Oct 29 20:05:46 fw pluto[25973]: | [1 is SA_LIFE_TYPE_SECONDS] Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: SA_LIFE_DURATION (variable length) Oct 29 20:05:46 fw pluto[25973]: | length/value: 4 Oct 29 20:05:46 fw pluto[25973]: | long duration: 3600 Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: SA_LIFE_TYPE Oct 29 20:05:46 fw pluto[25973]: | length/value: 2 Oct 29 20:05:46 fw pluto[25973]: | [2 is SA_LIFE_TYPE_KBYTES] Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: SA_LIFE_DURATION (variable length) Oct 29 20:05:46 fw pluto[25973]: | length/value: 4 Oct 29 20:05:46 fw pluto[25973]: | long duration: 250000 Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: ENCAPSULATION_MODE Oct 29 20:05:46 fw pluto[25973]: | length/value: 61444 Oct 29 20:05:46 fw pluto[25973]: | [61444 is ENCAPSULATION_MODE_UDP_TRANSPORT] Oct 29 20:05:46 fw pluto[25973]: | ******parse ISAKMP IPsec DOI attribute: Oct 29 20:05:46 fw pluto[25973]: | af+type: AUTH_ALGORITHM Oct 29 20:05:46 fw pluto[25973]: | length/value: 1 Oct 29 20:05:46 fw pluto[25973]: | [1 is AUTH_ALGORITHM_HMAC_MD5] Oct 29 20:05:46 fw pluto[25973]: | generate SPI: 2a 94 83 fd Oct 29 20:05:46 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #3: responding to Quick Mode {msgid:d6223dec} Oct 29 20:05:46 fw pluto[25973]: | compute_proto_keymat:needed_len (after ESP enc)=24 Oct 29 20:05:46 fw pluto[25973]: | compute_proto_keymat:needed_len (after ESP auth)=40 Oct 29 20:05:46 fw pluto[25973]: | install_inbound_ipsec_sa() checking if we can route Oct 29 20:05:46 fw pluto[25973]: | route owner of "l2tp_2"[2] 85.159.160.201 unrouted: NULL; eroute owner: NULL Oct 29 20:05:46 fw pluto[25973]: | could_route called for l2tp_2 (kind=CK_INSTANCE) Oct 29 20:05:46 fw pluto[25973]: | complete state transition with STF_OK Oct 29 20:05:46 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #3: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1 Oct 29 20:05:46 fw pluto[25973]: | sending reply packet to 85.159.160.201:30510 (from port=4500) Oct 29 20:05:46 fw pluto[25973]: | sending 164 bytes for STATE_QUICK_R0 through eth1:4500 to 85.159.160.201:30510: Oct 29 20:05:46 fw pluto[25973]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #3 Oct 29 20:05:46 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #3: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2 Oct 29 20:05:46 fw pluto[25973]: | modecfg pull: noquirk policy:push not-client Oct 29 20:05:46 fw pluto[25973]: | phase 1 is done, looking for phase 1 to unpend Oct 29 20:05:46 fw pluto[25973]: | next event EVENT_RETRANSMIT in 4 seconds for #1 Oct 29 20:05:46 fw pluto[25973]: | Oct 29 20:05:46 fw pluto[25973]: | *received 300 bytes from 85.159.160.201:30510 on eth1 (port=4500) Oct 29 20:05:46 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:46 fw pluto[25973]: | initiator cookie: Oct 29 20:05:46 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:46 fw pluto[25973]: | responder cookie: Oct 29 20:05:46 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:46 fw pluto[25973]: | next payload type: ISAKMP_NEXT_HASH Oct 29 20:05:46 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:46 fw pluto[25973]: | exchange type: ISAKMP_XCHG_QUICK Oct 29 20:05:46 fw pluto[25973]: | flags: ISAKMP_FLAG_ENCRYPTION Oct 29 20:05:46 fw pluto[25973]: | message ID: ec 3d 22 d6 Oct 29 20:05:46 fw pluto[25973]: | length: 300 Oct 29 20:05:46 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_QUICK (32) Oct 29 20:05:46 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:46 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:46 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:46 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:47 fw pluto[25973]: | peer and cookies match on #3, provided msgid ec3d22d6 vs ec3d22d6 Oct 29 20:05:47 fw pluto[25973]: | state object #3 found, in STATE_QUICK_R1 Oct 29 20:05:47 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:05:47 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #3: next payload type of ISAKMP Hash Payload has an unknown value: 67 Oct 29 20:05:47 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #3: malformed payload in packet Oct 29 20:05:47 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #3: sending notification PAYLOAD_MALFORMED to 85.159.160.201:30510 Oct 29 20:05:47 fw pluto[25973]: | sending 40 bytes for notification packet through eth1:4500 to 85.159.160.201:30510: Oct 29 20:05:47 fw pluto[25973]: | next event EVENT_RETRANSMIT in 3 seconds for #1 Oct 29 20:05:47 fw pluto[25973]: | Oct 29 20:05:47 fw pluto[25973]: | *received 52 bytes from 85.159.160.201:30510 on eth1 (port=4500) Oct 29 20:05:47 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:05:47 fw pluto[25973]: | initiator cookie: Oct 29 20:05:47 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:05:47 fw pluto[25973]: | responder cookie: Oct 29 20:05:47 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:47 fw pluto[25973]: | next payload type: ISAKMP_NEXT_HASH Oct 29 20:05:47 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:05:47 fw pluto[25973]: | exchange type: ISAKMP_XCHG_QUICK Oct 29 20:05:47 fw pluto[25973]: | flags: ISAKMP_FLAG_ENCRYPTION Oct 29 20:05:47 fw pluto[25973]: | message ID: ec 3d 22 d6 Oct 29 20:05:47 fw pluto[25973]: | length: 52 Oct 29 20:05:47 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_QUICK (32) Oct 29 20:05:47 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:05:47 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:05:47 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:05:47 fw pluto[25973]: | state hash entry 2 Oct 29 20:05:47 fw pluto[25973]: | peer and cookies match on #3, provided msgid ec3d22d6 vs ec3d22d6 Oct 29 20:05:47 fw pluto[25973]: | state object #3 found, in STATE_QUICK_R1 Oct 29 20:05:47 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:05:47 fw pluto[25973]: | ***parse ISAKMP Hash Payload: Oct 29 20:05:47 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:05:47 fw pluto[25973]: | length: 24 Oct 29 20:05:47 fw pluto[25973]: | install_ipsec_sa() for #3: outbound only Oct 29 20:05:47 fw pluto[25973]: | route owner of "l2tp_2"[2] 85.159.160.201 unrouted: NULL; eroute owner: NULL Oct 29 20:05:47 fw pluto[25973]: | could_route called for l2tp_2 (kind=CK_INSTANCE) Oct 29 20:05:47 fw pluto[25973]: | sr for #3: unrouted Oct 29 20:05:47 fw pluto[25973]: | route owner of "l2tp_2"[2] 85.159.160.201 unrouted: NULL; eroute owner: NULL Oct 29 20:05:47 fw pluto[25973]: | eroute_connection add eroute 10.254.254.2/32:1701 --17-> 85.159.160.201/32:1701 => esp.94e0e5d2@85.159.160.201 (raw_eroute) Oct 29 20:05:47 fw pluto[25973]: | command executing up-host Oct 29 20:05:47 fw pluto[25973]: | executing up-host: 2>&1 PLUTO_VERSION='1.1' PLUTO_VERB='up-host' PLUTO_CONNECTION='l2tp_2' PLUTO_NEXT_HOP='85.159.160.201' PLUTO_INTERFACE='ipsec0' PLUTO_ME='10.254.254.2' PLUTO_MY_ID='10.254.254.2' PLUTO_MY_CLIENT='10.254.254.2/32' PLUTO_MY_CLIENT_NET='10.254.254.2' PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701' PLUTO_MY_PROTOCOL='17' PLUTO_PEER='85.159.160.201' PLUTO_PEER_ID='@QB-R40' PLUTO_PEER_CLIENT='85.159.160.201/32' PLUTO_PEER_CLIENT_NET='85.159.160.201' PLUTO_PEER_CLIENT_MASK='255.255.255.255' PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA='' PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown Oct 29 20:05:47 fw pluto[25973]: | route_and_eroute: firewall_notified: true Oct 29 20:05:47 fw pluto[25973]: | command executing prepare-host Oct 29 20:05:47 fw pluto[25973]: | executing prepare-host: 2>&1 PLUTO_VERSION='1.1' PLUTO_VERB='prepare-host' PLUTO_CONNECTION='l2tp_2' PLUTO_NEXT_HOP='85.159.160.201' PLUTO_INTERFACE='ipsec0' PLUTO_ME='10.254.254.2' PLUTO_MY_ID='10.254.254.2' PLUTO_MY_CLIENT='10.254.254.2/32' PLUTO_MY_CLIENT_NET='10.254.254.2' PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701' PLUTO_MY_PROTOCOL='17' PLUTO_PEER='85.159.160.201' PLUTO_PEER_ID='@QB-R40' PLUTO_PEER_CLIENT='85.159.160.201/32' PLUTO_PEER_CLIENT_NET='85.159.160.201' PLUTO_PEER_CLIENT_MASK='255.255.255.255' PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA='' PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown Oct 29 20:05:47 fw pluto[25973]: | command executing route-host Oct 29 20:05:47 fw pluto[25973]: | executing route-host: 2>&1 PLUTO_VERSION='1.1' PLUTO_VERB='route-host' PLUTO_CONNECTION='l2tp_2' PLUTO_NEXT_HOP='85.159.160.201' PLUTO_INTERFACE='ipsec0' PLUTO_ME='10.254.254.2' PLUTO_MY_ID='10.254.254.2' PLUTO_MY_CLIENT='10.254.254.2/32' PLUTO_MY_CLIENT_NET='10.254.254.2' PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701' PLUTO_MY_PROTOCOL='17' PLUTO_PEER='85.159.160.201' PLUTO_PEER_ID='@QB-R40' PLUTO_PEER_CLIENT='85.159.160.201/32' PLUTO_PEER_CLIENT_NET='85.159.160.201' PLUTO_PEER_CLIENT_MASK='255.255.255.255' PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA='' PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown Oct 29 20:05:47 fw pluto[25973]: | route_and_eroute: instance "l2tp_2"[2] 85.159.160.201, setting eroute_owner {spd=0x978f9ec,sr=0x978f9ec} to #3 (was #0) (newest_ipsec_sa=#0) Oct 29 20:05:47 fw pluto[25973]: | complete state transition with STF_OK Oct 29 20:05:47 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #3: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2 Oct 29 20:05:47 fw pluto[25973]: | inserting event EVENT_SA_EXPIRE, timeout in 3600 seconds for #3 Oct 29 20:05:47 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #3: STATE_QUICK_R2: IPsec SA established {ESP=>0x94e0e5d2 <0x2a9483fd xfrm=3DES_0-HMAC_MD5 NATD=85.159.160.201:30510 DPD=none} Oct 29 20:05:47 fw pluto[25973]: | modecfg pull: noquirk policy:push not-client Oct 29 20:05:47 fw pluto[25973]: | phase 1 is done, looking for phase 1 to unpend Oct 29 20:05:47 fw pluto[25973]: | next event EVENT_RETRANSMIT in 3 seconds for #1 Oct 29 20:05:50 fw pluto[25973]: | Oct 29 20:05:50 fw pluto[25973]: | *time to handle event Oct 29 20:05:50 fw pluto[25973]: | handling event EVENT_RETRANSMIT Oct 29 20:05:50 fw pluto[25973]: | event after this is EVENT_NAT_T_KEEPALIVE in 13 seconds Oct 29 20:05:50 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:05:50 fw pluto[25973]: | handling event EVENT_RETRANSMIT for 85.159.160.201 "l2tp_2" #1 Oct 29 20:05:50 fw pluto[25973]: | sending 140 bytes for EVENT_RETRANSMIT through eth1:500 to 85.159.160.201:30510: Oct 29 20:05:50 fw pluto[25973]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #1 Oct 29 20:05:50 fw pluto[25973]: | next event EVENT_NAT_T_KEEPALIVE in 13 seconds Oct 29 20:06:03 fw pluto[25973]: | Oct 29 20:06:03 fw pluto[25973]: | *time to handle event Oct 29 20:06:03 fw pluto[25973]: | handling event EVENT_NAT_T_KEEPALIVE Oct 29 20:06:03 fw pluto[25973]: | event after this is EVENT_RETRANSMIT in 7 seconds Oct 29 20:06:03 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:06:03 fw last message repeated 2 times Oct 29 20:06:03 fw pluto[25973]: | sending 1 bytes for NAT-T Keep Alive through eth1:4500 to 85.159.160.201:30510: Oct 29 20:06:03 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:06:03 fw pluto[25973]: | inserting event EVENT_NAT_T_KEEPALIVE, timeout in 20 seconds Oct 29 20:06:03 fw pluto[25973]: | next event EVENT_RETRANSMIT in 7 seconds for #1 Oct 29 20:06:10 fw pluto[25973]: | Oct 29 20:06:10 fw pluto[25973]: | *time to handle event Oct 29 20:06:10 fw pluto[25973]: | handling event EVENT_RETRANSMIT Oct 29 20:06:10 fw pluto[25973]: | event after this is EVENT_NAT_T_KEEPALIVE in 13 seconds Oct 29 20:06:10 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:06:10 fw pluto[25973]: | handling event EVENT_RETRANSMIT for 85.159.160.201 "l2tp_2" #1 Oct 29 20:06:10 fw pluto[25973]: | sending 140 bytes for EVENT_RETRANSMIT through eth1:500 to 85.159.160.201:30510: Oct 29 20:06:10 fw pluto[25973]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #1 Oct 29 20:06:10 fw pluto[25973]: | next event EVENT_NAT_T_KEEPALIVE in 13 seconds Oct 29 20:06:22 fw pluto[25973]: | Oct 29 20:06:22 fw pluto[25973]: | *received 68 bytes from 85.159.160.201:30510 on eth1 (port=4500) Oct 29 20:06:22 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:06:22 fw pluto[25973]: | initiator cookie: Oct 29 20:06:22 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:06:22 fw pluto[25973]: | responder cookie: Oct 29 20:06:22 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:06:22 fw pluto[25973]: | next payload type: ISAKMP_NEXT_HASH Oct 29 20:06:22 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:06:22 fw pluto[25973]: | exchange type: ISAKMP_XCHG_INFO Oct 29 20:06:22 fw pluto[25973]: | flags: ISAKMP_FLAG_ENCRYPTION Oct 29 20:06:22 fw pluto[25973]: | message ID: 93 5d eb 71 Oct 29 20:06:22 fw pluto[25973]: | length: 68 Oct 29 20:06:22 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_INFO (5) Oct 29 20:06:22 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:06:22 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:06:22 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:06:22 fw pluto[25973]: | state hash entry 2 Oct 29 20:06:22 fw pluto[25973]: | peer and cookies match on #3, provided msgid 00000000 vs ec3d22d6/00000000 Oct 29 20:06:22 fw pluto[25973]: | peer and cookies match on #2, provided msgid 00000000 vs 00000000/00000000 Oct 29 20:06:22 fw pluto[25973]: | p15 state object #2 found, in STATE_MAIN_R3 Oct 29 20:06:22 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:06:22 fw pluto[25973]: | ***parse ISAKMP Hash Payload: Oct 29 20:06:22 fw pluto[25973]: | next payload type: ISAKMP_NEXT_D Oct 29 20:06:22 fw pluto[25973]: | length: 24 Oct 29 20:06:22 fw pluto[25973]: | ***parse ISAKMP Delete Payload: Oct 29 20:06:22 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:06:22 fw pluto[25973]: | length: 16 Oct 29 20:06:22 fw pluto[25973]: | DOI: ISAKMP_DOI_IPSEC Oct 29 20:06:22 fw pluto[25973]: | protocol ID: 3 Oct 29 20:06:22 fw pluto[25973]: | SPI size: 4 Oct 29 20:06:22 fw pluto[25973]: | number of SPIs: 1 Oct 29 20:06:22 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:06:22 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #2: received Delete SA(0x94e0e5d2) payload: deleting IPSEC State #3 Oct 29 20:06:22 fw pluto[25973]: | deleting state #3 Oct 29 20:06:22 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:06:22 fw pluto[25973]: | sending 68 bytes for delete notify through eth1:4500 to 85.159.160.201:30510: Oct 29 20:06:22 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:06:22 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:06:22 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:06:22 fw pluto[25973]: | state hash entry 2 Oct 29 20:06:22 fw pluto[25973]: | command executing down-host Oct 29 20:06:22 fw pluto[25973]: | executing down-host: 2>&1 PLUTO_VERSION='1.1' PLUTO_VERB='down-host' PLUTO_CONNECTION='l2tp_2' PLUTO_NEXT_HOP='85.159.160.201' PLUTO_INTERFACE='ipsec0' PLUTO_ME='10.254.254.2' PLUTO_MY_ID='10.254.254.2' PLUTO_MY_CLIENT='10.254.254.2/32' PLUTO_MY_CLIENT_NET='10.254.254.2' PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701' PLUTO_MY_PROTOCOL='17' PLUTO_PEER='85.159.160.201' PLUTO_PEER_ID='@QB-R40' PLUTO_PEER_CLIENT='85.159.160.201/32' PLUTO_PEER_CLIENT_NET='85.159.160.201' PLUTO_PEER_CLIENT_MASK='255.255.255.255' PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA='' PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown Oct 29 20:06:22 fw pluto[25973]: | eroute_connection delete eroute 10.254.254.2/32:1701 --17-> 85.159.160.201/32:1701 => int.0@0.0.0.0 (raw_eroute) Oct 29 20:06:22 fw pluto[25973]: | route owner of "l2tp_2"[2] 85.159.160.201 unrouted: NULL Oct 29 20:06:22 fw pluto[25973]: | command executing unroute-host Oct 29 20:06:22 fw pluto[25973]: | executing unroute-host: 2>&1 PLUTO_VERSION='1.1' PLUTO_VERB='unroute-host' PLUTO_CONNECTION='l2tp_2' PLUTO_NEXT_HOP='85.159.160.201' PLUTO_INTERFACE='ipsec0' PLUTO_ME='10.254.254.2' PLUTO_MY_ID='10.254.254.2' PLUTO_MY_CLIENT='10.254.254.2/32' PLUTO_MY_CLIENT_NET='10.254.254.2' PLUTO_MY_CLIENT_MASK='255.255.255.255' PLUTO_MY_PORT='1701' PLUTO_MY_PROTOCOL='17' PLUTO_PEER='85.159.160.201' PLUTO_PEER_ID='@QB-R40' PLUTO_PEER_CLIENT='85.159.160.201/32' PLUTO_PEER_CLIENT_NET='85.159.160.201' PLUTO_PEER_CLIENT_MASK='255.255.255.255' PLUTO_PEER_PORT='1701' PLUTO_PEER_PROTOCOL='17' PLUTO_PEER_CA='' PLUTO_CONN_POLICY='PSK+ENCRYPT+DONTREKEY' ipsec _updown Oct 29 20:06:22 fw pluto[25973]: | del: 94 e0 e5 d2 Oct 29 20:06:22 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #2: received and ignored informational message Oct 29 20:06:22 fw pluto[25973]: | complete state transition with STF_IGNORE Oct 29 20:06:22 fw pluto[25973]: | next event EVENT_NAT_T_KEEPALIVE in 1 seconds Oct 29 20:06:22 fw pluto[25973]: | Oct 29 20:06:22 fw pluto[25973]: | *received 84 bytes from 85.159.160.201:30510 on eth1 (port=4500) Oct 29 20:06:22 fw pluto[25973]: | **parse ISAKMP Message: Oct 29 20:06:22 fw pluto[25973]: | initiator cookie: Oct 29 20:06:22 fw pluto[25973]: | ba 36 79 9f cc cc 67 58 Oct 29 20:06:22 fw pluto[25973]: | responder cookie: Oct 29 20:06:22 fw pluto[25973]: | db 05 a3 8a 22 a0 2e 8d Oct 29 20:06:22 fw pluto[25973]: | next payload type: ISAKMP_NEXT_HASH Oct 29 20:06:22 fw pluto[25973]: | ISAKMP version: ISAKMP Version 1.0 Oct 29 20:06:22 fw pluto[25973]: | exchange type: ISAKMP_XCHG_INFO Oct 29 20:06:22 fw pluto[25973]: | flags: ISAKMP_FLAG_ENCRYPTION Oct 29 20:06:22 fw pluto[25973]: | message ID: c0 2d 8f 06 Oct 29 20:06:22 fw pluto[25973]: | length: 84 Oct 29 20:06:22 fw pluto[25973]: | processing packet with exchange type=ISAKMP_XCHG_INFO (5) Oct 29 20:06:22 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:06:22 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:06:22 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:06:22 fw pluto[25973]: | state hash entry 2 Oct 29 20:06:22 fw pluto[25973]: | peer and cookies match on #2, provided msgid 00000000 vs 00000000/00000000 Oct 29 20:06:22 fw pluto[25973]: | p15 state object #2 found, in STATE_MAIN_R3 Oct 29 20:06:22 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:06:22 fw pluto[25973]: | ***parse ISAKMP Hash Payload: Oct 29 20:06:22 fw pluto[25973]: | next payload type: ISAKMP_NEXT_D Oct 29 20:06:22 fw pluto[25973]: | length: 24 Oct 29 20:06:22 fw pluto[25973]: | ***parse ISAKMP Delete Payload: Oct 29 20:06:22 fw pluto[25973]: | next payload type: ISAKMP_NEXT_NONE Oct 29 20:06:22 fw pluto[25973]: | length: 28 Oct 29 20:06:22 fw pluto[25973]: | DOI: ISAKMP_DOI_IPSEC Oct 29 20:06:22 fw pluto[25973]: | protocol ID: 1 Oct 29 20:06:22 fw pluto[25973]: | SPI size: 16 Oct 29 20:06:22 fw pluto[25973]: | number of SPIs: 1 Oct 29 20:06:22 fw pluto[25973]: | removing 4 bytes of padding Oct 29 20:06:22 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:06:22 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:06:22 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:06:22 fw pluto[25973]: | state hash entry 2 Oct 29 20:06:22 fw pluto[25973]: | peer and cookies match on #2, provided msgid 00000000 vs 00000000 Oct 29 20:06:22 fw pluto[25973]: | state object #2 found, in STATE_MAIN_R3 Oct 29 20:06:22 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:06:22 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201 #2: received Delete SA payload: deleting ISAKMP State #2 Oct 29 20:06:22 fw pluto[25973]: | deleting state #2 Oct 29 20:06:22 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:06:22 fw pluto[25973]: | sending 84 bytes for delete notify through eth1:4500 to 85.159.160.201:30510: Oct 29 20:06:22 fw pluto[25973]: | ICOOKIE: ba 36 79 9f cc cc 67 58 Oct 29 20:06:22 fw pluto[25973]: | RCOOKIE: db 05 a3 8a 22 a0 2e 8d Oct 29 20:06:22 fw pluto[25973]: | peer: 55 9f a0 c9 Oct 29 20:06:22 fw pluto[25973]: | state hash entry 2 Oct 29 20:06:22 fw pluto[25973]: | processing connection l2tp_2[2] 85.159.160.201 Oct 29 20:06:22 fw pluto[25973]: "l2tp_2"[2] 85.159.160.201: deleting connection "l2tp_2" instance with peer 85.159.160.201 {isakmp=#0/ipsec=#0} Oct 29 20:06:22 fw pluto[25973]: | alg_info_delref(0x978a940) alg_info->ref_cnt=6 Oct 29 20:06:22 fw pluto[25973]: | del: ba 36 79 9f cc cc 67 58 db 05 a3 8a 22 a0 2e 8d Oct 29 20:06:22 fw pluto[25973]: packet from 85.159.160.201:30510: received and ignored informational message Oct 29 20:06:22 fw pluto[25973]: | complete state transition with STF_IGNORE Oct 29 20:06:22 fw pluto[25973]: | next event EVENT_NAT_T_KEEPALIVE in 1 seconds Oct 29 20:06:23 fw pluto[25973]: | Oct 29 20:06:23 fw pluto[25973]: | *time to handle event Oct 29 20:06:23 fw pluto[25973]: | handling event EVENT_NAT_T_KEEPALIVE Oct 29 20:06:23 fw pluto[25973]: | event after this is EVENT_RETRANSMIT in 27 seconds Oct 29 20:06:23 fw pluto[25973]: | processing connection l2tp_2[1] 85.159.160.201 Oct 29 20:06:23 fw pluto[25973]: | next event EVENT_RETRANSMIT in 27 seconds for #1