[vpn-help] Temporary traffic stops while connected to Cisco VPN

Thu Dec 9 10:44:33 CST 2010

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.

>> 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.