[strongSwan] strongswan-4.2.8 have problem when nat-traversal need reconnected

Brian Zhao - 赵宪鹏 Brian.Zhao at zyxel.cn
Wed Sep 29 06:49:48 CEST 2010


Hi all,

I used strongswan-4.2.8, I find a strange thing, when I create a tunnel through an NATed device.

My topology like this:

Left vpn gateway-------------------------------NAT device-----------------------right vpn gateway 

192.168.2.34------------------------192.168.2.1||172.25.24.52-------------------172.25.24.216

 

The problem is like this: when the first time I can create the tunnel between left vpn gateway and right vpn gateway, it is OK. But when right vpn maybe have to restart or reload to use the latest configure file. After right vpn gateway restart, the tunnel cannot reconnect. And left have to execute “ipsec reload”(or something like this such as “ipsec restart”)to clean up something, then they can create a connection again.

 

I doubt maybe because of left ipsec status have not clean up after connection down cause this problem.

 

Do you have any solution to deal with this problem? Maybe I can add something like cleanup status when a connection down. Any suggestions? 

 

 

Right ipsec status result(before execute “ipsec reload”):

# ipsec status

000 "test": 192.168.3.0/24===172.25.24.216:4500[@moon.com]...172.25.24.52:10107[

@sun.com]===192.168.1.0/24; prospective erouted; eroute owner: #0

000 "test":   newest ISAKMP SA: #0; newest IPsec SA: #0;

000

000 #7: "test" STATE_MAIN_I1 (sent MI1, expecting MR1); EVENT_RETRANSMIT in 18s

000 #7: pending Phase 2 for "test" replacing #0

000

 

Left ipsec.conf:

config setup

     plutodebug=control

     nat_traversal=yes

 

#start conn test

conn test

     left=192.168.2.34

     leftid=@sun.com

     leftsubnet=192.168.1.1/24

     leftfirewall=yes

     right=172.25.24.216

     rightid=@moon.com

     rightsubnet=192.168.3.1/24

     ikelifetime=86400s

     keylife=3600s

     ike=3des-md5-modp1024!

     esp=3des-md5!

     dpdaction=hold

     dpddelay=60

     dpdtimeout=300

     pfs=no

     authby=secret

     keyexchange=ikev1

     leftsourceip=192.168.1.1

     auto=start

#end conn test

 

Right ipsec.conf:

config setup

     plutodebug=control

     nat_traversal=yes

 

#start conn test

conn test

     left=172.25.24.216

     leftid=@moon.com

     leftsubnet=192.168.3.1/24

     leftfirewall=yes

     right=172.25.24.52

     rightid=@sun.com

     rightsubnet=192.168.1.1/24

     ikelifetime=86400s

     keylife=3600s

     ike=3des-md5-modp1024!

     esp=3des-md5!

     dpdaction=hold

     dpddelay=60

     dpdtimeout=300

     pfs=no

     authby=secret

     keyexchange=ikev1

     leftsourceip=192.168.3.1

     auto=start

#end conn test

 

Left log:

Sep 29 04:34:34 authpriv.warning ipsec_starter: Starting strongSwan 4.2.8 IPsec

[starter]...

Sep 29 04:34:35 authpriv.warning pluto: Starting Pluto (strongSwan Version 4.2.8

 THREADS VENDORID)

Sep 29 04:34:35 authpriv.warning pluto: including NAT-Traversal patch (Version 0

.6c)

Sep 29 04:34:35 authpriv.debug pluto: | xauth module: using default get_secret()

 function

Sep 29 04:34:35 authpriv.debug pluto: | xauth module: using default verify_secre

t() function

Sep 29 04:34:35 authpriv.debug pluto: | inserting event EVENT_REINIT_SECRET, tim

eout in 3600 seconds

Sep 29 04:34:35 authpriv.warning pluto: ike_alg: Activating OAKLEY_AES_CBC encry

ption: Ok

Sep 29 04:34:35 authpriv.warning pluto: ike_alg: Activating OAKLEY_BLOWFISH_CBC

encryption: Ok

Sep 29 04:34:35 authpriv.warning pluto: ike_alg: Activating OAKLEY_SERPENT_CBC e

ncryption: Ok

Sep 29 04:34:35 authpriv.warning pluto: ike_alg: Activating OAKLEY_SHA2_256 hash

: Ok

Sep 29 04:34:35 authpriv.warning pluto: ike_alg: Activating OAKLEY_SHA2_384 hash

: Ok

Sep 29 04:34:35 authpriv.warning pluto: ike_alg: Activating OAKLEY_SHA2_512 hash

: Ok

Sep 29 04:34:35 authpriv.warning pluto: ike_alg: Activating OAKLEY_TWOFISH_CBC e

ncryption: Ok

Sep 29 04:34:35 authpriv.warning pluto: ike_alg: Activating OAKLEY_TWOFISH_CBC_S

SH encryption: Ok

Sep 29 04:34:35 authpriv.warning pluto: Testing registered IKE encryption algori

thms:

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_BLOWFISH_CBC self-test not availa

ble

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_3DES_CBC self-test not available

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_AES_CBC self-test not available

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SERPENT_CBC self-test not availab

le

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_TWOFISH_CBC self-test not availab

le

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_TWOFISH_CBC_SSH self-test not ava

ilable

Sep 29 04:34:35 authpriv.warning pluto: Testing registered IKE hash algorithms:

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_MD5 hash self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_MD5 hmac self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SHA hash self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SHA hmac self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SHA2_256 hash self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SHA2_256 hmac self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SHA2_384 hash self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SHA2_384 hmac self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SHA2_512 hash self-test passed

Sep 29 04:34:35 authpriv.warning pluto: OAKLEY_SHA2_512 hmac self-test passed

Sep 29 04:34:35 authpriv.warning pluto: All crypto self-tests passed

Sep 29 04:34:35 authpriv.warning pluto: Using Linux 2.6 IPsec interface code

Sep 29 04:34:35 authpriv.warning ipsec_starter: can't execv(/usr/local/libexec/i

psec/charon,...): No such file or directory

Sep 29 04:34:35 authpriv.warning pluto: Changing to directory '/etc/ipsec.d/cace

rts'

Sep 29 04:34:35 authpriv.warning pluto: Changing to directory '/etc/ipsec.d/aace

rts'

Sep 29 04:34:35 authpriv.warning pluto: Changing to directory '/etc/ipsec.d/ocsp

certs'

Sep 29 04:34:35 authpriv.warning pluto: Changing to directory '/etc/ipsec.d/crls

'

Sep 29 04:34:35 authpriv.warning pluto: Changing to directory '/etc/ipsec.d/acer

ts'

Sep 29 04:34:35 authpriv.debug pluto: | inserting event EVENT_LOG_DAILY, timeout

 in 69925 seconds

Sep 29 04:34:35 authpriv.debug pluto: | next event EVENT_REINIT_SECRET in 3600 s

econds

Sep 29 04:34:35 authpriv.debug pluto: |

Sep 29 04:34:35 authpriv.debug pluto: | *received whack message

Sep 29 04:34:35 authpriv.warning pluto: listening for IKE messages

Sep 29 04:34:35 authpriv.debug pluto: | found lo with address 127.0.0.1

Sep 29 04:34:35 authpriv.debug pluto: | found br0 with address 192.168.1.1

Sep 29 04:34:35 authpriv.debug pluto: | found nas1 with address 192.168.2.34

Sep 29 04:34:35 authpriv.warning pluto: adding interface nas1/nas1 192.168.2.34:

500

Sep 29 04:34:35 authpriv.warning pluto: adding interface nas1/nas1 192.168.2.34:

4500

Sep 29 04:34:35 authpriv.warning pluto: adding interface br0/br0 192.168.1.1:500

Sep 29 04:34:35 authpriv.warning pluto: adding interface br0/br0 192.168.1.1:450

0

Sep 29 04:34:35 authpriv.warning pluto: adding interface lo/lo 127.0.0.1:500

Sep 29 04:34:35 authpriv.warning pluto: adding interface lo/lo 127.0.0.1:4500

Sep 29 04:34:35 authpriv.debug pluto: | could not open /proc/net/if_inet6

Sep 29 04:34:35 authpriv.warning pluto: loading secrets from "/etc/ipsec.secrets

"

Sep 29 04:34:35 authpriv.warning pluto: loaded shared key for @moon.com @sun.com

 

Sep 29 04:34:35 authpriv.warning pluto: loaded xauth credentials of user '0'

Sep 29 04:34:35 authpriv.warning pluto: loaded xauth credentials of user '0'

Sep 29 04:34:35 authpriv.warning pluto: loaded xauth credentials of user '0'

Sep 29 04:34:35 authpriv.warning pluto: loaded xauth credentials of user '0'

Sep 29 04:34:35 authpriv.warning pluto: loaded xauth credentials of user '0'

Sep 29 04:34:35 authpriv.debug pluto: | next event EVENT_REINIT_SECRET in 3600 s

econds

Sep 29 04:34:50 authpriv.warning ipsec_starter: charon too long to start... - ki

ll kill

Sep 29 04:34:51 authpriv.warning ipsec_starter: connect(charon_ctl) failed: No s

uch file or directory

Sep 29 04:34:51 authpriv.debug pluto: |

Sep 29 04:34:51 authpriv.debug pluto: | *received whack message

Sep 29 04:34:51 authpriv.debug pluto: | from whack: got --esp=3des-md5!

Sep 29 04:34:51 authpriv.debug pluto: | esp string values: 3_000-1, strict

Sep 29 04:34:51 authpriv.debug pluto: | from whack: got --ike=3des-md5-modp1024!

Sep 29 04:34:51 authpriv.debug pluto: | ike string values: 5_000-1-2, strict

Sep 29 04:34:51 authpriv.warning pluto: added connection description "test"

Sep 29 04:34:51 authpriv.debug pluto: | 192.168.1.0/24===192.168.2.34[@sun.com].

..172.25.24.216[@moon.com]===192.168.3.0/24

Sep 29 04:34:51 authpriv.debug pluto: | ike_life: 86400s; ipsec_life: 3600s; rek

ey_margin: 540s; rekey_fuzz: 100%; keyingtries: 3; policy: PSK+ENCRYPT+TUNNEL

Sep 29 04:34:51 authpriv.debug pluto: | next event EVENT_REINIT_SECRET in 3584 s

econds

Sep 29 04:34:51 authpriv.debug pluto: |

Sep 29 04:34:51 authpriv.debug pluto: | *received whack message

Sep 29 04:34:51 authpriv.debug pluto: | creating state object #1 at 0x523d50

Sep 29 04:34:51 authpriv.debug pluto: | ICOOKIE:  61 1a e6 ab  ba e8 9a 19

Sep 29 04:34:51 authpriv.debug pluto: | RCOOKIE:  00 00 00 00  00 00 00 00

Sep 29 04:34:51 authpriv.debug pluto: | peer:  ac 19 18 d8

Sep 29 04:34:51 authpriv.debug pluto: | state hash entry 16

Sep 29 04:34:51 authpriv.debug pluto: | inserting event EVENT_SO_DISCARD, timeou

t in 0 seconds for #1

Sep 29 04:34:51 authpriv.debug pluto: | Queuing pending Quick Mode with 172.25.2

4.216 "test"

Sep 29 04:34:51 authpriv.warning pluto: "test" #1: initiating Main Mode

Sep 29 04:34:51 authpriv.debug pluto: | 5_000-1-2, strict

Sep 29 04:34:51 authpriv.debug pluto: | inserting event EVENT_RETRANSMIT, timeou

t in 10 seconds for #1

Sep 29 04:34:51 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 10 second

s for #1

Sep 29 04:34:56 authpriv.warning ipsec_starter: connect(charon_ctl) failed: No s

uch file or directory

Sep 29 04:34:56 authpriv.debug pluto: |

Sep 29 04:34:56 authpriv.debug pluto: | *received whack message

Sep 29 04:34:56 authpriv.warning pluto: attempt to redefine connection "test"

Sep 29 04:34:56 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 5 seconds

 for #1

Sep 29 04:34:56 authpriv.debug pluto: |

Sep 29 04:34:56 authpriv.debug pluto: | *received whack message

Sep 29 04:34:56 authpriv.debug pluto: | Queuing pending Quick Mode with 172.25.2

4.216 "test" already done

Sep 29 04:34:56 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 5 seconds

 for #1

Sep 29 04:35:01 authpriv.debug pluto: |

Sep 29 04:35:01 authpriv.debug pluto: | *time to handle event

Sep 29 04:35:01 authpriv.debug pluto: | event after this is EVENT_REINIT_SECRET

in 3574 seconds

Sep 29 04:35:01 authpriv.debug pluto: | handling event EVENT_RETRANSMIT for 172.

25.24.216 "test" #1

Sep 29 04:35:01 authpriv.debug pluto: | inserting event EVENT_RETRANSMIT, timeou

t in 20 seconds for #1

Sep 29 04:35:01 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 20 second

s for #1

Sep 29 04:35:21 authpriv.debug pluto: |

Sep 29 04:35:21 authpriv.debug pluto: | *time to handle event

Sep 29 04:35:21 authpriv.debug pluto: | event after this is EVENT_REINIT_SECRET

in 3554 seconds

Sep 29 04:35:21 authpriv.debug pluto: | handling event EVENT_RETRANSMIT for 172.

25.24.216 "test" #1

Sep 29 04:35:21 authpriv.debug pluto: | inserting event EVENT_RETRANSMIT, timeou

t in 40 seconds for #1

Sep 29 04:35:21 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 40 second

s for #1

#

 

 

 

Right log:

Sep 29 04:26:08 authpriv.debug pluto: |

Sep 29 04:26:08 authpriv.debug pluto: | *time to handle event

Sep 29 04:26:08 authpriv.debug pluto: | event after this is EVENT_REINIT_SECRET

in 3340 seconds

Sep 29 04:26:08 authpriv.debug pluto: | handling event EVENT_RETRANSMIT for 172.

25.24.52 "test" #8

Sep 29 04:26:08 authpriv.debug pluto: | inserting event EVENT_RETRANSMIT, timeou

t in 20 seconds for #8

Sep 29 04:26:08 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 20 second

s for #8

Sep 29 04:26:22 authpriv.debug pluto: |

Sep 29 04:26:22 authpriv.debug pluto: | *received 236 bytes from 172.25.24.52:50

0 on nas1

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [strongSwan 4.2.8]

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [XAUTH]

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [Dead Peer Detection]

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [RFC 3947]

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-03]

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-02]

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-00]

Sep 29 04:26:22 authpriv.debug pluto: | preparse_isakmp_policy: peer requests PS

K authentication

Sep 29 04:26:22 authpriv.warning pluto: packet from 172.25.24.52:500: initial Ma

in Mode message received on 172.25.24.216:500 but no connection has been authori

zed with policy=PSK

Sep 29 04:26:22 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 6 seconds

 for #8

Sep 29 04:26:28 authpriv.debug pluto: |

Sep 29 04:26:28 authpriv.debug pluto: | *time to handle event

Sep 29 04:26:28 authpriv.debug pluto: | event after this is EVENT_REINIT_SECRET

in 3320 seconds

Sep 29 04:26:28 authpriv.debug pluto: | handling event EVENT_RETRANSMIT for 172.

25.24.52 "test" #8

Sep 29 04:26:28 authpriv.debug pluto: | inserting event EVENT_RETRANSMIT, timeou

t in 40 seconds for #8

Sep 29 04:26:28 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 40 second

s for #8

Sep 29 04:26:32 authpriv.debug pluto: |

Sep 29 04:26:32 authpriv.debug pluto: | *received 236 bytes from 172.25.24.52:50

0 on nas1

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [strongSwan 4.2.8]

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [XAUTH]

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [Dead Peer Detection]

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [RFC 3947]

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-03]

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-02]

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-00]

Sep 29 04:26:32 authpriv.debug pluto: | preparse_isakmp_policy: peer requests PS

K authentication

Sep 29 04:26:32 authpriv.warning pluto: packet from 172.25.24.52:500: initial Ma

in Mode message received on 172.25.24.216:500 but no connection has been authori

zed with policy=PSK

Sep 29 04:26:32 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 36 second

s for #8

Sep 29 04:26:52 authpriv.debug pluto: |

Sep 29 04:26:52 authpriv.debug pluto: | *received 236 bytes from 172.25.24.52:50

0 on nas1

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [strongSwan 4.2.8]

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [XAUTH]

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [Dead Peer Detection]

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: received V

endor ID payload [RFC 3947]

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-03]

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-02]

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: ignoring V

endor ID payload [draft-ietf-ipsec-nat-t-ike-00]

Sep 29 04:26:52 authpriv.debug pluto: | preparse_isakmp_policy: peer requests PS

K authentication

Sep 29 04:26:52 authpriv.warning pluto: packet from 172.25.24.52:500: initial Ma

in Mode message received on 172.25.24.216:500 but no connection has been authori

zed with policy=PSK

Sep 29 04:26:52 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 16 second

s for #8

Sep 29 04:27:08 authpriv.debug pluto: |

Sep 29 04:27:08 authpriv.debug pluto: | *time to handle event

Sep 29 04:27:08 authpriv.debug pluto: | event after this is EVENT_REINIT_SECRET

in 3280 seconds

Sep 29 04:27:08 authpriv.debug pluto: | handling event EVENT_RETRANSMIT for 172.

25.24.52 "test" #8

Sep 29 04:27:08 authpriv.warning pluto: "test" #8: max number of retransmissions

 (2) reached STATE_MAIN_I1.  No response (or no acceptable response) to our firs

t IKE message

Sep 29 04:27:08 authpriv.warning pluto: "test" #8: starting keying attempt 3 of

at most 3

Sep 29 04:27:08 authpriv.debug pluto: | creating state object #9 at 0x523d50

Sep 29 04:27:08 authpriv.debug pluto: | ICOOKIE:  24 e7 b2 43  4c dd 88 a2

Sep 29 04:27:08 authpriv.debug pluto: | RCOOKIE:  00 00 00 00  00 00 00 00

Sep 29 04:27:08 authpriv.debug pluto: | peer:  ac 19 18 34

Sep 29 04:27:08 authpriv.debug pluto: | state hash entry 24

Sep 29 04:27:08 authpriv.debug pluto: | inserting event EVENT_SO_DISCARD, timeou

t in 0 seconds for #9

Sep 29 04:27:08 authpriv.warning pluto: "test" #9: initiating Main Mode to repla

ce #8

Sep 29 04:27:08 authpriv.debug pluto: | 5_000-1-2, strict

Sep 29 04:27:08 authpriv.debug pluto: | inserting event EVENT_RETRANSMIT, timeou

t in 10 seconds for #9

Sep 29 04:27:08 authpriv.debug pluto: | ICOOKIE:  9a 2f c0 b8  5b 30 d3 a2

Sep 29 04:27:08 authpriv.debug pluto: | RCOOKIE:  00 00 00 00  00 00 00 00

Sep 29 04:27:08 authpriv.debug pluto: | peer:  ac 19 18 34

Sep 29 04:27:08 authpriv.debug pluto: | state hash entry 26

Sep 29 04:27:08 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 10 second

s for #9

Sep 29 04:27:10 authpriv.debug pluto: |

Sep 29 04:27:10 authpriv.debug pluto: | *received whack message

Sep 29 04:27:10 authpriv.debug pluto: | next event EVENT_RETRANSMIT in 8 seconds

 for #9

#

 

 

 

 

 

===================

Best regards,

Brian zhao| 赵宪鹏#15138

msn:brian_zhao1987 at hotmail.com

 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20100929/e79de95c/attachment.html>


More information about the Users mailing list