On 12/9/2010 11:44, Jochen De Smet wrote:
On 12/3/2010 17:40, Matthew Grooms wrote:
On 11/29/2010 9:44 AM, Jochen De Smet wrote:
I'm not 100% sure what kind of Cisco is on the other side; I configured
shrew
by importing the .pfc file. Here's a summary of the config options:
- general: hostname and port set, auto config set to "ike config pull"
- client: NAT traversal enabled, keep-alive packet rate 15 secs, ike
fragmentation disabled, all "other options" checked
- phase1: aggressive, group2, auto, key life time limit 86400 secs, 0
data lmit
- phase2: auto, auto, auto, compress disabled, key life time limit 3600
secs, 0 data limit
Symptom:
Sometimes all VPN traffic stops for a minute or so, then after that
things usually work again.
When looking at the "Network" tab of the established connection, it
seem
to always show
the number of establish associations as (expired + 2). Then after a
while expired increases
by 1 and that's when things work again.
I'm not sure if it's related, but the shrew client also appears to take
a lot longer to enable the
initial tunnel than the cisco client ( +-30 seconds vs +-3 seconds)
I'm not sure about this. Do you have any debug log output that shows
this problem happening?
Relevant IKE log part:
10/12/09 11:30:50 ii : phase2 sa will expire in 721 seconds
10/12/09 11:30:50 DB : policy found
10/12/09 11:30:50 DB : policy found
10/12/09 11:30:50 DB : tunnel found
10/12/09 11:30:50 DB : new phase2 ( IPSEC initiator )
10/12/09 11:30:50 DB : phase2 added ( obj count = 2 )
10/12/09 11:30:50 K> : send pfkey GETSPI ESP message
10/12/09 11:30:50 K< : recv pfkey GETSPI ESP message
10/12/09 11:30:50 DB : phase2 found
10/12/09 11:30:50 ii : updated spi for 1 ipsec-esp proposal
10/12/09 11:30:50 DB : phase1 found
10/12/09 11:30:50 >> : hash payload
10/12/09 11:30:50 >> : security association payload
10/12/09 11:30:50 >> : - proposal #1 payload
10/12/09 11:30:50 >> : -- transform #1 payload
10/12/09 11:30:50 >> : -- transform #2 payload
10/12/09 11:30:50 >> : -- transform #3 payload
10/12/09 11:30:50 >> : -- transform #4 payload
10/12/09 11:30:50 >> : -- transform #5 payload
10/12/09 11:30:50 >> : -- transform #6 payload
10/12/09 11:30:50 >> : -- transform #7 payload
10/12/09 11:30:50 >> : -- transform #8 payload
10/12/09 11:30:50 >> : -- transform #9 payload
10/12/09 11:30:50 >> : -- transform #10 payload
10/12/09 11:30:50 >> : -- transform #11 payload
10/12/09 11:30:50 >> : -- transform #12 payload
10/12/09 11:30:50 >> : -- transform #13 payload
10/12/09 11:30:50 >> : -- transform #14 payload
10/12/09 11:30:50 >> : -- transform #15 payload
10/12/09 11:30:50 >> : -- transform #16 payload
10/12/09 11:30:50 >> : -- transform #17 payload
10/12/09 11:30:50 >> : -- transform #18 payload
10/12/09 11:30:50 >> : nonce payload
10/12/09 11:30:50 >> : identification payload
10/12/09 11:30:50 >> : identification payload
10/12/09 11:30:50 == : phase2 hash_i ( input ) ( 632 bytes )
10/12/09 11:30:50 == : phase2 hash_i ( computed ) ( 20 bytes )
10/12/09 11:30:50 == : new phase2 iv ( 8 bytes )
10/12/09 11:30:50 >= : cookies 8fab8c4c0a2f9e34:7e8ca193d1179cbb
10/12/09 11:30:50 >= : message 8998c1c3
10/12/09 11:30:50 >= : encrypt iv ( 8 bytes )
10/12/09 11:30:50 == : encrypt packet ( 680 bytes )
10/12/09 11:30:50 == : stored iv ( 8 bytes )
10/12/09 11:30:50 -> : send IKE packet xxxxxxxx:500 -> xxxxxxxx:500 (
712 bytes )
10/12/09 11:30:50 DB : phase2 resend event scheduled ( ref count = 2 )
10/12/09 11:30:50 <- : recv IKE packet xxxxxxxx:500 -> xxxxxxxx:500 (
156 bytes )
10/12/09 11:30:50 DB : phase1 found
10/12/09 11:30:50 ii : processing phase2 packet ( 156 bytes )
10/12/09 11:30:50 DB : phase2 found
10/12/09 11:30:50 =< : cookies 8fab8c4c0a2f9e34:7e8ca193d1179cbb
10/12/09 11:30:50 =< : message 8998c1c3
10/12/09 11:30:50 =< : decrypt iv ( 8 bytes )
10/12/09 11:30:50 == : decrypt packet ( 156 bytes )
10/12/09 11:30:50 <= : trimmed packet padding ( 4 bytes )
10/12/09 11:30:50 <= : stored iv ( 8 bytes )
10/12/09 11:30:50 << : hash payload
10/12/09 11:30:50 << : security association payload
10/12/09 11:30:50 << : - propsal #1 payload
10/12/09 11:30:50 << : -- transform #14 payload
10/12/09 11:30:50 << : nonce payload
10/12/09 11:30:50 << : identification payload
10/12/09 11:30:50 << : identification payload
10/12/09 11:30:50 == : phase2 hash_r ( input ) ( 124 bytes )
10/12/09 11:30:50 == : phase2 hash_r ( computed ) ( 20 bytes )
10/12/09 11:30:50 == : phase2 hash_r ( received ) ( 20 bytes )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-aes )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-aes )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-aes )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-aes )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-aes )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-aes )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-blowfish )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-blowfish )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-blowfish )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-blowfish )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-blowfish )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : crypto transform type ( esp-3des != esp-blowfish )
10/12/09 11:30:50 ii : unmatched ipsec-esp proposal/transform
10/12/09 11:30:50 ii : msg auth ( hmac-sha != hmac-md5 )
10/12/09 11:30:50 ii : matched ipsec-esp proposal #1 transform #14
10/12/09 11:30:50 ii : - transform = esp-3des
10/12/09 11:30:50 ii : - key length = default
10/12/09 11:30:50 ii : - encap mode = tunnel
10/12/09 11:30:50 ii : - msg auth = hmac-sha
10/12/09 11:30:50 ii : - pfs dh group = none
10/12/09 11:30:50 ii : - life seconds = 3600
10/12/09 11:30:50 ii : - life kbytes = 0
10/12/09 11:30:50 DB : policy found
10/12/09 11:30:50 K> : send pfkey GETSPI ESP message
10/12/09 11:30:50 ii : phase2 ids accepted
10/12/09 11:30:50 ii : - loc ANY:xxxxxxxx:* -> ANY:0.0.0.0/0:*
10/12/09 11:30:50 ii : - rmt ANY:0.0.0.0/0:* -> ANY:xxxxxxxx:*
10/12/09 11:30:50 ii : phase2 sa established
10/12/09 11:30:50 ii : xxxxxxxx:500 <-> xxxxxxxx:500
10/12/09 11:30:50 == : phase2 hash_p ( input ) ( 41 bytes )
10/12/09 11:30:50 == : phase2 hash_p ( computed ) ( 20 bytes )
10/12/09 11:30:50 >> : hash payload
10/12/09 11:30:50 K< : recv pfkey GETSPI ESP message
10/12/09 11:30:50 >= : cookies 8fab8c4c0a2f9e34:7e8ca193d1179cbb
10/12/09 11:30:50 DB : phase2 found
10/12/09 11:30:50 >= : message 8998c1c3
10/12/09 11:30:50 >= : encrypt iv ( 8 bytes )
10/12/09 11:30:50 == : encrypt packet ( 52 bytes )
10/12/09 11:30:50 == : stored iv ( 8 bytes )
10/12/09 11:30:50 DB : phase2 resend event canceled ( ref count = 1 )
10/12/09 11:30:50 -> : send IKE packet xxxxxxxx:500 -> xxxxxxxx:500 (
80 bytes )
10/12/09 11:30:50 == : spi cipher key data ( 24 bytes )
10/12/09 11:30:50 == : spi hmac key data ( 20 bytes )
10/12/09 11:30:50 K> : send pfkey UPDATE ESP message
10/12/09 11:30:50 == : spi cipher key data ( 24 bytes )
10/12/09 11:30:50 == : spi hmac key data ( 20 bytes )
10/12/09 11:30:50 K< : recv pfkey UPDATE ESP message
10/12/09 11:30:50 K> : send pfkey UPDATE ESP message
10/12/09 11:30:50 K< : recv pfkey UPDATE ESP message
10/12/09 11:31:22 <- : recv IKE packet xxxxxxxx:500 -> xxxxxxxx:500 (
68 bytes )
10/12/09 11:31:22 DB : phase1 found
10/12/09 11:31:22 ii : processing informational packet ( 68 bytes )
10/12/09 11:31:22 == : new informational iv ( 8 bytes )
10/12/09 11:31:22 =< : cookies 8fab8c4c0a2f9e34:7e8ca193d1179cbb
10/12/09 11:31:22 =< : message 367da8ce
10/12/09 11:31:22 =< : decrypt iv ( 8 bytes )
10/12/09 11:31:22 == : decrypt packet ( 68 bytes )
10/12/09 11:31:22 <= : stored iv ( 8 bytes )
10/12/09 11:31:22 << : hash payload
10/12/09 11:31:22 << : delete payload
10/12/09 11:31:22 == : informational hash_i ( computed ) ( 20 bytes )
10/12/09 11:31:22 == : informational hash_c ( received ) ( 20 bytes )
10/12/09 11:31:22 ii : informational hash verified
10/12/09 11:31:22 ii : received peer DELETE message
10/12/09 11:31:22 ii : - xxxxxxxx:500 -> xxxxxxxx:500
10/12/09 11:31:22 ii : - ipsec-esp spi = 0x588e1e53
10/12/09 11:31:22 DB : phase2 found
10/12/09 11:31:22 DB : cleanup, marked phase2 0x588e1e53 for removal
10/12/09 11:31:22 DB : phase2 hard event canceled ( ref count = 1 )
10/12/09 11:31:22 K> : send pfkey DELETE ESP message
10/12/09 11:31:22 K> : send pfkey DELETE ESP message
10/12/09 11:31:22 ii : phase2 removal before expire time
10/12/09 11:31:22 DB : phase2 deleted ( obj count = 1 )
10/12/09 11:31:22 K< : recv pfkey DELETE ESP message
10/12/09 11:31:22 K< : recv pfkey DELETE ESP message
I think the issue happens in the 11:30:50 -> 11:31:22 timeframe;
during that time
the security associations tab shows the new ones as mature, and the
old one as
"dying". Once the dying one gets removed traffic starts flowing again.
And a little more detail. During this time, the "Security Associations"
tab shows, as I said, two DYING ones (one in each direction) which are
not seeing any increase in traffic anymore, and two MATURE ones; the
one from gateway -> client receives a few KB of traffic (7-15 or so),
while no traffic at all is going over the client -> gateway one.
As soon as the DYING ones disappear, traffic in both directions picks
up on the MATURE ones.
In the current instance, the DYING connections are now up to 3200/3600
seconds, and the MATURE ones are at 300/3600, with still no
connectivity. Usually things are back to normal by the time the new
MATURE ones hit 40/3600, so I'll likely have to reconnect on this one.
Any idea what the problem is or what to do about it? It's a bit
annoying
since the pause is usually long
enough to make my ssh sessions disconnect.
Have you noticed that the traffic passing correctly at a specific
time after the tunnel has been established? It could be that you have
a pahse2 timeout mismatch between the client and the gateway. To test
the client in my lab, I set it to use 60sec IPsec SA's to ensure that
it works well during phase2 rekeys. However, your cisco gateway may
be configured to behave differently, allowing a phase2 lifetime
mismatch to occur.
From the above debug log I'd say this isn't the issue, but then again
I might be misinterpreting it.
My other guess is that there is a firewall state expiring for the UDP
port mapping. Have you tried forcing NAT-T to enable to see if it has
an effect? The reason I suggest this is that keepalive messages
aren't sent unless NAT is detected and NAT-T is enabled.
I have not tried this. I do however have plenty of traffic going
including an ssh connection which sends keepalives every minute; I'd
expect that to be enough to keep any mappings alive. I can try and
enable NAT-T to see if it helps though.
-Matthew
J.
_______________________________________________
vpn-help mailing list
[email protected]
http://lists.shrew.net/mailman/listinfo/vpn-help
_______________________________________________
vpn-help mailing list
[email protected]
http://lists.shrew.net/mailman/listinfo/vpn-help
