[vpn-help] SAs expire immediately, connecting to Juniper SSG via Shrew

[Tim Keane]

I am attempting to configure a dialup IPSec VPN from the Shrew VPN client to a
Juniper SSG320.

This dialup VPN connection works using the NCP Secure Client - Juniper Edition.

When I attempt to connect using Shrew, Phase1 and Phase2 negotiations are
completed successfully.  However, the SAs immediately expire.  This is happening
using Shrew v. 2.1.7 and 2.2.0, on both XP and Win7 client computers.


>From what I can gather, here is the relevant part of the Trace Log:

11/10/27 15:01:47 !! : peer violates RFC, transform number mismatch ( 1 != 12 )
11/10/27 15:01:47 !! : peer violates RFC, transform number mismatch ( 1 != 12 )
11/10/27 15:01:47 ii : matched ipsec-esp proposal #1 transform #12
11/10/27 15:01:47 ii : - transform    = esp-aes
11/10/27 15:01:47 ii : - key length   = 128 bits
11/10/27 15:01:47 ii : - encap mode   = tunnel
11/10/27 15:01:47 ii : - msg auth     = hmac-sha1
11/10/27 15:01:47 ii : - pfs dh group = group2 ( modp-1024 )
11/10/27 15:01:47 ii : - life seconds = 3600
11/10/27 15:01:47 ii : - life kbytes  = 0
11/10/27 15:01:47 ii : matched ipsec-esp proposal #1 transform #12
11/10/27 15:01:47 ii : - transform    = esp-aes
11/10/27 15:01:47 ii : - key length   = 128 bits
11/10/27 15:01:47 ii : - encap mode   = tunnel
11/10/27 15:01:47 ii : - msg auth     = hmac-sha1
11/10/27 15:01:47 ii : - pfs dh group = group2 ( modp-1024 )
11/10/27 15:01:47 ii : - life seconds = 3600
11/10/27 15:01:47 ii : - life kbytes  = 0
11/10/27 15:01:47 DB : policy found
11/10/27 15:01:47 DB : policy found
11/10/27 15:01:47 K> : send pfkey GETSPI ESP message
11/10/27 15:01:47 ii : phase2 ids accepted
11/10/27 15:01:47 ii : - loc ANY:192.168.107.3:* -> ANY:192.168.100.2:*
11/10/27 15:01:47 ii : - rmt ANY:192.168.100.2:* -> ANY:192.168.107.3:*
11/10/27 15:01:47 ii : phase2 sa established
11/10/27 15:01:47 ii : 1.2.3.112:500 <-> 1.2.3.8:500
11/10/27 15:01:47 K> : send pfkey GETSPI ESP message
11/10/27 15:01:47 ii : phase2 ids accepted
11/10/27 15:01:47 ii : - loc ANY:192.168.107.3:* -> ANY:192.168.100.2:*
11/10/27 15:01:47 ii : - rmt ANY:192.168.100.2:* -> ANY:192.168.107.3:*
11/10/27 15:01:47 ii : phase2 sa established
11/10/27 15:01:47 ii : 1.2.3.112:500 <-> 1.2.3.8:500
11/10/27 15:01:47 == : phase2 hash_p ( input ) ( 57 bytes )
11/10/27 15:01:47 == : phase2 hash_p ( computed ) ( 20 bytes )
11/10/27 15:01:47 == : phase2 hash_p ( input ) ( 57 bytes )
11/10/27 15:01:47 == : phase2 hash_p ( computed ) ( 20 bytes )
11/10/27 15:01:47 >> : hash payload
11/10/27 15:01:47 >> : hash payload
11/10/27 15:01:47 >= : cookies 4499bbb0562699ec:5cc749d6ada60baf
11/10/27 15:01:47 >= : message 7196e317
11/10/27 15:01:47 >= : encrypt iv ( 16 bytes )
11/10/27 15:01:47 == : encrypt packet ( 52 bytes )
11/10/27 15:01:47 >= : cookies 4499bbb0562699ec:5cc749d6ada60baf
11/10/27 15:01:47 >= : message 7196e317
11/10/27 15:01:47 >= : encrypt iv ( 16 bytes )
11/10/27 15:01:47 == : encrypt packet ( 52 bytes )
11/10/27 15:01:47 K< : recv pfkey GETSPI ESP message
11/10/27 15:01:47 K< : recv pfkey GETSPI ESP message
11/10/27 15:01:47 == : stored iv ( 16 bytes )
11/10/27 15:01:47 == : stored iv ( 16 bytes )
11/10/27 15:01:47 DB : phase2 resend event canceled ( ref count = 1 )
11/10/27 15:01:47 DB : phase2 resend event canceled ( ref count = 1 )
11/10/27 15:01:47 -> : send IKE packet 1.2.3.112:500 -> 1.2.3.8:500 ( 88 bytes)
11/10/27 15:01:47 -> : send IKE packet 1.2.3.112:500 -> 1.2.3.8:500 ( 88 bytes)
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 == : PFS DH shared secret ( 128 bytes )
11/10/27 15:01:47 == : spi cipher key data ( 16 bytes )
11/10/27 15:01:47 == : spi hmac key data ( 20 bytes )
11/10/27 15:01:47 == : PFS DH shared secret ( 128 bytes )
11/10/27 15:01:47 == : spi cipher key data ( 16 bytes )
11/10/27 15:01:47 == : spi hmac key data ( 20 bytes )
11/10/27 15:01:47 K> : send pfkey UPDATE ESP message
11/10/27 15:01:47 K> : send pfkey UPDATE ESP message
11/10/27 15:01:47 == : spi cipher key data ( 16 bytes )
11/10/27 15:01:47 == : spi hmac key data ( 20 bytes )
11/10/27 15:01:47 == : spi cipher key data ( 16 bytes )
11/10/27 15:01:47 == : spi hmac key data ( 20 bytes )
11/10/27 15:01:47 K> : send pfkey UPDATE ESP message
11/10/27 15:01:47 K< : recv pfkey UPDATE ESP message
11/10/27 15:01:47 K> : send pfkey UPDATE ESP message
11/10/27 15:01:47 K< : recv pfkey UPDATE ESP message
11/10/27 15:01:47 <- : recv IKE packet 1.2.3.8:500 -> 1.2.3.112:500 ( 76 bytes )
11/10/27 15:01:47 <- : recv IKE packet 1.2.3.8:500 -> 1.2.3.112:500 ( 76 bytes )
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 ii : processing phase2 packet ( 76 bytes )
11/10/27 15:01:47 ii : processing phase2 packet ( 76 bytes )
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 !! : phase2 packet ignored, resending last packet ( phase2
already mature )
11/10/27 15:01:47 !! : phase2 packet ignored, resending last packet ( phase2
already mature )
11/10/27 15:01:47 -> : resend 1 phase2 packet(s) [0/2] 1.2.3.112:500 ->
 1.2.3.8:500
11/10/27 15:01:47 <- : recv IKE packet 1.2.3.8:500 -> 1.2.3.112:500 ( 76 bytes )
11/10/27 15:01:47 -> : resend 1 phase2 packet(s) [0/2] 1.2.3.112:500 ->
 1.2.3.8:500
11/10/27 15:01:47 <- : recv IKE packet 1.2.3.8:500 -> 1.2.3.112:500 ( 76 bytes )
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 ii : processing phase2 packet ( 76 bytes )
11/10/27 15:01:47 ii : processing phase2 packet ( 76 bytes )
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 !! : phase2 packet ignored, resending last packet ( phase2
already mature )
11/10/27 15:01:47 !! : phase2 packet ignored, resending last packet ( phase2
already mature )
11/10/27 15:01:47 -> : resend 1 phase2 packet(s) [1/2] 1.2.3.112:500 -> 
1.2.3.8:500
11/10/27 15:01:47 <- : recv IKE packet 1.2.3.8:500 -> 1.2.3.112:500 ( 76 bytes )
11/10/27 15:01:47 -> : resend 1 phase2 packet(s) [1/2] 1.2.3.112:500 -> 
1.2.3.8:500
11/10/27 15:01:47 <- : recv IKE packet 1.2.3.8:500 -> 1.2.3.112:500 ( 76 bytes )
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 ii : processing phase2 packet ( 76 bytes )
11/10/27 15:01:47 ii : processing phase2 packet ( 76 bytes )
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 !! : phase2 packet ignored, resending last packet ( phase2
already mature )
11/10/27 15:01:47 !! : phase2 packet ignored, resending last packet ( phase2
already mature )
11/10/27 15:01:47 -> : resend 1 phase2 packet(s) [2/2] 1.2.3.112:500 -> 
1.2.3.8:500
11/10/27 15:01:47 -> : resend 1 phase2 packet(s) [2/2] 1.2.3.112:500 -> 
1.2.3.8:500
11/10/27 15:01:47 K< : recv pfkey UPDATE ESP message
11/10/27 15:01:47 K< : recv pfkey UPDATE ESP message
11/10/27 15:01:47 <- : recv IKE packet 1.2.3.8:500 -> 1.2.3.112:500 ( 76 bytes )
11/10/27 15:01:47 <- : recv IKE packet 1.2.3.8:500 -> 1.2.3.112:500 ( 76 bytes )
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 ii : processing phase2 packet ( 76 bytes )
11/10/27 15:01:47 ii : processing phase2 packet ( 76 bytes )
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 DB : phase2 found
11/10/27 15:01:47 !! : phase2 packet ignored, resending last packet ( phase2
already mature )
11/10/27 15:01:47 !! : phase2 packet ignored, resending last packet ( phase2
already mature )
11/10/27 15:01:47 ii : resend limit exceeded for phase2 exchange
11/10/27 15:01:47 ii : resend limit exceeded for phase2 exchange
11/10/27 15:01:47 DB : phase2 soft event canceled ( ref count = 2 )
11/10/27 15:01:47 DB : phase2 hard event canceled ( ref count = 1 )
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 DB : phase2 soft event canceled ( ref count = 2 )
11/10/27 15:01:47 DB : phase2 hard event canceled ( ref count = 1 )
11/10/27 15:01:47 DB : phase1 found
11/10/27 15:01:47 ii : sending peer DELETE message
11/10/27 15:01:47 ii : - 1.2.3.112:500 -> 1.2.3.8:500
11/10/27 15:01:47 ii : - ipsec-esp spi = 0x6e860a46
11/10/27 15:01:47 ii : - data size 0
11/10/27 15:01:47 ii : sending peer DELETE message
11/10/27 15:01:47 ii : - 1.2.3.112:500 -> 1.2.3.8:500
11/10/27 15:01:47 ii : - ipsec-esp spi = 0x6e860a46
11/10/27 15:01:47 ii : - data size 0
11/10/27 15:01:47 >> : hash payload
11/10/27 15:01:47 >> : delete payload
11/10/27 15:01:47 >> : hash payload
11/10/27 15:01:47 >> : delete payload
11/10/27 15:01:47 == : new informational hash ( 20 bytes )
11/10/27 15:01:47 == : new informational iv ( 16 bytes )
11/10/27 15:01:47 >= : cookies 4499bbb0562699ec:5cc749d6ada60baf
11/10/27 15:01:47 >= : message 29d83950
11/10/27 15:01:47 >= : encrypt iv ( 16 bytes )
11/10/27 15:01:47 == : encrypt packet ( 68 bytes )
11/10/27 15:01:47 == : stored iv ( 16 bytes )
11/10/27 15:01:47 == : new informational hash ( 20 bytes )
11/10/27 15:01:47 == : new informational iv ( 16 bytes )
11/10/27 15:01:47 >= : cookies 4499bbb0562699ec:5cc749d6ada60baf
11/10/27 15:01:47 >= : message 29d83950
11/10/27 15:01:47 >= : encrypt iv ( 16 bytes )
11/10/27 15:01:47 == : encrypt packet ( 68 bytes )
11/10/27 15:01:47 == : stored iv ( 16 bytes )
11/10/27 15:01:47 -> : send IKE packet 1.2.3.112:500 -> 1.2.3.8:500 ( 104 bytes )
11/10/27 15:01:47 -> : send IKE packet 1.2.3.112:500 -> 1.2.3.8:500 ( 104 bytes )
11/10/27 15:01:47 K> : send pfkey DELETE ESP message
11/10/27 15:01:47 K> : send pfkey DELETE ESP message
11/10/27 15:01:47 ii : phase2 removal before expire time
11/10/27 15:01:47 K> : send pfkey DELETE ESP message
11/10/27 15:01:47 K> : send pfkey DELETE ESP message
11/10/27 15:01:47 ii : phase2 removal before expire time
11/10/27 15:01:47 DB : phase2 deleted ( obj count = 0 )
11/10/27 15:01:47 DB : phase2 deleted ( obj count = 0 )
11/10/27 15:01:47 K< : recv pfkey DELETE ESP message
11/10/27 15:01:47 K< : recv pfkey DELETE ESP message
11/10/27 15:01:47 K< : recv pfkey DELETE ESP message
11/10/27 15:01:47 K< : recv pfkey DELETE ESP message
11/10/27 15:01:49 ii : hard halt signal received, shutting down
11/10/27 15:01:49 ii : hard halt signal received, shutting down
11/10/27 15:01:49 DB : removing all peer tunnel refrences
11/10/27 15:01:49 DB : tunnel dpd event canceled ( ref count = 5 )
11/10/27 15:01:49 DB : tunnel stats event canceled ( ref count = 4 )
11/10/27 15:01:49 DB : removing tunnel config references
11/10/27 15:01:49 DB : config deleted ( obj count = 0 )
11/10/27 15:01:49 DB : removing tunnel phase2 references
11/10/27 15:01:49 DB : removing tunnel phase1 references
11/10/27 15:01:49 DB : phase1 soft event canceled ( ref count = 3 )
11/10/27 15:01:49 DB : phase1 hard event canceled ( ref count = 2 )
11/10/27 15:01:49 DB : phase1 dead event canceled ( ref count = 1 )
11/10/27 15:01:49 DB : removing all peer tunnel refrences
11/10/27 15:01:49 DB : tunnel dpd event canceled ( ref count = 5 )
11/10/27 15:01:49 DB : tunnel stats event canceled ( ref count = 4 )
11/10/27 15:01:49 DB : removing tunnel config references
11/10/27 15:01:49 DB : config deleted ( obj count = 0 )
11/10/27 15:01:49 DB : removing tunnel phase2 references
11/10/27 15:01:49 DB : removing tunnel phase1 references
11/10/27 15:01:49 DB : phase1 soft event canceled ( ref count = 3 )
11/10/27 15:01:49 DB : phase1 hard event canceled ( ref count = 2 )
11/10/27 15:01:49 DB : phase1 dead event canceled ( ref count = 1 )
11/10/27 15:01:49 ii : sending peer DELETE message
11/10/27 15:01:49 ii : - 1.2.3.112:500 -> 1.2.3.8:500
11/10/27 15:01:49 ii : - isakmp spi = 4499bbb0562699ec:5cc749d6ada60baf
11/10/27 15:01:49 ii : - data size 0
11/10/27 15:01:49 ii : sending peer DELETE message
11/10/27 15:01:49 ii : - 1.2.3.112:500 -> 1.2.3.8:500
11/10/27 15:01:49 ii : - isakmp spi = 4499bbb0562699ec:5cc749d6ada60baf
11/10/27 15:01:49 ii : - data size 0