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:

  1. This site uses cookies to help personalise content, tailor your experience and to keep you logged in if you register.
    By continuing to use this site, you are consenting to our use of cookies.
    Dismiss Notice