[Openswan Users] DPD and ERROR: netlink response for Add SA esp.xxxxxxxx at y.y.y.y included errno 17: File exists

Tue Jul 19 11:42:10 EDT 2011

On Tue, 19 Jul 2011, L Felgr wrote:

> Problem with DPD:
> If I switch Dev2 off for more than dpddelay then Dev1 correctly recognizes Dev2 as dead and after switching Dev2 on the IPsec tunnel is
> reestablished without any problem. If I restart Dev2 (switching it off and on again or rebooting) just after keep-alive packets are
> exchanged so there is enough time for Dev2 to be ready for communication before dpddelay expires then the error 17: File exists (see in
> the syslog listing) appears in 50 % cases and tunnel reestablishment freezes for 40 minutes or thereabouts. Evidently, it is the problem
> of Dev1 which is not able to recognize that Dev2 went through reset meanwhile. Dev1 and Dev2 are interchangeable regarding this problem.
>  
> I am aware of:
> 1) This problem can be solved by using dpddelay as short as possible. 10 sec would be fair value for my purposes. But I can't use values
> under 1 min beacuse of the price of exchanging keep-alive messages over GSM network. There can be hundreds of such devices in the
> network.
> 2) The problem maybe comes from the fact there is not enough time for pluto to disconnect tunnel before rebooting. Anyway, If anybody
> switches supply voltage off on Dev2 (it's OK with embedded system - nothing is damaged) then there surely is not enough time to do
> anything. And this can happen in real situation quite often.
>  
> So what can I do? Should I find critical code and try to change something? That is not probably good idea because either IPsec stack in
> the kernel or IKE deamon are written according to RFC's and if I change anything then I can loose interoperability with other systems
> (Cisco, Windows etc).

If the powercycled unit comes back on, and reconnects to the other unit, the IPsec SA should be re-established
and the older SA on the unit that did not get power cycled should get replaced. Are you not seeing that
happening?

Are you using our initscripts or are you starting pluto manually? If manually do you start pluto
with --uniqueids ?

Paul
> Thanks for help in advance.
>  
> L. Felgr
>  
> ========================================
> Dev1 syslog listing
> ========================================
> 2011-07-18 11:38:02 pluto[431]: Starting Pluto (Openswan Version 2.6.25) pid:431
> 2011-07-18 11:38:02 pluto[431]: Setting NAT-Traversal port-4500 floating to off
> 2011-07-18 11:38:02 pluto[431]:    port floating activation criteria nat_t=0/port_float=1
> 2011-07-18 11:38:02 pluto[431]:    NAT-Traversal support  [disabled]
> 2011-07-18 11:38:02 pluto[431]: using /dev/urandom as source of random entropy
> 2011-07-18 11:38:02 pluto[431]: no helpers will be started, all cryptographic operations will be done inline
> 2011-07-18 11:38:03 pluto[431]: Using Linux 2.6 IPsec interface code on 2.6.23 (experimental code)
> 2011-07-18 11:38:03 pluto[431]: Changed path to directory '/etc/ipsec.d/cacerts'
> 2011-07-18 11:38:03 pluto[431]: added connection description "ipsec1"
> 2011-07-18 11:38:04 pluto[431]: listening for IKE messages
> 2011-07-18 11:38:04 pluto[431]: adding interface ppp0/ppp0 10.0.2.125:500
> 2011-07-18 11:38:04 pluto[431]: adding interface eth0/eth0 192.168.2.149:500
> 2011-07-18 11:38:04 pluto[431]: loading secrets from "/etc/ipsec.d/ipsec.secrets"
> 2011-07-18 11:38:04 pluto[431]: "ipsec1" #1: initiating Main Mode
> 2011-07-18 11:38:04 pppd[371]: Script /etc/scripts/ip-up finished (pid 392), status = 0x0
> 2011-07-18 11:38:07 pluto[431]: "ipsec1" #1: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:38:07 pluto[431]: "ipsec1" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
> 2011-07-18 11:38:07 pluto[431]: "ipsec1" #1: STATE_MAIN_I2: sent MI2, expecting MR2
> 2011-07-18 11:38:09 pluto[431]: "ipsec1" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
> 2011-07-18 11:38:09 pluto[431]: "ipsec1" #1: STATE_MAIN_I3: sent MI3, expecting MR3
> 2011-07-18 11:38:10 pluto[431]: "ipsec1" #1: Main mode peer ID is ID_IPV4_ADDR: '10.0.3.114'
> 2011-07-18 11:38:10 pluto[431]: "ipsec1" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
> 2011-07-18 11:38:10 pluto[431]: "ipsec1" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 11:38:10 pluto[431]: "ipsec1" #1: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:38:10 pluto[431]: "ipsec1" #2: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP {using isakmp#1 msgid:4cf964f1 proposal=defaults
> pfsgroup=no-pfs}
> 2011-07-18 11:38:10 pluto[431]: packet from 10.0.3.114:500: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:38:10 pluto[431]: "ipsec1" #3: responding to Main Mode
> 2011-07-18 11:38:10 pluto[431]: "ipsec1" #3: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> 2011-07-18 11:38:10 pluto[431]: "ipsec1" #3: STATE_MAIN_R1: sent MR1, expecting MI2
> 2011-07-18 11:38:11 pluto[431]: "ipsec1" #2: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:38:11 pluto[431]: "ipsec1" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
> 2011-07-18 11:38:11 pluto[431]: "ipsec1" #2: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP=0xbd885898 0x982ea68a
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> 2011-07-18 11:38:12 pluto[431]: "ipsec1" #3: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> 2011-07-18 11:38:12 pluto[431]: "ipsec1" #3: STATE_MAIN_R2: sent MR2, expecting MI3
> 2011-07-18 11:38:23 pluto[431]: "ipsec1" #3: discarding duplicate packet; already STATE_MAIN_R2
> 2011-07-18 11:38:23 pluto[431]: "ipsec1" #3: Main mode peer ID is ID_IPV4_ADDR: '10.0.3.114'
> 2011-07-18 11:38:23 pluto[431]: "ipsec1" #3: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> 2011-07-18 11:38:23 pluto[431]: "ipsec1" #3: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #3: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #3: the peer proposed: 192.168.2.0/24:0/0 - 192.168.3.0/24:0/0
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4: responding to Quick Mode proposal {msgid:55efdddf}
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4:     us: 192.168.2.0/24===10.0.2.125
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4:   them: 10.0.3.114===192.168.3.0/24
> 2011-07-18 11:38:24 pluto[431]: | NAT-OA: 0 tunnel: 0 
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4: keeping refhim=4294901761 during rekey
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
> 2011-07-18 11:38:24 pluto[431]: "ipsec1" #4: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=0x3b859493 0xecbb3010
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> ****************************************
> State: IPsec tunnel established - OK
> Action: Dev2 - power off
> ****************************************
> 2011-07-18 11:40:21 pluto[431]: "ipsec1" #3: DPD: No response from peer - declaring peer dead
> 2011-07-18 11:40:21 pluto[431]: "ipsec1" #3: DPD: Restarting all connections that share this peer
> 2011-07-18 11:40:21 pluto[431]: "ipsec1" #3: terminating SAs using this connection
> 2011-07-18 11:40:21 pluto[431]: "ipsec1" #4: deleting state (STATE_QUICK_R2)
> 2011-07-18 11:40:21 pluto[431]: "ipsec1" #3: deleting state (STATE_MAIN_R3)
> 2011-07-18 11:40:21 pluto[431]: "ipsec1" #2: deleting state (STATE_QUICK_I2)
> 2011-07-18 11:40:21 pluto[431]: "ipsec1" #1: deleting state (STATE_MAIN_I4)
> 2011-07-18 11:40:21 pluto[431]: "ipsec1" #5: initiating Main Mode
> ****************************************
> State: Dead peer detected - OK
> ****************************************
> 2011-07-18 11:42:02 pluto[431]: pending Quick Mode with 10.0.3.114 "ipsec1" took too long -- replacing phase 1
> 2011-07-18 11:42:02 pluto[431]: "ipsec1" #6: initiating Main Mode to replace #5
> ****************************************
> Action: Dev2 - power on
> ****************************************
> 2011-07-18 11:42:57 pluto[431]: packet from 10.0.3.114:500: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:42:57 pluto[431]: "ipsec1" #7: responding to Main Mode
> 2011-07-18 11:42:57 pluto[431]: "ipsec1" #7: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> 2011-07-18 11:42:57 pluto[431]: "ipsec1" #7: STATE_MAIN_R1: sent MR1, expecting MI2
> 2011-07-18 11:42:57 pluto[431]: ERROR: asynchronous network error report on ppp0 (sport=500) for message to 10.0.3.114 port 500,
> complainant 10.1.0.21: No route to host [errno 113, origin ICMP type 3 code 1 (not authenticated)]
> 2011-07-18 11:43:07 pluto[431]: packet from 10.0.3.114:500: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:43:07 pluto[431]: "ipsec1" #8: responding to Main Mode
> 2011-07-18 11:43:07 pluto[431]: "ipsec1" #8: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> 2011-07-18 11:43:07 pluto[431]: "ipsec1" #8: STATE_MAIN_R1: sent MR1, expecting MI2
> 2011-07-18 11:43:08 pluto[431]: "ipsec1" #8: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> 2011-07-18 11:43:08 pluto[431]: "ipsec1" #8: STATE_MAIN_R2: sent MR2, expecting MI3
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #8: Main mode peer ID is ID_IPV4_ADDR: '10.0.3.114'
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #8: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #8: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #8: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #8: the peer proposed: 192.168.2.0/24:0/0 - 192.168.3.0/24:0/0
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #9: responding to Quick Mode proposal {msgid:7db4f7aa}
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #9:     us: 192.168.2.0/24===10.0.2.125
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #9:   them: 10.0.3.114===192.168.3.0/24
> 2011-07-18 11:43:09 pluto[431]: | NAT-OA: 0 tunnel: 0 
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #9: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #9: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #9: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:43:09 pluto[431]: "ipsec1" #9: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
> 2011-07-18 11:43:10 pluto[431]: "ipsec1" #9: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=0x0b056df3 0x17354389
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> 2011-07-18 11:43:12 pluto[431]: "ipsec1" #6: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:43:12 pluto[431]: "ipsec1" #6: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
> 2011-07-18 11:43:12 pluto[431]: "ipsec1" #6: STATE_MAIN_I2: sent MI2, expecting MR2
> 2011-07-18 11:43:13 pluto[431]: "ipsec1" #6: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
> 2011-07-18 11:43:13 pluto[431]: "ipsec1" #6: STATE_MAIN_I3: sent MI3, expecting MR3
> 2011-07-18 11:43:14 pluto[431]: "ipsec1" #6: Main mode peer ID is ID_IPV4_ADDR: '10.0.3.114'
> 2011-07-18 11:43:14 pluto[431]: "ipsec1" #6: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
> 2011-07-18 11:43:14 pluto[431]: "ipsec1" #6: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 11:43:14 pluto[431]: "ipsec1" #6: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:43:14 pluto[431]: "ipsec1" #10: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP {using isakmp#6 msgid:46478d55
> proposal=defaults pfsgroup=no-pfs}
> 2011-07-18 11:43:14 pluto[431]: "ipsec1" #10: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:43:14 pluto[431]: "ipsec1" #10: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
> 2011-07-18 11:43:14 pluto[431]: "ipsec1" #10: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP=0x14b49ae2 0x2d1cc833
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> ****************************************
> State: IPsec tunnel reestablished - OK
> ****************************************
> 2011-07-18 11:44:07 pluto[431]: "ipsec1" #7: max number of retransmissions (2) reached STATE_MAIN_R1
> ****************************************
> Action: Dev2 - reboot
> ****************************************
> 2011-07-18 11:47:57 pluto[431]: packet from 10.0.3.114:500: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:47:57 pluto[431]: "ipsec1" #11: responding to Main Mode
> 2011-07-18 11:47:57 pluto[431]: "ipsec1" #11: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> 2011-07-18 11:47:57 pluto[431]: "ipsec1" #11: STATE_MAIN_R1: sent MR1, expecting MI2
> 2011-07-18 11:47:58 pluto[431]: "ipsec1" #11: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> 2011-07-18 11:47:58 pluto[431]: "ipsec1" #11: STATE_MAIN_R2: sent MR2, expecting MI3
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #11: Main mode peer ID is ID_IPV4_ADDR: '10.0.3.114'
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #11: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #11: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #11: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #11: the peer proposed: 192.168.2.0/24:0/0 - 192.168.3.0/24:0/0
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12: responding to Quick Mode proposal {msgid:fee93b6a}
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12:     us: 192.168.2.0/24===10.0.2.125
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12:   them: 10.0.3.114===192.168.3.0/24
> 2011-07-18 11:47:59 pluto[431]: | NAT-OA: 0 tunnel: 0 
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12: keeping refhim=4294901761 during rekey
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
> 2011-07-18 11:47:59 pluto[431]: "ipsec1" #12: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=0xf05a1802 0x32e9fe4f
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> ****************************************
> State: IPsec tunnel reestablished - OK
> Action: Dev2 - another reboot
> ****************************************
> 2011-07-18 11:54:53 pluto[431]: packet from 10.0.3.114:500: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:54:53 pluto[431]: "ipsec1" #13: responding to Main Mode
> 2011-07-18 11:54:53 pluto[431]: "ipsec1" #13: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> 2011-07-18 11:54:53 pluto[431]: "ipsec1" #13: STATE_MAIN_R1: sent MR1, expecting MI2
> 2011-07-18 11:54:54 pluto[431]: "ipsec1" #13: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #13: STATE_MAIN_R2: sent MR2, expecting MI3
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #13: Main mode peer ID is ID_IPV4_ADDR: '10.0.3.114'
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #13: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #13: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #13: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #13: the peer proposed: 192.168.2.0/24:0/0 - 192.168.3.0/24:0/0
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #14: responding to Quick Mode proposal {msgid:579b2969}
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #14:     us: 192.168.2.0/24===10.0.2.125
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #14:   them: 10.0.3.114===192.168.3.0/24
> 2011-07-18 11:54:55 pluto[431]: | NAT-OA: 0 tunnel: 0 
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #14: keeping refhim=4294901761 during rekey
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #14: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
> 2011-07-18 11:54:55 pluto[431]: "ipsec1" #14: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> 2011-07-18 11:54:56 pluto[431]: "ipsec1" #14: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:54:56 pluto[431]: "ipsec1" #14: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
> 2011-07-18 11:54:56 pluto[431]: "ipsec1" #14: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=0xbd885898 0x1b084a6f
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> 2011-07-18 11:58:54 pluto[431]: packet from 10.0.3.114:500: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:58:54 pluto[431]: "ipsec1" #15: responding to Main Mode
> 2011-07-18 11:58:54 pluto[431]: "ipsec1" #15: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> 2011-07-18 11:58:54 pluto[431]: "ipsec1" #15: STATE_MAIN_R1: sent MR1, expecting MI2
> 2011-07-18 11:58:54 pluto[431]: ERROR: asynchronous network error report on ppp0 (sport=500) for message to 10.0.3.114 port 500,
> complainant 10.1.0.21: No route to host [errno 113, origin ICMP type 3 code 1 (not authenticated)]
> 2011-07-18 11:59:04 pluto[431]: packet from 10.0.3.114:500: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:59:04 pluto[431]: "ipsec1" #16: responding to Main Mode
> 2011-07-18 11:59:04 pluto[431]: "ipsec1" #16: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> 2011-07-18 11:59:04 pluto[431]: "ipsec1" #16: STATE_MAIN_R1: sent MR1, expecting MI2
> 2011-07-18 11:59:06 pluto[431]: "ipsec1" #15: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> 2011-07-18 11:59:06 pluto[431]: "ipsec1" #15: STATE_MAIN_R2: sent MR2, expecting MI3
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #15: Main mode peer ID is ID_IPV4_ADDR: '10.0.3.114'
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #15: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #15: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #15: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #15: the peer proposed: 192.168.2.0/24:0/0 - 192.168.3.0/24:0/0
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #17: responding to Quick Mode proposal {msgid:56b0ce8b}
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #17:     us: 192.168.2.0/24===10.0.2.125
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #17:   them: 10.0.3.114===192.168.3.0/24
> 2011-07-18 11:59:07 pluto[431]: | NAT-OA: 0 tunnel: 0 
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #17: keeping refhim=4294901761 during rekey
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #17: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #17: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> 2011-07-18 11:59:07 pluto[431]: "ipsec1" #17: ERROR: netlink response for Add SA esp.b056df3 at 10.0.3.114 included errno 17: File exists
> ****************************************
> State: error encountered, nothing important happens for next 45 minutes
> ****************************************
> 2011-07-18 11:59:17 pluto[431]: "ipsec1" #17: discarding duplicate packet; already STATE_QUICK_R1
> 2011-07-18 11:59:38 last message repeated 1 time
> 2011-07-18 12:00:14 pluto[431]: "ipsec1" #16: max number of retransmissions (2) reached STATE_MAIN_R1
> 2011-07-18 12:12:17 pluto[431]: "ipsec1" #17: max number of retransmissions (20) reached STATE_QUICK_R1
> 2011-07-18 12:44:07 pluto[431]: packet from 10.0.3.114:500: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 12:44:07 pluto[431]: "ipsec1" #18: responding to Main Mode
> 2011-07-18 12:44:07 pluto[431]: "ipsec1" #18: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> 2011-07-18 12:44:07 pluto[431]: "ipsec1" #18: STATE_MAIN_R1: sent MR1, expecting MI2
> 2011-07-18 12:44:09 pluto[431]: "ipsec1" #18: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> 2011-07-18 12:44:09 pluto[431]: "ipsec1" #18: STATE_MAIN_R2: sent MR2, expecting MI3
> 2011-07-18 12:44:09 pluto[431]: "ipsec1" #18: Main mode peer ID is ID_IPV4_ADDR: '10.0.3.114'
> 2011-07-18 12:44:09 pluto[431]: "ipsec1" #18: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> 2011-07-18 12:44:09 pluto[431]: "ipsec1" #18: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 12:44:09 pluto[431]: "ipsec1" #18: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 12:45:44 pluto[431]: "ipsec1" #18: the peer proposed: 192.168.2.0/24:0/0 - 192.168.3.0/24:0/0
> 2011-07-18 12:45:44 pluto[431]: "ipsec1" #19: responding to Quick Mode proposal {msgid:4ae48898}
> 2011-07-18 12:45:44 pluto[431]: "ipsec1" #19:     us: 192.168.2.0/24===10.0.2.125
> 2011-07-18 12:45:44 pluto[431]: "ipsec1" #19:   them: 10.0.3.114===192.168.3.0/24
> 2011-07-18 12:45:44 pluto[431]: | NAT-OA: 0 tunnel: 0 
> 2011-07-18 12:45:44 pluto[431]: "ipsec1" #19: keeping refhim=4294901761 during rekey
> 2011-07-18 12:45:44 pluto[431]: "ipsec1" #19: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
> 2011-07-18 12:45:44 pluto[431]: "ipsec1" #19: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> 2011-07-18 12:45:45 pluto[431]: "ipsec1" #19: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 12:45:45 pluto[431]: "ipsec1" #19: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
> 2011-07-18 12:45:45 pluto[431]: "ipsec1" #19: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=0xe8a79ed2 0xa13d3474
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> ****************************************
> State: IPsec tunnel reestablished - OK
> ****************************************
> 2011-07-18 12:59:09 pluto[431]: "ipsec1" #18: ignoring Delete SA payload: PROTO_IPSEC_ESP SA(0x0b056df3) not found (maybe expired)
> 2011-07-18 12:59:09 pluto[431]: "ipsec1" #18: received and ignored informational message
> 2011-07-18 12:59:09 pluto[431]: packet from 10.0.3.114:500: Informational Exchange is for an unknown (expired?) SA with MSGID:0xcbbeb8a1
>  
>  
> 
> ========================================
> Dev2 syslog listing (after last reboot)
> ========================================
> 2011-07-18 11:59:12 pluto[562]: Starting Pluto (Openswan Version 2.6.34) pid:562
> 2011-07-18 11:59:12 pluto[562]: LEAK_DETECTIVE support [disabled]
> 2011-07-18 11:59:12 pluto[562]: OCF support for IKE [disabled]
> 2011-07-18 11:59:12 pluto[562]: NSS support [disabled]
> 2011-07-18 11:59:12 pluto[562]: HAVE_STATSD notification support not compiled in
> 2011-07-18 11:59:12 pluto[562]: Setting NAT-Traversal port-4500 floating to off
> 2011-07-18 11:59:12 pluto[562]:    port floating activation criteria nat_t=0/port_float=1
> 2011-07-18 11:59:12 pluto[562]:    NAT-Traversal support  [disabled]
> 2011-07-18 11:59:12 pluto[562]: using /dev/urandom as source of random entropy
> 2011-07-18 11:59:12 pluto[562]: ike_alg_register_enc(): Activating OAKLEY_AES_CBC: Ok (ret=0)
> 2011-07-18 11:59:12 pluto[562]: no helpers will be started, all cryptographic operations will be done inline
> 2011-07-18 11:59:12 pluto[562]: Kernel interface auto-pick
> 2011-07-18 11:59:12 pluto[562]: Using Linux 2.6 IPsec interface code on 2.6.27_stm23_004 (experimental code)
> 2011-07-18 11:59:12 pluto[562]: ike_alg_register_enc(): Activating aes_ccm_8: Ok (ret=0)
> 2011-07-18 11:59:12 pluto[562]: ike_alg_add(): ERROR: Algorithm already exists
> 2011-07-18 11:59:12 pluto[562]: ike_alg_register_enc(): Activating aes_ccm_12: FAILED (ret=-17)
> 2011-07-18 11:59:12 pluto[562]: ike_alg_add(): ERROR: Algorithm already exists
> 2011-07-18 11:59:12 pluto[562]: ike_alg_register_enc(): Activating aes_ccm_16: FAILED (ret=-17)
> 2011-07-18 11:59:12 pluto[562]: ike_alg_add(): ERROR: Algorithm already exists
> 2011-07-18 11:59:12 pluto[562]: ike_alg_register_enc(): Activating aes_gcm_8: FAILED (ret=-17)
> 2011-07-18 11:59:12 pluto[562]: ike_alg_add(): ERROR: Algorithm already exists
> 2011-07-18 11:59:12 pluto[562]: ike_alg_register_enc(): Activating aes_gcm_12: FAILED (ret=-17)
> 2011-07-18 11:59:12 pluto[562]: ike_alg_add(): ERROR: Algorithm already exists
> 2011-07-18 11:59:12 pluto[562]: ike_alg_register_enc(): Activating aes_gcm_16: FAILED (ret=-17)
> 2011-07-18 11:59:12 pluto[562]: Changed path to directory '/etc/ipsec.d/cacerts'
> 2011-07-18 11:59:12 pluto[562]: Could not change to directory '/etc/ipsec.d/aacerts': /
> 2011-07-18 11:59:12 pluto[562]: Could not change to directory '/etc/ipsec.d/ocspcerts': /
> 2011-07-18 11:59:12 pluto[562]: Could not change to directory '/etc/ipsec.d/crls'
> 2011-07-18 11:59:13 pluto[562]: added connection description "ipsec1"
> 2011-07-18 11:59:13 pluto[562]: listening for IKE messages
> 2011-07-18 11:59:13 pluto[562]: adding interface ppp0/ppp0 10.0.3.114:500
> 2011-07-18 11:59:13 pluto[562]: adding interface eth0:1/eth0:1 192.168.2.151:500
> 2011-07-18 11:59:13 pluto[562]: adding interface eth0/eth0 192.168.3.151:500
> 2011-07-18 11:59:13 pluto[562]: loading secrets from "/etc/ipsec.d/ipsec.secrets"
> 2011-07-18 11:59:13 pluto[562]: "ipsec1" #1: initiating Main Mode
> 2011-07-18 11:59:13 pppd[528]: Script /etc/scripts/ip-up finished (pid 532), status = 0x0
> 2011-07-18 11:59:25 pluto[562]: "ipsec1" #1: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 11:59:25 pluto[562]: "ipsec1" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
> 2011-07-18 11:59:25 pluto[562]: "ipsec1" #1: STATE_MAIN_I2: sent MI2, expecting MR2
> 2011-07-18 11:59:25 pluto[562]: packet from 10.0.2.125:500: phase 1 message is part of an unknown exchange
> 2011-07-18 11:59:27 pluto[562]: "ipsec1" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
> 2011-07-18 11:59:27 pluto[562]: "ipsec1" #1: STATE_MAIN_I3: sent MI3, expecting MR3
> 2011-07-18 11:59:28 pluto[562]: "ipsec1" #1: Main mode peer ID is ID_IPV4_ADDR: '10.0.2.125'
> 2011-07-18 11:59:28 pluto[562]: "ipsec1" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
> 2011-07-18 11:59:28 pluto[562]: "ipsec1" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 11:59:28 pluto[562]: "ipsec1" #1: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:59:28 pluto[562]: "ipsec1" #2: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP {using isakmp#1 msgid:8bceb056 proposal=defaults
> pfsgroup=no-pfs}
> 2011-07-18 11:59:28 pluto[562]: "ipsec1" #2: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 11:59:28 pluto[562]: "ipsec1" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
> 2011-07-18 11:59:28 pluto[562]: "ipsec1" #2: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP=0x6dce16fa 0x0b056df3
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> 2011-07-18 11:59:38 pluto[562]: packet from 10.0.2.125:500: phase 1 message is part of an unknown exchange
> 2011-07-18 11:59:38 pluto[562]: "ipsec1" #2: retransmitting in response to duplicate packet; already STATE_QUICK_I2
> 2011-07-18 11:59:57 pluto[562]: packet from 10.0.2.125:500: phase 1 message is part of an unknown exchange
> 2011-07-18 11:59:58 pluto[562]: "ipsec1" #2: retransmitting in response to duplicate packet; already STATE_QUICK_I2
> 2011-07-18 12:00:40 pluto[562]: "ipsec1" #2: discarding duplicate packet -- exhausted retransmission; already STATE_QUICK_I2
> 2011-07-18 12:12:00 last message repeated 17 times
> 2011-07-18 12:43:30 pluto[562]: packet from 10.0.2.125:500: Informational Exchange is for an unknown (expired?) SA with MSGID:0xda76b0f3
> 2011-07-18 12:43:31 pluto[562]: "ipsec1" #1: ignoring Delete SA payload: PROTO_IPSEC_ESP SA(0x17354389) not found (maybe expired)
> 2011-07-18 12:43:31 pluto[562]: "ipsec1" #1: received and ignored informational message
> 2011-07-18 12:43:36 pluto[562]: "ipsec1" #1: ignoring Delete SA payload: PROTO_IPSEC_ESP SA(0x2d1cc833) not found (maybe expired)
> 2011-07-18 12:43:36 pluto[562]: "ipsec1" #1: received and ignored informational message
> 2011-07-18 12:43:36 pluto[562]: packet from 10.0.2.125:500: Informational Exchange is for an unknown (expired?) SA with MSGID:0xbc92b9a4
> 2011-07-18 12:44:26 pluto[562]: "ipsec1" #3: initiating Main Mode to replace #1
> 2011-07-18 12:44:28 pluto[562]: "ipsec1" #3: received Vendor ID payload [Dead Peer Detection]
> 2011-07-18 12:44:28 pluto[562]: "ipsec1" #3: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
> 2011-07-18 12:44:28 pluto[562]: "ipsec1" #3: STATE_MAIN_I2: sent MI2, expecting MR2
> 2011-07-18 12:44:30 pluto[562]: "ipsec1" #3: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
> 2011-07-18 12:44:30 pluto[562]: "ipsec1" #3: STATE_MAIN_I3: sent MI3, expecting MR3
> 2011-07-18 12:44:30 pluto[562]: "ipsec1" #3: Main mode peer ID is ID_IPV4_ADDR: '10.0.2.125'
> 2011-07-18 12:44:30 pluto[562]: "ipsec1" #3: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
> 2011-07-18 12:44:30 pluto[562]: "ipsec1" #3: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128
> prf=oakley_sha group=modp2048}
> 2011-07-18 12:44:30 pluto[562]: "ipsec1" #3: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 12:46:03 pluto[562]: "ipsec1" #4: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP to replace #2 {using isakmp#3 msgid:9888e44a
> proposal=defaults pfsgroup=no-pfs}
> 2011-07-18 12:46:05 pluto[562]: "ipsec1" #4: Dead Peer Detection (RFC 3706): enabled
> 2011-07-18 12:46:05 pluto[562]: "ipsec1" #4: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
> 2011-07-18 12:46:05 pluto[562]: "ipsec1" #4: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP=0xa13d3474 0xe8a79ed2
> xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
> 2011-07-18 12:48:21 pluto[562]: packet from 10.0.2.125:500: Informational Exchange is for an unknown (expired?) SA with MSGID:0x88fdae94
> 2011-07-18 12:48:21 pluto[562]: "ipsec1" #3: ignoring Delete SA payload: PROTO_IPSEC_ESP SA(0x32e9fe4f) not found (maybe expired)
> 2011-07-18 12:48:21 pluto[562]: "ipsec1" #3: received and ignored informational message
> 2011-07-18 12:55:18 pluto[562]: packet from 10.0.2.125:500: Informational Exchange is for an unknown (expired?) SA with MSGID:0x1dd8ee22
> 2011-07-18 12:55:18 pluto[562]: "ipsec1" #3: ignoring Delete SA payload: PROTO_IPSEC_ESP SA(0x1b084a6f) not found (maybe expired)
> 2011-07-18 12:55:18 pluto[562]: "ipsec1" #3: received and ignored informational message
> 2011-07-18 12:59:29 pluto[562]: packet from 10.0.2.125:500: Informational Exchange is for an unknown (expired?) SA with MSGID:0x7a8c1104
> 
>