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

Fri Dec 10 09:24:11 CST 2010

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
> vpn-help at lists.shrew.net
> http://lists.shrew.net/mailman/listinfo/vpn-help