1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.

OS X - RV042 VPN Rekeying Issues

Discussion in 'Cisco Small Business Routers and VPN Solutions' started by bhallida, Aug 22, 2006.

  1. bhallida

    bhallida LI Guru Member

    I am using a client (OS X/IPSecuritas) to gateway (RV042) tunnel. Racoon doesn't seem to be playing nice with my router when rekeying.

    When phase 1 rekeys, the next attempt to rekey phase 2 fails. Subsequent phase 2 attempts then succeed. This ends up leaving about a 20 minute window where my vpn is down when using Phase 1 lifetime of 18800, phase 2 lifetime of 3600.

    The relevant error message from the RV042 is: Quick Mode I1 message is unacceptable because it uses a previously used Message ID 0xd52677d5 (perhaps this is a duplicated packet)

    Also I noticed that Racoon seems to be rekeying phase 2 at closer to 2880 sec (which is not how its configured)?

    The log is as follows (Racoon log is very verbose, but I can provide that too if it will help):
    Aug 17 23:05:46 2006 VPN Log Ignoring Vendor ID payload [4a131c8107035845...]
    Aug 17 23:05:46 2006 VPN Log Ignoring Vendor ID payload [4df37928e9fc4fd1...]
    Aug 17 23:05:46 2006 VPN Log Received Vendor ID payload Type = [draft-ietf-ipsec-nat-t-ike-02]
    Aug 17 23:05:46 2006 VPN Log Ignoring Vendor ID payload Type = [draft-ietf-ipsec-nat-t-ike-02_n]
    Aug 17 23:05:46 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Aggressive Mode 1st packet
    Aug 17 23:05:46 2006 VPN Log Aggressive mode peer ID is ID_USER_FQDN: '"User ID"'
    Aug 17 23:05:46 2006 VPN Log Responding to Aggressive Mode from "Nat Router Infront of client"
    Aug 17 23:05:46 2006 VPN Log [Tunnel Negotiation Info] >>> Responder Send Aggressive Mode 2nd packet
    Aug 17 23:05:47 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Aggressive Mode 3rd packet
    Aug 17 23:05:47 2006 VPN Log Aggressive mode peer ID is ID_USER_FQDN: '"User ID"'
    Aug 17 23:05:47 2006 VPN Log [Tunnel Negotiation Info] Aggressive Mode Phase 1 SA Established
    Aug 17 23:05:47 2006 VPN Log [Tunnel Negotiation Info] Initiator Cookies = c05d 4498 2242 d67d
    Aug 17 23:05:47 2006 VPN Log [Tunnel Negotiation Info] Responder Cookies = 6ca7 77e3 6f29 b1fc
    Aug 17 23:05:47 2006 VPN Log Received informational payload, type IPSEC_INITIAL_CONTACT
    Aug 17 23:05:47 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 17 23:05:48 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30bd
    Aug 17 23:05:48 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = 7f7f3ed
    Aug 17 23:05:48 2006 VPN Log [Tunnel Negotiation Info] >>> Responder send Quick Mode 2nd packet
    Aug 17 23:05:48 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 3rd packet
    Aug 17 23:05:48 2006 VPN Log [Tunnel Negotiation Info] Quick Mode Phase 2 SA Established, IPSec Tunnel Connected
    Aug 17 23:53:50 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 17 23:53:51 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30be
    Aug 17 23:53:51 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = f8b5fc
    Aug 17 23:53:51 2006 VPN Log [Tunnel Negotiation Info] >>> Responder send Quick Mode 2nd packet
    Aug 17 23:53:53 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 3rd packet
    Aug 17 23:53:53 2006 VPN Log [Tunnel Negotiation Info] Quick Mode Phase 2 SA Established, IPSec Tunnel Connected
    Aug 18 00:41:54 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 18 00:41:54 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30bf
    Aug 18 00:41:54 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = 5e67b0a
    Aug 18 00:41:54 2006 VPN Log [Tunnel Negotiation Info] >>> Responder send Quick Mode 2nd packet
    Aug 18 00:41:56 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 3rd packet
    Aug 18 00:41:56 2006 VPN Log [Tunnel Negotiation Info] Quick Mode Phase 2 SA Established, IPSec Tunnel Connected
    Aug 18 01:29:57 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 18 01:29:57 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30c0
    Aug 18 01:29:57 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = f028ec9
    Aug 18 01:29:57 2006 VPN Log [Tunnel Negotiation Info] >>> Responder send Quick Mode 2nd packet
    Aug 18 01:29:59 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 3rd packet
    Aug 18 01:29:59 2006 VPN Log [Tunnel Negotiation Info] Quick Mode Phase 2 SA Established, IPSec Tunnel Connected
    Aug 18 02:18:01 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 18 02:18:02 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30c1
    Aug 18 02:18:02 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = 588e3a
    Aug 18 02:18:02 2006 VPN Log [Tunnel Negotiation Info] >>> Responder send Quick Mode 2nd packet
    Aug 18 02:18:03 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 3rd packet
    Aug 18 02:18:03 2006 VPN Log [Tunnel Negotiation Info] Quick Mode Phase 2 SA Established, IPSec Tunnel Connected
    Aug 18 03:06:04 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 18 03:06:04 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30c2
    Aug 18 03:06:04 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = 5fca36
    Aug 18 03:06:04 2006 VPN Log [Tunnel Negotiation Info] >>> Responder send Quick Mode 2nd packet
    Aug 18 03:06:06 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 3rd packet
    Aug 18 03:06:06 2006 VPN Log [Tunnel Negotiation Info] Quick Mode Phase 2 SA Established, IPSec Tunnel Connected
    Aug 18 03:54:08 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 18 03:54:09 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30c3
    Aug 18 03:54:09 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = 2831697
    Aug 18 03:54:09 2006 VPN Log [Tunnel Negotiation Info] >>> Responder send Quick Mode 2nd packet
    Aug 18 03:54:10 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 3rd packet
    Aug 18 03:54:10 2006 VPN Log [Tunnel Negotiation Info] Quick Mode Phase 2 SA Established, IPSec Tunnel Connected
    Aug 18 04:19:07 2006 VPN Log [Tunnel Negotiation Info] >>> Initiator Send Aggressive Mode 1st packet
    Aug 18 04:19:07 2006 VPN Log initiating Aggressive Mode #28 to replace #20, connection "ips1"
    Aug 18 04:19:08 2006 VPN Log STATE_AGGR_I1: initiate
    Aug 18 04:20:18 2006 VPN Log [Tunnel Negotiation Info] >>> Initiator Send Aggressive Mode 1st packet
    Aug 18 04:20:18 2006 VPN Log initiating Aggressive Mode #29 to replace #28, connection "ips1"
    Aug 18 04:20:18 2006 VPN Log STATE_AGGR_I1: initiate
    Aug 18 04:21:28 2006 VPN Log [Tunnel Negotiation Info] >>> Initiator Send Aggressive Mode 1st packet
    Aug 18 04:21:28 2006 VPN Log initiating Aggressive Mode #30 to replace #29, connection "ips1"
    Aug 18 04:21:28 2006 VPN Log STATE_AGGR_I1: initiate
    Aug 18 04:42:11 2006 VPN Log Ignoring Vendor ID payload [4a131c8107035845...]
    Aug 18 04:42:11 2006 VPN Log Ignoring Vendor ID payload [4df37928e9fc4fd1...]
    Aug 18 04:42:11 2006 VPN Log Received Vendor ID payload Type = [draft-ietf-ipsec-nat-t-ike-02]
    Aug 18 04:42:11 2006 VPN Log Ignoring Vendor ID payload Type = [draft-ietf-ipsec-nat-t-ike-02_n]
    Aug 18 04:42:11 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Aggressive Mode 1st packet
    Aug 18 04:42:11 2006 VPN Log Aggressive mode peer ID is ID_USER_FQDN: '"User ID"'
    Aug 18 04:42:11 2006 VPN Log Responding to Aggressive Mode from "Nat Router Infront of client"
    Aug 18 04:42:12 2006 VPN Log [Tunnel Negotiation Info] >>> Responder Send Aggressive Mode 2nd packet
    Aug 18 04:42:14 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Aggressive Mode 3rd packet
    Aug 18 04:42:14 2006 VPN Log Aggressive mode peer ID is ID_USER_FQDN: '"User ID"'
    Aug 18 04:42:14 2006 VPN Log [Tunnel Negotiation Info] Aggressive Mode Phase 1 SA Established
    Aug 18 04:42:14 2006 VPN Log [Tunnel Negotiation Info] Initiator Cookies = 627 a0eb d9ad 4ff3
    Aug 18 04:42:14 2006 VPN Log [Tunnel Negotiation Info] Responder Cookies = 9aa4 9159 1f84 e7
    Aug 18 04:42:15 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 18 04:42:15 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30c4
    Aug 18 04:42:15 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = baf657
    Aug 18 04:42:35 2006 VPN Log Quick Mode I1 message is unacceptable because it uses a previously used Message ID 0xd52677d5 (perhaps this is a duplicated packet)
    Aug 18 05:05:50 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 1st packet
    Aug 18 05:05:51 2006 VPN Log [Tunnel Negotiation Info] Inbound SPI value = d44a30c5
    Aug 18 05:05:51 2006 VPN Log [Tunnel Negotiation Info] Outbound SPI value = ea4417b
    Aug 18 05:05:51 2006 VPN Log [Tunnel Negotiation Info] >>> Responder send Quick Mode 2nd packet
    Aug 18 05:05:51 2006 VPN Log [Tunnel Negotiation Info] <<< Responder Received Quick Mode 3rd packet
    Aug 18 05:05:51 2006 VPN Log [Tunnel Negotiation Info] Quick Mode Phase 2 SA Established, IPSec Tunnel Connected


    Any help would be appreciated.

    Thanks,
    Ben Halliday:confused:
     
  2. Toxic

    Toxic Administrator Staff Member

    try using Seconds that generate whole minutes and/or Hours

    18800 = 313.33333333333333333333333333333 minutes = 5.22222222 hours

    28800 = 480 minutes = 8hrs
     
  3. bhallida

    bhallida LI Guru Member

    For testing purposes I tried
    phase 1 = 180 sec = 3 minutes
    phase 2 = 120 sec = 2 mintues

    Same result. After more staring at the logs I found the following which may or may not be relevant:

    1) Racoon is rekeying phase 2 early. Every 100 seconds using the above config. (this is wierd, but phase 2 rekeys just fine until phase 1 has to rekey)

    2) When phase 1 lifetime expires the RV042 (openswan?/freeswan?/strongswan?) tries to initiate rekeying. Racoon ignores these attempts with the message:

    Aug 22 21:59:14 benslaptop racoon: DEBUG: remoteconf.c:134:getrmconf(): no remote configuration found.\n
    Aug 22 21:59:14 benslaptop racoon: ERROR: isakmp.c:1086:isakmp_ph1begin_r(): couldn't find configuration.\n
    Aug 22 21:59:14 benslaptop racoon: INFO: isakmp.c:1879:isakmp_ph1expire(): ISAKMP-SA expired <client_ip>[4500]-<RV042_ip>[4500] spi:b54ef9f80f138d5e:aad8996b7d7d9a95\n
    Aug 22 21:59:15 benslaptop racoon: INFO: isakmp.c:1927:isakmp_ph1delete(): ISAKMP-SA deleted <client_ip>[4500]-<RV042_ip>[4500] spi:b54ef9f80f138d5e:aad8996b7d7d9a95\n


    I'm assuming this is because I am using natt so there is no policy specifically defined in racoon for a connection between the RV042 and my natt router ip.

    3) When phase 1 lifetime expires, in addition to whats mentioned above, Racoon marks phase 1 as expired (see message above), and waits for the next phase 2 rekeying before trying to rekey phase 1 (don't know if this difference in behavior is a configuration issue or a difference in implementation). Once racoon sees it is time to rekey phase 2, it initiates a phase 1 rekeying which succeeds, but when it proceeds to rekey phase 2 the RV042 rejects the message giving the message:

    'Quick Mode I1 message is unacceptable because it uses a previously used Message ID 0x653a2217 (perhaps this is a duplicated packet)'.

    4) Racoon times out waiting for phase 2 to rekey, then it retrys after 25 seconds and rekeying succeeds.

    I don't see anything different about the second attempt in the logs, but I can speculate that Racoon is using a different 'Message ID'.

    Any other ideas? Logs are attached in logs.zip (sorry, racoon log was too big).
     

    Attached Files:

Share This Page