[Openswan Users] net-to-net with multiple subnets, unrouted

Tue Nov 23 14:58:00 EST 2010

On Tue, 23 Nov 2010, Paul Wouters wrote:

> On Tue, 23 Nov 2010, kallen at groknaut.net wrote:
>>
>>>> 2) why do 3 out of 4 of my "connections" show as "unrouted; eroute owner: #0"?
>>>>   and why does the linux gateway keep trying to, i think, negotiate add'l
>>>>   IPSEC SAs? and why do those attempts fail? is it a misconfig on my end, a
>>>>   misconfig on the Juniper end? or an interop problem?
>>>
>>> Can you show some more logs here?

had to run another test to lower the log level. log is at the end.

>> after using leftsourceip, keeping my hands off the routes, and firing
>> it up, i have a route to one of the two rightsubnets:
>>
>> 192.168.101.0   5.5.5.100       255.255.255.0   UG    0      0        0 eth1
>>
>> but how to get routes for all rightsubnets? probably is a symptom of the
>> problem in #2 above.
>
> Set leftsourceip= for all the connection you defined.

my config currently has has only one conn section within which is
rightsubnets. should i break out each rightsubnet into a conn section in
order to associate a leftsourceip with each?

current config:

version 2.0
config setup
        interfaces=%defaultroute
        plutodebug="control parsing"
        virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12,%v4:!10.8.13.0/24,%v4:!172.16.6.0/24
        protostack=netkey

conn bender
        type=tunnel
        left=5.5.5.22
        leftnexthop=5.5.5.100
        leftsourceip=10.8.13.18
        leftsubnets={172.16.6.0/24 10.8.13.0/24}
        right=6.6.6.3
        #rightnexthop=6.6.6.2
        rightsubnets={192.168.101.0/24 192.168.111.0/24}
        authby=secret
        auto=add
        pfs=no

Nov 23 11:37:06 linux-gw ipsec__plutorun: Starting Pluto subsystem...
Nov 23 11:37:06 linux-gw pluto[10356]: nss directory plutomain: /etc/ipsec.d
Nov 23 11:37:06 linux-gw pluto[10356]: NSS Initialized
Nov 23 11:37:06 linux-gw pluto[10356]: Non-fips mode set in /proc/sys/crypto/fips_enabled
Nov 23 11:37:06 linux-gw pluto[10356]: Starting Pluto (Openswan Version 2.6.31; Vendor ID OE}GnD\177ZAYe[) pid:10356
Nov 23 11:37:06 linux-gw pluto[10356]: Non-fips mode set in /proc/sys/crypto/fips_enabled
Nov 23 11:37:06 linux-gw pluto[10356]: LEAK_DETECTIVE support [enabled]
Nov 23 11:37:06 linux-gw pluto[10356]: SAref support [disabled]: Protocol not available
Nov 23 11:37:06 linux-gw pluto[10356]: SAbind support [disabled]: Protocol not available
Nov 23 11:37:06 linux-gw pluto[10356]: NSS support [enabled]
Nov 23 11:37:06 linux-gw pluto[10356]: HAVE_STATSD notification support not compiled in
Nov 23 11:37:06 linux-gw pluto[10356]: Setting NAT-Traversal port-4500 floating to off
Nov 23 11:37:06 linux-gw pluto[10356]:    port floating activation criteria nat_t=0/port_float=1
Nov 23 11:37:06 linux-gw pluto[10356]:    NAT-Traversal support  [disabled]
Nov 23 11:37:06 linux-gw pluto[10356]: | inserting event EVENT_REINIT_SECRET, timeout in 3600 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | inserting event EVENT_PENDING_DDNS, timeout in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating OAKLEY_TWOFISH_CBC_SSH: Ok (ret=0)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating OAKLEY_TWOFISH_CBC: Ok (ret=0)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating OAKLEY_SERPENT_CBC: Ok (ret=0)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating OAKLEY_AES_CBC: Ok (ret=0)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating OAKLEY_BLOWFISH_CBC: Ok (ret=0)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_hash(): Activating OAKLEY_SHA2_512: Ok (ret=0)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_hash(): Activating OAKLEY_SHA2_256: Ok (ret=0)
Nov 23 11:37:06 linux-gw pluto[10356]: starting up 3 cryptographic helpers
Nov 23 11:37:06 linux-gw pluto[10356]: started helper (thread) pid=1086437696 (fd:10)
Nov 23 11:37:06 linux-gw pluto[10356]: started helper (thread) pid=1096927552 (fd:12)
Nov 23 11:37:06 linux-gw pluto[10356]: started helper (thread) pid=1107417408 (fd:14)
Nov 23 11:37:06 linux-gw pluto[10356]: Using Linux 2.6 IPsec interface code on 2.6.18-194.el5 (experimental code)
Nov 23 11:37:06 linux-gw pluto[10356]: | status value returned by setting the priority of this thread (id=1) 22
Nov 23 11:37:06 linux-gw pluto[10356]: | helper 1 waiting on fd: 13
Nov 23 11:37:06 linux-gw pluto[10356]: | status value returned by setting the priority of this thread (id=0) 22
Nov 23 11:37:06 linux-gw pluto[10356]: | status value returned by setting the priority of this thread (id=2) 22
Nov 23 11:37:06 linux-gw pluto[10356]: | helper 0 waiting on fd: 11
Nov 23 11:37:06 linux-gw pluto[10356]: | helper 2 waiting on fd: 15
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating aes_ccm_8: Ok (ret=0)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_add(): ERROR: Algorithm already exists
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating aes_ccm_12: FAILED (ret=-17)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_add(): ERROR: Algorithm already exists
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating aes_ccm_16: FAILED (ret=-17)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_add(): ERROR: Algorithm already exists
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating aes_gcm_8: FAILED (ret=-17)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_add(): ERROR: Algorithm already exists
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating aes_gcm_12: FAILED (ret=-17)
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_add(): ERROR: Algorithm already exists
Nov 23 11:37:06 linux-gw pluto[10356]: ike_alg_register_enc(): Activating aes_gcm_16: FAILED (ret=-17)
Nov 23 11:37:06 linux-gw pluto[10356]: Could not change to directory '/etc/ipsec.d/cacerts': /
Nov 23 11:37:06 linux-gw pluto[10356]: Could not change to directory '/etc/ipsec.d/aacerts': /
Nov 23 11:37:06 linux-gw pluto[10356]: Could not change to directory '/etc/ipsec.d/ocspcerts': /
Nov 23 11:37:06 linux-gw pluto[10356]: Could not change to directory '/etc/ipsec.d/crls'
Nov 23 11:37:06 linux-gw pluto[10356]: | inserting event EVENT_LOG_DAILY, timeout in 44574 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | 
Nov 23 11:37:06 linux-gw pluto[10356]: | *received whack message
Nov 23 11:37:06 linux-gw pluto[10356]: | Added new connection bender/1x1 with policy PSK+ENCRYPT+TUNNEL+IKEv2ALLOW
Nov 23 11:37:06 linux-gw pluto[10356]: | counting wild cards for 5.5.5.22 is 0
Nov 23 11:37:06 linux-gw pluto[10356]: | counting wild cards for 6.6.6.3 is 0
Nov 23 11:37:06 linux-gw pluto[10356]: added connection description "bender/1x1"
Nov 23 11:37:06 linux-gw pluto[10356]: | 172.16.6.0/24===5.5.5.22<5.5.5.22>[+S=C]---5.5.5.100...6.6.6.3<6.6.6.3>[+S=C]===192.168.101.0/24
Nov 23 11:37:06 linux-gw pluto[10356]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy: PSK+ENCRYPT+TUNNEL+IKEv2ALLOW
Nov 23 11:37:06 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | 
Nov 23 11:37:06 linux-gw pluto[10356]: | *received whack message
Nov 23 11:37:06 linux-gw pluto[10356]: | Added new connection bender/1x2 with policy PSK+ENCRYPT+TUNNEL+IKEv2ALLOW
Nov 23 11:37:06 linux-gw pluto[10356]: | counting wild cards for 5.5.5.22 is 0
Nov 23 11:37:06 linux-gw pluto[10356]: | counting wild cards for 6.6.6.3 is 0
Nov 23 11:37:06 linux-gw pluto[10356]: added connection description "bender/1x2"
Nov 23 11:37:06 linux-gw pluto[10356]: | 172.16.6.0/24===5.5.5.22<5.5.5.22>[+S=C]---5.5.5.100...6.6.6.3<6.6.6.3>[+S=C]===192.168.111.0/24
Nov 23 11:37:06 linux-gw pluto[10356]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy: PSK+ENCRYPT+TUNNEL+IKEv2ALLOW
Nov 23 11:37:06 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | 
Nov 23 11:37:06 linux-gw pluto[10356]: | *received whack message
Nov 23 11:37:06 linux-gw pluto[10356]: | Added new connection bender/2x1 with policy PSK+ENCRYPT+TUNNEL+IKEv2ALLOW
Nov 23 11:37:06 linux-gw pluto[10356]: | counting wild cards for 5.5.5.22 is 0
Nov 23 11:37:06 linux-gw pluto[10356]: | counting wild cards for 6.6.6.3 is 0
Nov 23 11:37:06 linux-gw pluto[10356]: added connection description "bender/2x1"
Nov 23 11:37:06 linux-gw pluto[10356]: | 10.8.13.0/24===5.5.5.22<5.5.5.22>[+S=C]---5.5.5.100...6.6.6.3<6.6.6.3>[+S=C]===192.168.101.0/24
Nov 23 11:37:06 linux-gw pluto[10356]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy: PSK+ENCRYPT+TUNNEL+IKEv2ALLOW
Nov 23 11:37:06 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | 
Nov 23 11:37:06 linux-gw pluto[10356]: | *received whack message
Nov 23 11:37:06 linux-gw pluto[10356]: | Added new connection bender/2x2 with policy PSK+ENCRYPT+TUNNEL+IKEv2ALLOW
Nov 23 11:37:06 linux-gw pluto[10356]: | counting wild cards for 5.5.5.22 is 0
Nov 23 11:37:06 linux-gw pluto[10356]: | counting wild cards for 6.6.6.3 is 0
Nov 23 11:37:06 linux-gw pluto[10356]: added connection description "bender/2x2"
Nov 23 11:37:06 linux-gw pluto[10356]: | 10.8.13.0/24===5.5.5.22<5.5.5.22>[+S=C]---5.5.5.100...6.6.6.3<6.6.6.3>[+S=C]===192.168.111.0/24
Nov 23 11:37:06 linux-gw pluto[10356]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy: PSK+ENCRYPT+TUNNEL+IKEv2ALLOW
Nov 23 11:37:06 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | 
Nov 23 11:37:06 linux-gw pluto[10356]: | *received whack message
Nov 23 11:37:06 linux-gw pluto[10356]: listening for IKE messages
Nov 23 11:37:06 linux-gw pluto[10356]: | found lo with address 127.0.0.1
Nov 23 11:37:06 linux-gw pluto[10356]: | found eth0 with address 10.8.13.16
Nov 23 11:37:06 linux-gw pluto[10356]: | found eth0 with address 10.8.13.18
Nov 23 11:37:06 linux-gw pluto[10356]: | found eth1 with address 5.5.5.22
Nov 23 11:37:06 linux-gw pluto[10356]: | found tun0 with address 10.8.0.1
Nov 23 11:37:06 linux-gw pluto[10356]: | invalid listen= option ignored: empty string 
Nov 23 11:37:06 linux-gw pluto[10356]: | Only looking to listen on 0.0.0.0 
Nov 23 11:37:06 linux-gw pluto[10356]: adding interface tun0/tun0 10.8.0.1:500
Nov 23 11:37:06 linux-gw pluto[10356]: adding interface eth1/eth1 5.5.5.22:500
Nov 23 11:37:06 linux-gw pluto[10356]: adding interface eth0/eth0 10.8.13.18:500
Nov 23 11:37:06 linux-gw pluto[10356]: adding interface eth0/eth0 10.8.13.16:500
Nov 23 11:37:06 linux-gw pluto[10356]: adding interface lo/lo 127.0.0.1:500
Nov 23 11:37:06 linux-gw pluto[10356]: | found lo with address 0000:0000:0000:0000:0000:0000:0000:0001
Nov 23 11:37:06 linux-gw pluto[10356]: adding interface lo/lo ::1:500
Nov 23 11:37:06 linux-gw pluto[10356]: loading secrets from "/etc/ipsec.secrets"
Nov 23 11:37:06 linux-gw pluto[10356]: loading secrets from "/etc/ipsec.d/bender.secrets"
Nov 23 11:37:06 linux-gw pluto[10356]: | id type added to secret(0x2af973956618) PPK_PSK: 5.5.5.22
Nov 23 11:37:06 linux-gw pluto[10356]: | id type added to secret(0x2af973956618) PPK_PSK: 6.6.6.3
Nov 23 11:37:06 linux-gw pluto[10356]: | Processing PSK at line 1: passed
Nov 23 11:37:06 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 60 seconds
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | *received whack message
Nov 23 11:37:08 linux-gw pluto[10356]: initiating all conns with alias='bender' 
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:37:08 linux-gw pluto[10356]: | creating state object #1 at 0x2af973956868
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  00 00 00 00  00 00 00 00
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 5
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting state object #1 on chain 5
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | Queuing pending Quick Mode with 6.6.6.3 "bender/2x2"
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: initiating Main Mode
Nov 23 11:37:08 linux-gw pluto[10356]: | sending 492 bytes for main_outI1 through eth1:500 to 6.6.6.3:500 (using #1)
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x1
Nov 23 11:37:08 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:37:08 linux-gw pluto[10356]: | Queuing pending Quick Mode with 6.6.6.3 "bender/2x1"
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:37:08 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:37:08 linux-gw pluto[10356]: | Queuing pending Quick Mode with 6.6.6.3 "bender/1x2"
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:37:08 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:37:08 linux-gw pluto[10356]: | Queuing pending Quick Mode with 6.6.6.3 "bender/1x1"
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | *received 156 bytes from 6.6.6.3:500 on eth1 (port=500)
Nov 23 11:37:08 linux-gw pluto[10356]: | **parse ISAKMP Message:
Nov 23 11:37:08 linux-gw pluto[10356]: |    initiator cookie:
Nov 23 11:37:08 linux-gw pluto[10356]: |   e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: |    responder cookie:
Nov 23 11:37:08 linux-gw pluto[10356]: |   08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_SA
Nov 23 11:37:08 linux-gw pluto[10356]: |    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
Nov 23 11:37:08 linux-gw pluto[10356]: |    exchange type: ISAKMP_XCHG_IDPROT
Nov 23 11:37:08 linux-gw pluto[10356]: |    flags: none
Nov 23 11:37:08 linux-gw pluto[10356]: |    message ID:  00 00 00 00
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 156
Nov 23 11:37:08 linux-gw pluto[10356]: |  processing version=1.0 packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 state object not found
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  00 00 00 00  00 00 00 00
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 5
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 peer and cookies match on #1, provided msgid 00000000 vs 00000000
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 state object #1 found, in STATE_MAIN_I1
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x2(ISAKMP_NEXT_SA) needed: 0x2 opt: 0x2080
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Security Association Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_VID
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 52
Nov 23 11:37:08 linux-gw pluto[10356]: |    DOI: ISAKMP_DOI_IPSEC
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x2080
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Vendor ID Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_VID
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 32
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x2080
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Vendor ID Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_VID
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 20
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x2080
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Vendor ID Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 24
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: ignoring unknown Vendor ID payload [925414152942290b65aa6c4bf142b1f6e08a2bb11100000014060000]
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: received Vendor ID payload [Dead Peer Detection]
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: ignoring Vendor ID payload [HeartBeat Notify 386b0100]
Nov 23 11:37:08 linux-gw pluto[10356]: | ****parse IPsec DOI SIT:
Nov 23 11:37:08 linux-gw pluto[10356]: |    IPsec DOI SIT: SIT_IDENTITY_ONLY
Nov 23 11:37:08 linux-gw pluto[10356]: | ****parse ISAKMP Proposal Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 40
Nov 23 11:37:08 linux-gw pluto[10356]: |    proposal number: 1
Nov 23 11:37:08 linux-gw pluto[10356]: |    protocol ID: PROTO_ISAKMP
Nov 23 11:37:08 linux-gw pluto[10356]: |    SPI size: 0
Nov 23 11:37:08 linux-gw pluto[10356]: |    number of transforms: 1
Nov 23 11:37:08 linux-gw pluto[10356]: | *****parse ISAKMP Transform Payload (ISAKMP):
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 32
Nov 23 11:37:08 linux-gw pluto[10356]: |    transform number: 1
Nov 23 11:37:08 linux-gw pluto[10356]: |    transform ID: KEY_IKE
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP Oakley attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: OAKLEY_ENCRYPTION_ALGORITHM
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 5
Nov 23 11:37:08 linux-gw pluto[10356]: |    [5 is OAKLEY_3DES_CBC]
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP Oakley attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: OAKLEY_HASH_ALGORITHM
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 2
Nov 23 11:37:08 linux-gw pluto[10356]: |    [2 is OAKLEY_SHA1]
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP Oakley attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: OAKLEY_GROUP_DESCRIPTION
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 2
Nov 23 11:37:08 linux-gw pluto[10356]: |    [2 is OAKLEY_GROUP_MODP1024]
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP Oakley attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: OAKLEY_AUTHENTICATION_METHOD
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 1
Nov 23 11:37:08 linux-gw pluto[10356]: |    [1 is OAKLEY_PRESHARED_KEY]
Nov 23 11:37:08 linux-gw pluto[10356]: | started looking for secret for 5.5.5.22->6.6.6.3 of kind PPK_PSK
Nov 23 11:37:08 linux-gw pluto[10356]: | actually looking for secret for 5.5.5.22->6.6.6.3 of kind PPK_PSK
Nov 23 11:37:08 linux-gw pluto[10356]: | 1: compared key 6.6.6.3 to 5.5.5.22 / 6.6.6.3 -> 4
Nov 23 11:37:08 linux-gw pluto[10356]: | 2: compared key 5.5.5.22 to 5.5.5.22 / 6.6.6.3 -> 12
Nov 23 11:37:08 linux-gw pluto[10356]: | line 1: match=12 
Nov 23 11:37:08 linux-gw pluto[10356]: | best_match 0>12 best=0x2af973956618 (line=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | concluding with best_match=12 best=0x2af973956618 (lineno=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP Oakley attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: OAKLEY_LIFE_TYPE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 1
Nov 23 11:37:08 linux-gw pluto[10356]: |    [1 is OAKLEY_LIFE_SECONDS]
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP Oakley attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: OAKLEY_LIFE_DURATION
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 3600
Nov 23 11:37:08 linux-gw pluto[10356]: | Oakley Transform 1 accepted
Nov 23 11:37:08 linux-gw pluto[10356]: | 1: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
Nov 23 11:37:08 linux-gw pluto[10356]: | asking helper 1 to do build_kenonce op on seq: 1 (len=2776, pcw_work=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 1 read 2768+4/2776 bytes fd: 13
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 1 doing build_kenonce op id: 1
Nov 23 11:37:08 linux-gw pluto[10356]: | complete state transition with STF_SUSPEND
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 58 seconds
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 58 seconds
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 1 has finished work (cnt now 1)
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 1 replies to id: q#1
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  00 00 00 00  00 00 00 00
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 5
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting state object #1 on chain 14
Nov 23 11:37:08 linux-gw pluto[10356]: | complete state transition with STF_OK
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
Nov 23 11:37:08 linux-gw pluto[10356]: | sending reply packet to 6.6.6.3:500 (from port 500)
Nov 23 11:37:08 linux-gw pluto[10356]: | sending 180 bytes for STATE_MAIN_I1 through eth1:500 to 6.6.6.3:500 (using #1)
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: STATE_MAIN_I2: sent MI2, expecting MR2
Nov 23 11:37:08 linux-gw pluto[10356]: | modecfg pull: noquirk policy:push not-client
Nov 23 11:37:08 linux-gw pluto[10356]: | phase 1 is done, looking for phase 2 to unpend
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 1 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | *received 196 bytes from 6.6.6.3:500 on eth1 (port=500)
Nov 23 11:37:08 linux-gw pluto[10356]: | **parse ISAKMP Message:
Nov 23 11:37:08 linux-gw pluto[10356]: |    initiator cookie:
Nov 23 11:37:08 linux-gw pluto[10356]: |   e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: |    responder cookie:
Nov 23 11:37:08 linux-gw pluto[10356]: |   08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_KE
Nov 23 11:37:08 linux-gw pluto[10356]: |    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
Nov 23 11:37:08 linux-gw pluto[10356]: |    exchange type: ISAKMP_XCHG_IDPROT
Nov 23 11:37:08 linux-gw pluto[10356]: |    flags: none
Nov 23 11:37:08 linux-gw pluto[10356]: |    message ID:  00 00 00 00
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 196
Nov 23 11:37:08 linux-gw pluto[10356]: |  processing version=1.0 packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 peer and cookies match on #1, provided msgid 00000000 vs 00000000
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 state object #1 found, in STATE_MAIN_I2
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x10(ISAKMP_NEXT_KE) needed: 0x410 opt: 0x102080
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Key Exchange Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONCE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 132
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x400(ISAKMP_NEXT_NONCE) needed: 0x400 opt: 0x102080
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Nonce Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 36
Nov 23 11:37:08 linux-gw pluto[10356]: | started looking for secret for 5.5.5.22->6.6.6.3 of kind PPK_PSK
Nov 23 11:37:08 linux-gw pluto[10356]: | actually looking for secret for 5.5.5.22->6.6.6.3 of kind PPK_PSK
Nov 23 11:37:08 linux-gw pluto[10356]: | 1: compared key 6.6.6.3 to 5.5.5.22 / 6.6.6.3 -> 4
Nov 23 11:37:08 linux-gw pluto[10356]: | 2: compared key 5.5.5.22 to 5.5.5.22 / 6.6.6.3 -> 12
Nov 23 11:37:08 linux-gw pluto[10356]: | line 1: match=12 
Nov 23 11:37:08 linux-gw pluto[10356]: | best_match 0>12 best=0x2af973956618 (line=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | concluding with best_match=12 best=0x2af973956618 (lineno=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | parent1 type: 7 group: 2 len: 2776 
Nov 23 11:37:08 linux-gw pluto[10356]: | 2: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
Nov 23 11:37:08 linux-gw pluto[10356]: | asking helper 2 to do compute dh+iv op on seq: 2 (len=2776, pcw_work=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 2 read 2768+4/2776 bytes fd: 15
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 2 doing compute dh+iv op id: 2
Nov 23 11:37:08 linux-gw pluto[10356]: | complete state transition with STF_SUSPEND
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 58 seconds
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 58 seconds
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 2 has finished work (cnt now 1)
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 2 replies to id: q#2
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | thinking about whether to send my certificate:
Nov 23 11:37:08 linux-gw pluto[10356]: |   I have RSA key: OAKLEY_PRESHARED_KEY cert.type: CERT_NONE 
Nov 23 11:37:08 linux-gw pluto[10356]: |   sendcert: CERT_ALWAYSSEND and I did not get a certificate request 
Nov 23 11:37:08 linux-gw pluto[10356]: |   so do not send cert.
Nov 23 11:37:08 linux-gw pluto[10356]: | I did not send a certificate because digital signatures are not being used. (PSK)
Nov 23 11:37:08 linux-gw pluto[10356]: |  I am not sending a certificate request
Nov 23 11:37:08 linux-gw pluto[10356]: | complete state transition with STF_OK
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
Nov 23 11:37:08 linux-gw pluto[10356]: | sending reply packet to 6.6.6.3:500 (from port 500)
Nov 23 11:37:08 linux-gw pluto[10356]: | sending 68 bytes for STATE_MAIN_I2 through eth1:500 to 6.6.6.3:500 (using #1)
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: STATE_MAIN_I3: sent MI3, expecting MR3
Nov 23 11:37:08 linux-gw pluto[10356]: | modecfg pull: noquirk policy:push not-client
Nov 23 11:37:08 linux-gw pluto[10356]: | phase 1 is done, looking for phase 2 to unpend
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 1 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | *received 68 bytes from 6.6.6.3:500 on eth1 (port=500)
Nov 23 11:37:08 linux-gw pluto[10356]: | **parse ISAKMP Message:
Nov 23 11:37:08 linux-gw pluto[10356]: |    initiator cookie:
Nov 23 11:37:08 linux-gw pluto[10356]: |   e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: |    responder cookie:
Nov 23 11:37:08 linux-gw pluto[10356]: |   08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_ID
Nov 23 11:37:08 linux-gw pluto[10356]: |    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
Nov 23 11:37:08 linux-gw pluto[10356]: |    exchange type: ISAKMP_XCHG_IDPROT
Nov 23 11:37:08 linux-gw pluto[10356]: |    flags: ISAKMP_FLAG_ENCRYPTION
Nov 23 11:37:08 linux-gw pluto[10356]: |    message ID:  00 00 00 00
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 68
Nov 23 11:37:08 linux-gw pluto[10356]: |  processing version=1.0 packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 peer and cookies match on #1, provided msgid 00000000 vs 00000000
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 state object #1 found, in STATE_MAIN_I3
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x20(ISAKMP_NEXT_ID) needed: 0x120 opt: 0x2080
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Identification Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_HASH
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 12
Nov 23 11:37:08 linux-gw pluto[10356]: |    ID type: ID_IPV4_ADDR
Nov 23 11:37:08 linux-gw pluto[10356]: |    DOI specific A: 17
Nov 23 11:37:08 linux-gw pluto[10356]: |    DOI specific B: 500
Nov 23 11:37:08 linux-gw pluto[10356]: |      obj:   40 7d 8f 03  00 00 00 18  3d 83 03 60
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x100(ISAKMP_NEXT_HASH) needed: 0x100 opt: 0x2080
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Hash Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 24
Nov 23 11:37:08 linux-gw pluto[10356]: | removing 4 bytes of padding
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: Main mode peer ID is ID_IPV4_ADDR: '6.6.6.3'
Nov 23 11:37:08 linux-gw pluto[10356]: | complete state transition with STF_OK
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_SA_REPLACE, timeout in 2607 seconds for #1
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1024}
Nov 23 11:37:08 linux-gw pluto[10356]: | modecfg pull: noquirk policy:push not-client
Nov 23 11:37:08 linux-gw pluto[10356]: | phase 1 is done, looking for phase 2 to unpend
Nov 23 11:37:08 linux-gw pluto[10356]: | unqueuing pending Quick Mode with 6.6.6.3 "bender/1x1" import:admin initiate
Nov 23 11:37:08 linux-gw pluto[10356]: | duplicating state object #1
Nov 23 11:37:08 linux-gw pluto[10356]: | creating state object #2 at 0x2af97395eba8
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting state object #2 on chain 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #2
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/1x1" #2: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW {using isakmp#1 msgid:71366cc3 proposal=defaults pfsgroup=no-pfs}
Nov 23 11:37:08 linux-gw pluto[10356]: | 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
Nov 23 11:37:08 linux-gw pluto[10356]: | asking helper 0 to do build_nonce op on seq: 3 (len=2776, pcw_work=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #2
Nov 23 11:37:08 linux-gw pluto[10356]: | unqueuing pending Quick Mode with 6.6.6.3 "bender/1x2" import:admin initiate
Nov 23 11:37:08 linux-gw pluto[10356]: | duplicating state object #1
Nov 23 11:37:08 linux-gw pluto[10356]: | creating state object #3 at 0x2af97395f358
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 0 read 2768+4/2776 bytes fd: 11
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 0 doing build_nonce op id: 3
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting state object #3 on chain 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #3
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/1x2" #3: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW {using isakmp#1 msgid:dab8f02c proposal=defaults pfsgroup=no-pfs}
Nov 23 11:37:08 linux-gw pluto[10356]: | 1: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
Nov 23 11:37:08 linux-gw pluto[10356]: | asking helper 1 to do build_nonce op on seq: 4 (len=2776, pcw_work=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 1 read 2768+4/2776 bytes fd: 13
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #3
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 1 doing build_nonce op id: 4
Nov 23 11:37:08 linux-gw pluto[10356]: | unqueuing pending Quick Mode with 6.6.6.3 "bender/2x1" import:admin initiate
Nov 23 11:37:08 linux-gw pluto[10356]: | duplicating state object #1
Nov 23 11:37:08 linux-gw pluto[10356]: | creating state object #4 at 0x2af97395fec8
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x1
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting state object #4 on chain 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #4
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x1" #4: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW {using isakmp#1 msgid:c34d7844 proposal=defaults pfsgroup=no-pfs}
Nov 23 11:37:08 linux-gw pluto[10356]: | 2: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
Nov 23 11:37:08 linux-gw pluto[10356]: | asking helper 2 to do build_nonce op on seq: 5 (len=2776, pcw_work=1)
Nov 23 11:37:08 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 2 read 2768+4/2776 bytes fd: 15
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #4
Nov 23 11:37:08 linux-gw pluto[10356]: | unqueuing pending Quick Mode with 6.6.6.3 "bender/2x2" import:admin initiate
Nov 23 11:37:08 linux-gw pluto[10356]: | duplicating state object #1
Nov 23 11:37:08 linux-gw pluto[10356]: | creating state object #5 at 0x2af9739609e8
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 2 doing build_nonce op id: 5
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting state object #5 on chain 14
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #5
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x2" #5: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW {using isakmp#1 msgid:83300565 proposal=defaults pfsgroup=no-pfs}
Nov 23 11:37:08 linux-gw pluto[10356]: | 0: w->pcw_dead: 0 w->pcw_work: 1 cnt: 3
Nov 23 11:37:08 linux-gw pluto[10356]: | asking helper 0 to do build_nonce op on seq: 6 (len=2776, pcw_work=2)
Nov 23 11:37:08 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 0 read 2768+4/2776 bytes fd: 11
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 0 doing build_nonce op id: 6
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #5
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 58 seconds
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 58 seconds
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 0 has finished work (cnt now 2)
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 0 replies to id: q#3
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:37:08 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:37:08 linux-gw pluto[10356]: | sending 236 bytes for quick_outI1 through eth1:500 to 6.6.6.3:500 (using #2)
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #2
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 1 has finished work (cnt now 1)
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 1 replies to id: q#4
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:37:08 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:37:08 linux-gw pluto[10356]: | sending 236 bytes for quick_outI1 through eth1:500 to 6.6.6.3:500 (using #3)
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #3
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 2 has finished work (cnt now 1)
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 2 replies to id: q#5
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x1
Nov 23 11:37:08 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:37:08 linux-gw pluto[10356]: | sending 236 bytes for quick_outI1 through eth1:500 to 6.6.6.3:500 (using #4)
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #4
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 3 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #4
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #4
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 0 has finished work (cnt now 1)
Nov 23 11:37:08 linux-gw pluto[10356]: | helper 0 replies to id: q#6
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:08 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:37:08 linux-gw pluto[10356]: | sending 236 bytes for quick_outI1 through eth1:500 to 6.6.6.3:500 (using #5)
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #5
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 1 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #5
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #5
Nov 23 11:37:08 linux-gw pluto[10356]: | 
Nov 23 11:37:08 linux-gw pluto[10356]: | *received 204 bytes from 6.6.6.3:500 on eth1 (port=500)
Nov 23 11:37:08 linux-gw pluto[10356]: | **parse ISAKMP Message:
Nov 23 11:37:08 linux-gw pluto[10356]: |    initiator cookie:
Nov 23 11:37:08 linux-gw pluto[10356]: |   e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: |    responder cookie:
Nov 23 11:37:08 linux-gw pluto[10356]: |   08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_HASH
Nov 23 11:37:08 linux-gw pluto[10356]: |    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
Nov 23 11:37:08 linux-gw pluto[10356]: |    exchange type: ISAKMP_XCHG_QUICK
Nov 23 11:37:08 linux-gw pluto[10356]: |    flags: ISAKMP_FLAG_ENCRYPTION
Nov 23 11:37:08 linux-gw pluto[10356]: |    message ID:  44 78 4d c3
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 204
Nov 23 11:37:08 linux-gw pluto[10356]: |  processing version=1.0 packet with exchange type=ISAKMP_XCHG_QUICK (32)
Nov 23 11:37:08 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:37:08 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:37:08 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 peer and cookies match on #5, provided msgid 44784dc3 vs 65053083
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 peer and cookies match on #4, provided msgid 44784dc3 vs 44784dc3
Nov 23 11:37:08 linux-gw pluto[10356]: | v1 state object #4 found, in STATE_QUICK_I1
Nov 23 11:37:08 linux-gw pluto[10356]: | processing connection bender/2x1
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x100(ISAKMP_NEXT_HASH) needed: 0x502 opt: 0x200030
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Hash Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_SA
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 24
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x2(ISAKMP_NEXT_SA) needed: 0x402 opt: 0x200030
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Security Association Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONCE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 52
Nov 23 11:37:08 linux-gw pluto[10356]: |    DOI: ISAKMP_DOI_IPSEC
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x400(ISAKMP_NEXT_NONCE) needed: 0x400 opt: 0x200030
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Nonce Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_ID
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 36
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x20(ISAKMP_NEXT_ID) needed: 0x0 opt: 0x200030
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Identification Payload (IPsec DOI):
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_ID
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 16
Nov 23 11:37:08 linux-gw pluto[10356]: |    ID type: ID_IPV4_ADDR_SUBNET
Nov 23 11:37:08 linux-gw pluto[10356]: |    Protocol ID: 0
Nov 23 11:37:08 linux-gw pluto[10356]: |    port: 0
Nov 23 11:37:08 linux-gw pluto[10356]: |      obj:   0a 08 0d 00  ff ff ff 00  0b 00 00 10  04 00 00 00
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x20(ISAKMP_NEXT_ID) needed: 0x0 opt: 0x200030
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Identification Payload (IPsec DOI):
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_N
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 16
Nov 23 11:37:08 linux-gw pluto[10356]: |    ID type: ID_IPV4_ADDR_SUBNET
Nov 23 11:37:08 linux-gw pluto[10356]: |    Protocol ID: 0
Nov 23 11:37:08 linux-gw pluto[10356]: |    port: 0
Nov 23 11:37:08 linux-gw pluto[10356]: |      obj:   c0 a8 65 00  ff ff ff 00  00 00 00 1c  00 00 00 01
Nov 23 11:37:08 linux-gw pluto[10356]: | got payload 0x800(ISAKMP_NEXT_N) needed: 0x0 opt: 0x200030
Nov 23 11:37:08 linux-gw pluto[10356]: | ***parse ISAKMP Notification Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 28
Nov 23 11:37:08 linux-gw pluto[10356]: |    DOI: ISAKMP_DOI_IPSEC
Nov 23 11:37:08 linux-gw pluto[10356]: |    protocol ID: 3
Nov 23 11:37:08 linux-gw pluto[10356]: |    SPI size: 4
Nov 23 11:37:08 linux-gw pluto[10356]: |    Notify Message Type: IPSEC_RESPONDER_LIFETIME
Nov 23 11:37:08 linux-gw pluto[10356]: | removing 4 bytes of padding
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x1" #4: ignoring informational payload, type IPSEC_RESPONDER_LIFETIME msgid=c34d7844
Nov 23 11:37:08 linux-gw pluto[10356]: | info:  ff 2e 2b 20  80 01 00 01  00 02 00 04  00 00 0e 10
Nov 23 11:37:08 linux-gw pluto[10356]: | ****parse IPsec DOI SIT:
Nov 23 11:37:08 linux-gw pluto[10356]: |    IPsec DOI SIT: SIT_IDENTITY_ONLY
Nov 23 11:37:08 linux-gw pluto[10356]: | ****parse ISAKMP Proposal Payload:
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 40
Nov 23 11:37:08 linux-gw pluto[10356]: |    proposal number: 1
Nov 23 11:37:08 linux-gw pluto[10356]: |    protocol ID: PROTO_IPSEC_ESP
Nov 23 11:37:08 linux-gw pluto[10356]: |    SPI size: 4
Nov 23 11:37:08 linux-gw pluto[10356]: |    number of transforms: 1
Nov 23 11:37:08 linux-gw pluto[10356]: | parsing 4 raw bytes of ISAKMP Proposal Payload into SPI
Nov 23 11:37:08 linux-gw pluto[10356]: | SPI  ff 2e 2b 20
Nov 23 11:37:08 linux-gw pluto[10356]: | *****parse ISAKMP Transform Payload (ESP):
Nov 23 11:37:08 linux-gw pluto[10356]: |    next payload type: ISAKMP_NEXT_NONE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length: 28
Nov 23 11:37:08 linux-gw pluto[10356]: |    transform number: 1
Nov 23 11:37:08 linux-gw pluto[10356]: |    transform ID: ESP_3DES
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP IPsec DOI attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: SA_LIFE_TYPE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 1
Nov 23 11:37:08 linux-gw pluto[10356]: |    [1 is SA_LIFE_TYPE_SECONDS]
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP IPsec DOI attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: SA_LIFE_DURATION (variable length)
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 4
Nov 23 11:37:08 linux-gw pluto[10356]: |    long duration: 28800
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP IPsec DOI attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: ENCAPSULATION_MODE
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 1
Nov 23 11:37:08 linux-gw pluto[10356]: |    [1 is ENCAPSULATION_MODE_TUNNEL]
Nov 23 11:37:08 linux-gw pluto[10356]: | ******parse ISAKMP IPsec DOI attribute:
Nov 23 11:37:08 linux-gw pluto[10356]: |    af+type: AUTH_ALGORITHM
Nov 23 11:37:08 linux-gw pluto[10356]: |    length/value: 2
Nov 23 11:37:08 linux-gw pluto[10356]: |    [2 is AUTH_ALGORITHM_HMAC_SHA1]
Nov 23 11:37:08 linux-gw pluto[10356]: | our client is subnet 10.8.13.0/24
Nov 23 11:37:08 linux-gw pluto[10356]: | our client protocol/port is 0/0
Nov 23 11:37:08 linux-gw pluto[10356]: | peer client is subnet 192.168.101.0/24
Nov 23 11:37:08 linux-gw pluto[10356]: | peer client protocol/port is 0/0
Nov 23 11:37:08 linux-gw pluto[10356]: | compute_proto_keymat:needed_len (after ESP enc)=24
Nov 23 11:37:08 linux-gw pluto[10356]: | compute_proto_keymat:needed_len (after ESP auth)=44
Nov 23 11:37:08 linux-gw pluto[10356]: | install_ipsec_sa() for #4: inbound and outbound
Nov 23 11:37:08 linux-gw pluto[10356]: | route owner of "bender/2x1" unrouted: NULL; eroute owner: NULL
Nov 23 11:37:08 linux-gw pluto[10356]: | could_route called for bender/2x1 (kind=CK_PERMANENT)
Nov 23 11:37:08 linux-gw pluto[10356]: | add inbound eroute 192.168.101.0/24:0 --0-> 10.8.13.0/24:0 => tun.10000 at 5.5.5.22 (raw_eroute)
Nov 23 11:37:08 linux-gw pluto[10356]: | raw_eroute result=1 
Nov 23 11:37:08 linux-gw pluto[10356]: | sr for #4: unrouted
Nov 23 11:37:08 linux-gw pluto[10356]: | route owner of "bender/2x1" unrouted: NULL; eroute owner: NULL
Nov 23 11:37:08 linux-gw pluto[10356]: | eroute_connection add eroute 10.8.13.0/24:0 --0-> 192.168.101.0/24:0 => tun.0 at 6.6.6.3 (raw_eroute)
Nov 23 11:37:08 linux-gw pluto[10356]: | raw_eroute result=1 
Nov 23 11:37:08 linux-gw pluto[10356]: | command executing up-client
Nov 23 11:37:08 linux-gw pluto[10356]: | executing up-client: 2>&1 PLUTO_VERB='up-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1' PLUTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' PLUTO_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10.8.13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT='192.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW' PLUTO_XAUTH_USERNAME='' PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOMAIN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown
Nov 23 11:37:08 linux-gw pluto[10356]: | popen(): cmd is 766 chars long
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd(   0):2>&1 PLUTO_VERB='up-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1' PLUT:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd(  80):O_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' PLUTO_:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 160):MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10.8.13:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 240):.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0':
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 320): PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT='192.1:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 400):68.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK='255.2:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 480):55.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STA:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 560):CK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW' PLUTO_XAUTH_US:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 640):ERNAME='' PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOM:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 720):AIN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown:
Nov 23 11:37:08 linux-gw pluto[10356]: | route_and_eroute: firewall_notified: true
Nov 23 11:37:08 linux-gw pluto[10356]: | command executing prepare-client
Nov 23 11:37:08 linux-gw pluto[10356]: | executing prepare-client: 2>&1 PLUTO_VERB='prepare-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1' PLUTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' PLUTO_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10.8.13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT='192.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW' PLUTO_XAUTH_USERNAME='' PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOMAIN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown
Nov 23 11:37:08 linux-gw pluto[10356]: | popen(): cmd is 771 chars long
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd(   0):2>&1 PLUTO_VERB='prepare-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1':
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd(  80): PLUTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' P:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 160):LUTO_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 240):.8.13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCO:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 320):L='0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT=':
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 400):192.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK=':
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 480):255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUT:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 560):O_STACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW' PLUTO_XAU:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 640):TH_USERNAME='' PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISC:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 720):O_DOMAIN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown:
Nov 23 11:37:08 linux-gw pluto[10356]: | command executing route-client
Nov 23 11:37:08 linux-gw pluto[10356]: | executing route-client: 2>&1 PLUTO_VERB='route-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1' PLUTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' PLUTO_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10.8.13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT='192.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW' PLUTO_XAUTH_USERNAME='' PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOMAIN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown
Nov 23 11:37:08 linux-gw pluto[10356]: | popen(): cmd is 769 chars long
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd(   0):2>&1 PLUTO_VERB='route-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1' P:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd(  80):LUTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' PLU:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 160):TO_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10.8:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 240):.13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL=:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 320):'0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT='19:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 400):2.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK='25:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 480):5.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 560):STACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW' PLUTO_XAUTH:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 640):_USERNAME='' PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_:
Nov 23 11:37:08 linux-gw pluto[10356]: | cmd( 720):DOMAIN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown:
Nov 23 11:37:08 linux-gw pluto[10356]: | route_and_eroute: instance "bender/2x1", setting eroute_owner {spd=0x2af973950590,sr=0x2af973950590} to #4 (was #0) (newest_ipsec_sa=#0)
Nov 23 11:37:08 linux-gw pluto[10356]: | complete state transition with STF_OK
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x1" #4: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
Nov 23 11:37:08 linux-gw pluto[10356]: | sending reply packet to 6.6.6.3:500 (from port 500)
Nov 23 11:37:08 linux-gw pluto[10356]: | sending 52 bytes for STATE_QUICK_I1 through eth1:500 to 6.6.6.3:500 (using #4)
Nov 23 11:37:08 linux-gw pluto[10356]: | inserting event EVENT_SA_REPLACE, timeout in 28048 seconds for #4
Nov 23 11:37:08 linux-gw pluto[10356]: "bender/2x1" #4: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP=>0xff2e2b20 <0xaa358100 xfrm=3DES_0-HMAC_SHA1 NATOA=none NATD=none DPD=none}
Nov 23 11:37:08 linux-gw pluto[10356]: | modecfg pull: noquirk policy:push not-client
Nov 23 11:37:08 linux-gw pluto[10356]: | phase 1 is done, looking for phase 2 to unpend
Nov 23 11:37:08 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #5
Nov 23 11:37:08 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #5
Nov 23 11:37:18 linux-gw pluto[10356]: | 
Nov 23 11:37:18 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 0 seconds for #5
Nov 23 11:37:18 linux-gw pluto[10356]: | *time to handle event
Nov 23 11:37:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:37:18 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:37:18 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/2x2" #5
Nov 23 11:37:18 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #5)
Nov 23 11:37:18 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #5
Nov 23 11:37:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:37:18 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:37:18 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:37:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x2" #3
Nov 23 11:37:18 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #3)
Nov 23 11:37:18 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #3
Nov 23 11:37:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:37:18 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 20 seconds
Nov 23 11:37:18 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:37:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x1" #2
Nov 23 11:37:18 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #2)
Nov 23 11:37:18 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #2
Nov 23 11:37:18 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 20 seconds for #2
Nov 23 11:37:38 linux-gw pluto[10356]: | 
Nov 23 11:37:38 linux-gw pluto[10356]: | *received kernel message
Nov 23 11:37:38 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:38 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 0 seconds for #2
Nov 23 11:37:38 linux-gw pluto[10356]: | *time to handle event
Nov 23 11:37:38 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:37:38 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:37:38 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:37:38 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x1" #2
Nov 23 11:37:38 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #2)
Nov 23 11:37:38 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #2
Nov 23 11:37:38 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:37:38 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:37:38 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:37:38 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x2" #3
Nov 23 11:37:38 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #3)
Nov 23 11:37:38 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #3
Nov 23 11:37:38 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:37:38 linux-gw pluto[10356]: | event after this is EVENT_PENDING_DDNS in 28 seconds
Nov 23 11:37:38 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:37:38 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/2x2" #5
Nov 23 11:37:38 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #5)
Nov 23 11:37:38 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #5
Nov 23 11:37:38 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 28 seconds
Nov 23 11:37:38 linux-gw pluto[10356]: | 
Nov 23 11:37:38 linux-gw pluto[10356]: | *received kernel message
Nov 23 11:37:38 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:37:38 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 28 seconds
Nov 23 11:37:38 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 28 seconds
Nov 23 11:38:06 linux-gw pluto[10356]: | 
Nov 23 11:38:06 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 0 seconds
Nov 23 11:38:06 linux-gw pluto[10356]: | *time to handle event
Nov 23 11:38:06 linux-gw pluto[10356]: | handling event EVENT_PENDING_DDNS
Nov 23 11:38:06 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 12 seconds
Nov 23 11:38:06 linux-gw pluto[10356]: | inserting event EVENT_PENDING_DDNS, timeout in 60 seconds
Nov 23 11:38:06 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 12 seconds for #5
Nov 23 11:38:18 linux-gw pluto[10356]: | 
Nov 23 11:38:18 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 0 seconds for #5
Nov 23 11:38:18 linux-gw pluto[10356]: | *time to handle event
Nov 23 11:38:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:18 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/2x2" #5
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/2x2" #5: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/2x2" #5: starting keying attempt 2 of an unlimited number, but releasing whack
Nov 23 11:38:18 linux-gw pluto[10356]: | duplicating state object #1
Nov 23 11:38:18 linux-gw pluto[10356]: | creating state object #6 at 0x2af973961988
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:18 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:38:18 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:38:18 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting state object #6 on chain 14
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #6
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/2x2" #6: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW to replace #5 {using isakmp#1 msgid:d3d5f909 proposal=defaults pfsgroup=no-pfs}
Nov 23 11:38:18 linux-gw pluto[10356]: | 1: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
Nov 23 11:38:18 linux-gw pluto[10356]: | asking helper 1 to do build_nonce op on seq: 7 (len=2776, pcw_work=1)
Nov 23 11:38:18 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #6
Nov 23 11:38:18 linux-gw pluto[10356]: | deleting state #5
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 1 read 2768+4/2776 bytes fd: 13
Nov 23 11:38:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 1 doing build_nonce op id: 7
Nov 23 11:38:18 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:38:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x2" #3
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/1x2" #3: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/1x2" #3: starting keying attempt 2 of an unlimited number, but releasing whack
Nov 23 11:38:18 linux-gw pluto[10356]: | duplicating state object #1
Nov 23 11:38:18 linux-gw pluto[10356]: | creating state object #7 at 0x2af9739609c8
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:38:18 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:38:18 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:38:18 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting state object #7 on chain 14
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #7
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/1x2" #7: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW to replace #3 {using isakmp#1 msgid:2f65fd52 proposal=defaults pfsgroup=no-pfs}
Nov 23 11:38:18 linux-gw pluto[10356]: | 2: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
Nov 23 11:38:18 linux-gw pluto[10356]: | asking helper 2 to do build_nonce op on seq: 8 (len=2776, pcw_work=1)
Nov 23 11:38:18 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #7
Nov 23 11:38:18 linux-gw pluto[10356]: | deleting state #3
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 2 read 2768+4/2776 bytes fd: 15
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 2 doing build_nonce op id: 8
Nov 23 11:38:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:18 linux-gw pluto[10356]: | event after this is EVENT_PENDING_DDNS in 48 seconds
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:38:18 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x1" #2
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/1x1" #2: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/1x1" #2: starting keying attempt 2 of an unlimited number, but releasing whack
Nov 23 11:38:18 linux-gw pluto[10356]: | duplicating state object #1
Nov 23 11:38:18 linux-gw pluto[10356]: | creating state object #8 at 0x2af97395f358
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:38:18 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:38:18 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:38:18 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting state object #8 on chain 14
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #8
Nov 23 11:38:18 linux-gw pluto[10356]: "bender/1x1" #8: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW to replace #2 {using isakmp#1 msgid:df7a1201 proposal=defaults pfsgroup=no-pfs}
Nov 23 11:38:18 linux-gw pluto[10356]: | 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
Nov 23 11:38:18 linux-gw pluto[10356]: | asking helper 0 to do build_nonce op on seq: 9 (len=2776, pcw_work=1)
Nov 23 11:38:18 linux-gw pluto[10356]: | crypto helper write of request: cnt=2776<wlen=2776.  
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #8
Nov 23 11:38:18 linux-gw pluto[10356]: | deleting state #2
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 0 read 2768+4/2776 bytes fd: 11
Nov 23 11:38:18 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 48 seconds
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 0 doing build_nonce op id: 9
Nov 23 11:38:18 linux-gw pluto[10356]: | 
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 1 has finished work (cnt now 1)
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 1 replies to id: q#7
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:18 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:38:18 linux-gw pluto[10356]: | sending 236 bytes for quick_outI1 through eth1:500 to 6.6.6.3:500 (using #6)
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #6
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 2 has finished work (cnt now 1)
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 2 replies to id: q#8
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:38:18 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:38:18 linux-gw pluto[10356]: | sending 236 bytes for quick_outI1 through eth1:500 to 6.6.6.3:500 (using #7)
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #7
Nov 23 11:38:18 linux-gw pluto[10356]: | * processed 2 messages from cryptographic helpers 
Nov 23 11:38:18 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #7
Nov 23 11:38:18 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #7
Nov 23 11:38:18 linux-gw pluto[10356]: | 
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 0 has finished work (cnt now 1)
Nov 23 11:38:18 linux-gw pluto[10356]: | helper 0 replies to id: q#9
Nov 23 11:38:18 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:38:18 linux-gw pluto[10356]: | empty esp_info, returning defaults
Nov 23 11:38:18 linux-gw pluto[10356]: | sending 236 bytes for quick_outI1 through eth1:500 to 6.6.6.3:500 (using #8)
Nov 23 11:38:18 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #8
Nov 23 11:38:18 linux-gw pluto[10356]: | * processed 1 messages from cryptographic helpers 
Nov 23 11:38:18 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #8
Nov 23 11:38:18 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 10 seconds for #8
Nov 23 11:38:22 linux-gw pluto[10356]: | 
Nov 23 11:38:22 linux-gw pluto[10356]: | *received whack message
Nov 23 11:38:22 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:38:22 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 6 seconds for #8
Nov 23 11:38:22 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 6 seconds for #8
Nov 23 11:38:28 linux-gw pluto[10356]: | 
Nov 23 11:38:28 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 0 seconds for #8
Nov 23 11:38:28 linux-gw pluto[10356]: | *time to handle event
Nov 23 11:38:28 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:28 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:38:28 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:38:28 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x1" #8
Nov 23 11:38:28 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #8)
Nov 23 11:38:28 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #8
Nov 23 11:38:28 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:28 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:38:28 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:38:28 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x2" #7
Nov 23 11:38:28 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #7)
Nov 23 11:38:28 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #7
Nov 23 11:38:28 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:28 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 20 seconds
Nov 23 11:38:28 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:28 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/2x2" #6
Nov 23 11:38:28 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #6)
Nov 23 11:38:28 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #6
Nov 23 11:38:28 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 20 seconds for #6
Nov 23 11:38:48 linux-gw pluto[10356]: | 
Nov 23 11:38:48 linux-gw pluto[10356]: | next event EVENT_RETRANSMIT in 0 seconds for #6
Nov 23 11:38:48 linux-gw pluto[10356]: | *time to handle event
Nov 23 11:38:48 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:48 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:48 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/2x2" #6
Nov 23 11:38:48 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #6)
Nov 23 11:38:48 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #6
Nov 23 11:38:48 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:48 linux-gw pluto[10356]: | event after this is EVENT_RETRANSMIT in 0 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:38:48 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x2" #7
Nov 23 11:38:48 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #7)
Nov 23 11:38:48 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #7
Nov 23 11:38:48 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT
Nov 23 11:38:48 linux-gw pluto[10356]: | event after this is EVENT_PENDING_DDNS in 18 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:38:48 linux-gw pluto[10356]: | handling event EVENT_RETRANSMIT for 6.6.6.3 "bender/1x1" #8
Nov 23 11:38:48 linux-gw pluto[10356]: | sending 236 bytes for EVENT_RETRANSMIT through eth1:500 to 6.6.6.3:500 (using #8)
Nov 23 11:38:48 linux-gw pluto[10356]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #8
Nov 23 11:38:48 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 18 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | 
Nov 23 11:38:48 linux-gw pluto[10356]: | *received kernel message
Nov 23 11:38:48 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:38:48 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 18 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 18 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | 
Nov 23 11:38:48 linux-gw pluto[10356]: | *received kernel message
Nov 23 11:38:48 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:38:48 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 18 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 18 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | 
Nov 23 11:38:48 linux-gw pluto[10356]: | *received kernel message
Nov 23 11:38:48 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:38:48 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 18 seconds
Nov 23 11:38:48 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 18 seconds
Nov 23 11:38:54 linux-gw pluto[10356]: | 
Nov 23 11:38:54 linux-gw pluto[10356]: | *received whack message
Nov 23 11:38:54 linux-gw pluto[10356]: terminating all conns with alias='bender' 
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/2x2": terminating SAs using this connection
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/2x2" #6: deleting state (STATE_QUICK_I1)
Nov 23 11:38:54 linux-gw pluto[10356]: | deleting state #6
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/2x2" #1: deleting state (STATE_MAIN_I4)
Nov 23 11:38:54 linux-gw pluto[10356]: | deleting state #1
Nov 23 11:38:54 linux-gw pluto[10356]: | sending 84 bytes for delete notify through eth1:500 to 6.6.6.3:500 (using #1)
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/2x1
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/2x1": terminating SAs using this connection
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/2x1
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/2x1" #4: deleting state (STATE_QUICK_I2)
Nov 23 11:38:54 linux-gw pluto[10356]: | deleting state #4
Nov 23 11:38:54 linux-gw pluto[10356]: | no Phase 1 state for Delete
Nov 23 11:38:54 linux-gw pluto[10356]: | command executing down-client
Nov 23 11:38:54 linux-gw pluto[10356]: | executing down-client: 2>&1 PLUTO_VERB='down-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1' PLUTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' PLUTO_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10.8.13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT='192.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+IKEv2ALLOW' PLUTO_XAUTH_USERNAME='' PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOMAIN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown
Nov 23 11:38:54 linux-gw pluto[10356]: | popen(): cmd is 765 chars long
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd(   0):2>&1 PLUTO_VERB='down-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1' PL:
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd(  80):UTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' PLUT:
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd( 160):O_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10.8.:
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd( 240):13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL=':
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd( 320):0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT='192:
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd( 400):.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK='255:
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd( 480):.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_S:
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd( 560):TACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+IKEv2ALLOW' PLUTO_XAUTH_USE:
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd( 640):RNAME='' PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOMA:
Nov 23 11:38:54 linux-gw pluto[10356]: | cmd( 720):IN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown:
Nov 23 11:38:54 linux-gw pluto[10356]: | request to replace with shunt a prospective erouted policy with netkey kernel --- experimental
Nov 23 11:38:54 linux-gw pluto[10356]: | delete inbound eroute 192.168.101.0/24:0 --0-> 10.8.13.0/24:0 => unk255.10000 at 5.5.5.22 (raw_eroute)
Nov 23 11:38:54 linux-gw pluto[10356]: | raw_eroute result=1 
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/1x2": terminating SAs using this connection
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/1x2" #7: deleting state (STATE_QUICK_I1)
Nov 23 11:38:54 linux-gw pluto[10356]: | deleting state #7
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/1x1": terminating SAs using this connection
Nov 23 11:38:54 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:38:54 linux-gw pluto[10356]: "bender/1x1" #8: deleting state (STATE_QUICK_I1)
Nov 23 11:38:54 linux-gw pluto[10356]: | deleting state #8
Nov 23 11:38:54 linux-gw pluto[10356]: | ICOOKIE:  e2 9f 53 8e  dc 3e a9 94
Nov 23 11:38:54 linux-gw pluto[10356]: | RCOOKIE:  08 4c 6b a1  f2 65 5e 22
Nov 23 11:38:54 linux-gw pluto[10356]: | state hash entry 14
Nov 23 11:38:54 linux-gw pluto[10356]: | * processed 0 messages from cryptographic helpers 
Nov 23 11:38:54 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 12 seconds
Nov 23 11:38:54 linux-gw pluto[10356]: | next event EVENT_PENDING_DDNS in 12 seconds
Nov 23 11:38:56 linux-gw pluto[10356]: | 
Nov 23 11:38:56 linux-gw pluto[10356]: | *received whack message
Nov 23 11:38:56 linux-gw pluto[10356]: shutting down
Nov 23 11:38:56 linux-gw pluto[10356]: forgetting secrets
Nov 23 11:38:56 linux-gw pluto[10356]: | processing connection bender/2x2
Nov 23 11:38:56 linux-gw pluto[10356]: "bender/2x2": deleting connection
Nov 23 11:38:56 linux-gw pluto[10356]: | processing connection bender/2x1
Nov 23 11:38:56 linux-gw pluto[10356]: "bender/2x1": deleting connection
Nov 23 11:38:56 linux-gw pluto[10356]: | request to delete a unrouted policy with netkey kernel --- experimental
Nov 23 11:38:56 linux-gw pluto[10356]: | route owner of "bender/2x1" unrouted: NULL
Nov 23 11:38:56 linux-gw pluto[10356]: | command executing unroute-client
Nov 23 11:38:56 linux-gw pluto[10356]: | executing unroute-client: 2>&1 PLUTO_VERB='unroute-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1' PLUTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' PLUTO_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10.8.13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT='192.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+IKEv2ALLOW'  PLUTO_MY_SOURCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOMAIN_INFO='' PLUTO_PEER_BANNER='' ipsec _updown
Nov 23 11:38:56 linux-gw pluto[10356]: | popen(): cmd is 745 chars long
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd(   0):2>&1 PLUTO_VERB='unroute-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='bender/2x1':
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd(  80): PLUTO_INTERFACE='eth1' PLUTO_NEXT_HOP='5.5.5.100' PLUTO_ME='5.5.5.22' P:
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd( 160):LUTO_MY_ID='5.5.5.22' PLUTO_MY_CLIENT='10.8.13.0/24' PLUTO_MY_CLIENT_NET='10:
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd( 240):.8.13.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCO:
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd( 320):L='0' PLUTO_PEER='6.6.6.3' PLUTO_PEER_ID='6.6.6.3' PLUTO_PEER_CLIENT=':
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd( 400):192.168.101.0/24' PLUTO_PEER_CLIENT_NET='192.168.101.0' PLUTO_PEER_CLIENT_MASK=':
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd( 480):255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUT:
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd( 560):O_STACK='netkey'  PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+IKEv2ALLOW'  PLUTO_MY_SO:
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd( 640):URCEIP='10.8.13.18' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOMAIN_INFO='' PLUTO_PEE:
Nov 23 11:38:56 linux-gw pluto[10356]: | cmd( 720):R_BANNER='' ipsec _updown:
Nov 23 11:38:56 linux-gw pluto[10356]: | processing connection bender/1x2
Nov 23 11:38:56 linux-gw pluto[10356]: "bender/1x2": deleting connection
Nov 23 11:38:56 linux-gw pluto[10356]: | processing connection bender/1x1
Nov 23 11:38:56 linux-gw pluto[10356]: "bender/1x1": deleting connection
Nov 23 11:38:56 linux-gw pluto[10356]: shutting down interface lo/lo ::1:500
Nov 23 11:38:56 linux-gw pluto[10356]: shutting down interface lo/lo 127.0.0.1:500
Nov 23 11:38:56 linux-gw pluto[10356]: shutting down interface eth0/eth0 10.8.13.16:500
Nov 23 11:38:56 linux-gw pluto[10356]: shutting down interface eth0/eth0 10.8.13.18:500
Nov 23 11:38:56 linux-gw pluto[10356]: shutting down interface eth1/eth1 5.5.5.22:500
Nov 23 11:38:56 linux-gw pluto[10356]: shutting down interface tun0/tun0 10.8.0.1:500
Nov 23 11:38:56 linux-gw pluto[10356]: leak: struct event in event_schedule(), item size: 32
Nov 23 11:38:56 linux-gw pluto[10356]: leak: 3 * vid->data, item size: 6
Nov 23 11:38:56 linux-gw pluto[10356]: leak: self-vendor ID, item size: 33
Nov 23 11:38:56 linux-gw pluto[10356]: leak: init_pluto_vendorid, item size: 13
Nov 23 11:38:56 linux-gw pluto[10356]: leak: 2 * vid->data, item size: 13
Nov 23 11:38:56 linux-gw pluto[10356]: leak: myid string, item size: 13
Nov 23 11:38:56 linux-gw pluto[10356]: leak: my FQDN, item size: 11
Nov 23 11:38:56 linux-gw pluto[10356]: leak: 4 * connection alias, item size: 5
Nov 23 11:38:56 linux-gw pluto[10356]: leak: struct event in event_schedule(), item size: 32
Nov 23 11:38:56 linux-gw pluto[10356]: leak: myid string, item size: 13
Nov 23 11:38:56 linux-gw pluto[10356]: leak: pluto helpers, item size: 192
Nov 23 11:38:56 linux-gw pluto[10356]: leak: 2 * hasher name, item size: 16
Nov 23 11:38:56 linux-gw pluto[10356]: leak: 2 * struct event in event_schedule(), item size: 32
Nov 23 11:38:56 linux-gw pluto[10356]: leak: private_net_ko subnets, item size: 64
Nov 23 11:38:56 linux-gw pluto[10356]: leak: private_net_ok subnets, item size: 96
Nov 23 11:38:56 linux-gw pluto[10356]: leak: policies path, item size: 22
Nov 23 11:38:56 linux-gw pluto[10356]: leak: ocspcerts path, item size: 23
Nov 23 11:38:56 linux-gw pluto[10356]: leak: aacerts path, item size: 21
Nov 23 11:38:56 linux-gw pluto[10356]: leak: certs path, item size: 19
Nov 23 11:38:56 linux-gw pluto[10356]: leak: private path, item size: 21
Nov 23 11:38:56 linux-gw pluto[10356]: leak: crls path, item size: 18
Nov 23 11:38:56 linux-gw pluto[10356]: leak: cacert path, item size: 21
Nov 23 11:38:56 linux-gw pluto[10356]: leak: acert path, item size: 20
Nov 23 11:38:56 linux-gw pluto[10356]: leak: override ipsec.d, item size: 13
Nov 23 11:38:56 linux-gw pluto[10356]: leak: nss password file path, item size: 25
Nov 23 11:38:56 linux-gw pluto[10356]: leak: ipsec.conf, item size: 16
Nov 23 11:38:56 linux-gw pluto[10356]: leak: ipsecdir, item size: 13
Nov 23 11:38:56 linux-gw pluto[10356]: leak: ipsec_confs, item size: 5
Nov 23 11:38:56 linux-gw pluto[10356]: leak: 4 * default conf, item size: 5
Nov 23 11:38:56 linux-gw pluto[10356]: leak detective found 40 leaks, total size 813