I'm trying now for several days to establish a vpn connection between openWRT WR RC4 on a Linksys WRT54GS V4 and a LANCOM 1711. But so far I have no luck. I was able to connect to our company gateway (LANCOM) with an IPcop 1.4.10 box. I took the ipsec configuration from IPcop and removed the parts from ipsec.conf that were not allowed in openWRT. In addition, I had to add a line with "version 2.0".
I've tried in the past days all possible parameter settings I could think of, but I didn't succeed. So I ask you to point me in the right direction.
I see that the connection comes up to STATE_MAIN_I4 but stucks then because it waits for "phase 1 is done, looking for phase 1 to unpend" but this does never happen. Is there an ipsec settings that I can turn on in order to make it more LANCOM compatible?
Thanks in advance
Andreas
My ipsec.conf looks as follows:
version 2.0 # conforms to second version of ipsec.conf specification
config setup
plutodebug="control"
uniqueids=yes
virtual_private=%v4:10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16,%v4:!10.7.7.0/255.255.255.0,%v4:!10.11.12.0/255.255.255.0conn COMPANY
left=my.dyndns.net
leftnexthop=%defaultroute
leftsubnet=10.7.7.0/255.255.255.0
right=123.45.67.89
rightsubnet=10.11.12.0/255.255.255.0
rightnexthop=%defaultroute
ike=aes128-md5-modp1024,aes128-sha-modp1024
esp=aes128-md5,aes128-sha1
ikelifetime=1h
keylife=8h
dpddelay=60
dpdtimeout=120
dpdaction=hold
pfs=yes
authby=secret
auto=start#Disable Opportunistic Encryption
include /etc/ipsec.d/examples/no_oe.conf
When I start the connection with "ipsec setup --start", I see the following results via logread (some lines may be missing. I merged the log together from multiple "logread > /tmp/logN.txt" commands):
Jan 4 12:25:34 (none) daemon.err ipsec_setup: KLIPS ipsec0 on ppp0 84.140.241.216/255.255.255.255 pointopoint 217.0.116.103
Jan 4 12:25:36 (none) authpriv.err ipsec__plutorun: Starting Pluto subsystem...
Jan 4 12:25:36 (none) daemon.err ipsec_setup: ...Openswan IPsec started
Jan 4 12:25:37 (none) daemon.err ipsec_setup: Starting Openswan IPsec 2.4.4...
Jan 4 12:25:37 (none) kern.warn pluto[15082]: Starting Pluto (Openswan Version 2.4.4 X.509-1.5.4 PLUTO_SENDS_VENDORID PLUTO_USES_KEYRR; Vendor ID OEz}FFFfgr_e)
Jan 4 12:25:37 (none) kern.warn pluto[15082]: Setting NAT-Traversal port-4500 floating to off
Jan 4 12:25:37 (none) kern.warn pluto[15082]: port floating activation criteria nat_t=0/port_fload=1
Jan 4 12:25:37 (none) kern.warn pluto[15082]: including NAT-Traversal patch (Version 0.6c) [disabled]
Jan 4 12:25:37 (none) kern.debug pluto[15082]: | opening /dev/urandom
Jan 4 12:25:37 (none) kern.debug pluto[15082]: | inserting event EVENT_REINIT_SECRET, timeout in 3600 seconds
Jan 4 12:25:37 (none) kern.debug pluto[15082]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
Jan 4 12:25:37 (none) kern.warn pluto[15082]: ike_alg_register_enc(): Activating OAKLEY_AES_CBC: Ok (ret=0)
Jan 4 12:25:37 (none) kern.warn pluto[15082]: starting up 1 cryptographic helpers
Jan 4 12:25:37 (none) kern.warn pluto[15082]: started helper pid=15084 (fd:6)
Jan 4 12:25:37 (none) kern.warn pluto[15082]: Using KLIPS IPsec interface code on 2.4.30
Jan 4 12:25:37 (none) kern.debug pluto[15084]: | opening /dev/urandom
Jan 4 12:25:37 (none) kern.debug pluto[15082]: | inserting event EVENT_SHUNT_SCAN, timeout in 120 seconds
Jan 4 12:25:37 (none) kern.warn pluto[15082]: Changing to directory '/etc/ipsec.d/cacerts'
Jan 4 12:25:37 (none) kern.warn pluto[15082]: Changing to directory '/etc/ipsec.d/aacerts'
Jan 4 12:25:37 (none) kern.warn pluto[15082]: Changing to directory '/etc/ipsec.d/ocspcerts'
Jan 4 12:25:37 (none) kern.warn pluto[15082]: Changing to directory '/etc/ipsec.d/crls'
Jan 4 12:25:37 (none) kern.warn pluto[15082]: Warning: empty directory
Jan 4 12:25:37 (none) kern.debug pluto[15082]: | inserting event EVENT_LOG_DAILY, timeout in 41663 seconds
Jan 4 12:25:37 (none) kern.debug pluto[15082]: | next event EVENT_SHUNT_SCAN in 120 seconds
Jan 4 12:25:37 (none) kern.debug pluto[15084]: ! helper 0 waiting on fd: 7
Jan 4 12:25:42 (none) kern.debug pluto[15082]: |
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | *received whack message
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | Added new connection PTHHFW with policy PSK+ENCRYPT+TUNNEL+PFS
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | from whack: got --esp=aes128-md5,aes128-sha1
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | esp string values: 12_128-1, 12_128-2, flags=-strict
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | from whack: got --ike=aes128-md5-modp1024,aes128-sha-modp1024
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | ike string values: 7_128-1-2, 7_128-2-2, flags=-strict
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | counting wild cards for (none) is 15
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | counting wild cards for (none) is 15
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | alg_info_addref() alg_info->ref_cnt=1
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | alg_info_addref() alg_info->ref_cnt=1
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | alg_info_addref() alg_info->ref_cnt=2
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | alg_info_addref() alg_info->ref_cnt=2
Jan 4 12:25:42 (none) kern.warn pluto[15082]: added connection description "COMPANY"
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | 10.7.7.0/24===84.140.241.216---217.0.116.103...217.0.116.103---123.45.67.89===10.11.12.0/24
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy: PSK+ENCRYPT+TUNNEL+PFS
Jan 4 12:25:42 (none) kern.debug pluto[15082]: | next event EVENT_SHUNT_SCAN in 115 seconds
Jan 4 12:25:44 (none) kern.debug pluto[15082]: | best_match 0>6 best=0x1001ecf0 (line=1)
Jan 4 12:25:44 (none) kern.debug pluto[15082]: | concluding with best_match=6 best=0x1001ecf0 (lineno=1)
Jan 4 12:25:44 (none) kern.debug pluto[15082]: | 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1
Jan 4 12:25:44 (none) kern.debug pluto[15082]: | asking helper 0 to do build_kenonce op on seq: 1
Jan 4 12:25:44 (none) kern.debug pluto[15082]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
Jan 4 12:25:44 (none) kern.debug pluto[15082]: | complete state transition with STF_SUSPEND
Jan 4 12:25:44 (none) kern.debug pluto[15082]: | next event EVENT_SHUNT_SCAN in 113 seconds
Jan 4 12:25:44 (none) kern.debug pluto[15084]: ! helper -1 doing build_kenonce op id: 1
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing connection COMPANY
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | ICOOKIE: 29 91 a5 2c eb e6 6b 1c
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | RCOOKIE: 00 00 00 00 00 00 00 00
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer: d9 5b 2f 41
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state hash entry 31
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | ICOOKIE: 29 91 a5 2c eb e6 6b 1c
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | RCOOKIE: e4 ba e5 89 80 55 26 05
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer: d9 5b 2f 41
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state hash entry 5
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | complete state transition with STF_OK
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | sending reply packet to 123.45.67.89:500 (from port=500)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | sending 180 bytes for STATE_MAIN_I1 through ppp0:500 to 123.45.67.89:500:
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: STATE_MAIN_I2: sent MI2, expecting MR2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | modecfg pull: noquirk policy:push not-client
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | phase 1 is done, looking for phase 1 to unpend
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Jan 4 12:25:45 (none) kern.debug pluto[15082]: |
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | *received 180 bytes from 123.45.67.89:500 on ppp0 (port=500)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | ICOOKIE: 29 91 a5 2c eb e6 6b 1c
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | RCOOKIE: e4 ba e5 89 80 55 26 05
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer: d9 5b 2f 41
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state hash entry 5
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state object #1 found, in STATE_MAIN_I2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing connection COMPANY
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | thinking about whether to send my certificate:
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | I have RSA key: OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | sendcert: CERT_ALWAYSSEND and I did not get a certificate request
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | so do not send cert.
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: I did not send a certificate because I do not have one.
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | I am not sending a certificate request
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | started looking for secret for 84.140.241.216->123.45.67.89 of kind PPK_PSK
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | actually looking for secret for 84.140.241.216->123.45.67.89 of kind PPK_PSK
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | 1: compared PSK 123.45.67.89 to 84.140.241.216 / 123.45.67.89 -> 2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | 2: compared PSK 84.140.241.216 to 84.140.241.216 / 123.45.67.89 -> 6
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | best_match 0>6 best=0x1001ecf0 (line=1)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | concluding with best_match=6 best=0x1001ecf0 (lineno=1)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | complete state transition with STF_OK
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | sending reply packet to 123.45.67.89:500 (from port=500)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | sending 60 bytes for STATE_MAIN_I2 through ppp0:500 to 123.45.67.89:500:
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: STATE_MAIN_I3: sent MI3, expecting MR3
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | modecfg pull: noquirk policy:push not-client
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | phase 1 is done, looking for phase 1 to unpend
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Jan 4 12:25:45 (none) kern.debug pluto[15082]: |
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | *received 60 bytes from 123.45.67.89:500 on ppp0 (port=500)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | ICOOKIE: 29 91 a5 2c eb e6 6b 1c
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | RCOOKIE: e4 ba e5 89 80 55 26 05
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer: d9 5b 2f 41
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state hash entry 5
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state object #1 found, in STATE_MAIN_I3
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing connection COMPANY
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: Main mode peer ID is ID_IPV4_ADDR: '123.45.67.89'
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | complete state transition with STF_OK
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | inserting event EVENT_SA_REPLACE, timeout in 2633 seconds for #1
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128 prf=oakley_md5 group=modp1024}
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | ICOOKIE: 29 91 a5 2c eb e6 6b 1c
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | RCOOKIE: e4 ba e5 89 80 55 26 05
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer: d9 5b 2f 41
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state hash entry 5
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state object #1 found, in STATE_MAIN_I4
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #1: Dead Peer Detection (RFC 3706): enabled
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state: 1 requesting event none to be deleted by dpd.c:160
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | inserting event EVENT_DPD, timeout in 60 seconds for #1
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | modecfg pull: noquirk policy:push not-client
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | phase 1 is done, looking for phase 1 to unpend
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | unqueuing pending Quick Mode with 123.45.67.89 "COMPANY"
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | duplicating state object #1
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | creating state object #2 at 0x1001fd98
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing connection COMPANY
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | ICOOKIE: 29 91 a5 2c eb e6 6b 1c
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | RCOOKIE: e4 ba e5 89 80 55 26 05
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer: d9 5b 2f 41
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state hash entry 5
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #2
Jan 4 12:25:45 (none) kern.warn pluto[15082]: "COMPANY" #2: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP {using isakmp#1}
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | asking helper 0 to do build_kenonce op on seq: 2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | next event EVENT_DPD in 60 seconds for #1
Jan 4 12:25:45 (none) kern.debug pluto[15084]: ! helper -1 doing build_kenonce op id: 2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing connection COMPANY
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | kernel_alg_db_new() will return p_new->protoid=3, p_new->trans_cnt=2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | kernel_alg_db_new() trans[0]: transid=12, attr_cnt=2, attrs[0].type=5, attrs[0].val=1
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | kernel_alg_db_new() trans[1]: transid=12, attr_cnt=2, attrs[0].type=5, attrs[0].val=2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | returning new proposal from esp_info
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | generate SPI: 03 27 8f f5
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | sending 332 bytes for quick_outI1 through ppp0:500 to 123.45.67.89:500:
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | next event EVENT_RETRANSMIT in 10 seconds for #2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: |
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | *received 300 bytes from 123.45.67.89:500 on ppp0 (port=500)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing packet with exchange type=ISAKMP_XCHG_QUICK (32)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | ICOOKIE: 29 91 a5 2c eb e6 6b 1c
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | RCOOKIE: e4 ba e5 89 80 55 26 05
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer: d9 5b 2f 41
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state hash entry 5
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer and cookies match on #2, provided msgid 75a52bb2 vs 75a52bb2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | state object #2 found, in STATE_QUICK_I1
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | processing connection COMPANY
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | started looking for secret for 84.140.241.216->123.45.67.89 of kind PPK_PSK
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | actually looking for secret for 84.140.241.216->123.45.67.89 of kind PPK_PSK
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | 1: compared PSK 123.45.67.89 to 84.140.241.216 / 123.45.67.89 -> 2
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | 2: compared PSK 84.140.241.216 to 84.140.241.216 / 123.45.67.89 -> 6
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | best_match 0>6 best=0x1001ecf0 (line=1)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | concluding with best_match=6 best=0x1001ecf0 (lineno=1)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | our client is subnet 10.7.7.0/24
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | our client protocol/port is 0/0
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer client is subnet 10.11.12.0/24
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | peer client protocol/port is 0/0
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | install_ipsec_sa() for #2: inbound and outbound
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | route owner of "COMPANY" prospective erouted: self; eroute owner: self
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | could_route called for COMPANY (kind=CK_PERMANENT)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | add inbound eroute 10.11.12.0/24:0 --0-> 10.7.7.0/24:0 => tun.1001@84.140.241.216 (raw_eroute)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | sr for #2: prospective erouted
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | route owner of "COMPANY" prospective erouted: self; eroute owner: self
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | eroute_connection replace eroute 10.7.7.0/24:0 --0-> 10.11.12.0/24:0 => tun.1002@123.45.67.89 (raw_eroute)
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | command executing up-client
Jan 4 12:25:45 (none) kern.debug pluto[15082]: | executing up-client: 2>&1 PLUTO_VERSION='1.1' PLUTO_VERB='up-client' PLUTO_CONNECTION='PTHHFW' PLUTO_NEXT_HOP='217.0.116.103' PLUTO_INTERFACE='ipsec0' PLUTO_ME='84.140.241.216' PLUTO_MY_ID='84.140.241.216' PLUTO_MY_CLIENT='10.7.7.0/24' PLUTO_MY_CLIENT_NET='10.7.7.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='123.45.67.89' PLUTO_PEER_ID='123.45.67.89' PLUTO_PEER_CLIENT='10.11.12.0/24' PLUTO_PEER_CLIENT_NET='10.11.12.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+PFS+UP' ipsec _updown
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | route_and_eroute: firewall_notified: true
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | route_and_eroute: instance "COMPANY", setting eroute_owner {spd=0x1001d320,sr=0x1001d320} to #2 (was #0) (newest_ipsec_sa=#0)
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | ICOOKIE: 29 91 a5 2c eb e6 6b 1c
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | RCOOKIE: e4 ba e5 89 80 55 26 05
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | peer: d9 5b 2f 41
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | state hash entry 5
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | peer and cookies match on #2, provided msgid 00000000 vs 75a52bb2
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | state object #1 found, in STATE_MAIN_I4
Jan 4 12:25:46 (none) kern.warn pluto[15082]: "COMPANY" #2: Dead Peer Detection (RFC 3706): enabled
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | state: 2 requesting event none to be deleted by dpd.c:160
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | inserting event EVENT_DPD, timeout in 60 seconds for #2
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | state: 1 requesting event EVENT_DPD to be deleted by dpd.c:172
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | complete state transition with STF_OK
Jan 4 12:25:46 (none) kern.warn pluto[15082]: "COMPANY" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | sending reply packet to 123.45.67.89:500 (from port=500)
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | sending 60 bytes for STATE_QUICK_I1 through ppp0:500 to 123.45.67.89:500:
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | inserting event EVENT_SA_REPLACE, timeout in 27956 seconds for #2
Jan 4 12:25:46 (none) kern.warn pluto[15082]: "COMPANY" #2: STATE_QUICK_I2: sent QI2, IPsec SA established {ESP=>0x0d8554c5 <0x03278ff5 xfrm=AES_128-HMAC_MD5 NATD=none DPD=enabled}
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | modecfg pull: noquirk policy:push not-client
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | phase 1 is done, looking for phase 1 to unpend
Jan 4 12:25:46 (none) kern.debug pluto[15082]: | next event EVENT_DPD in 60 seconds for #2