PfSense 1.2.3 both ends tunnel drops after ~5 minutes regardless of DPD



  • I'm running a pair of pfSense 1.2.3 boxes (2.0 doesn't install on this hardware)
    The VPN gets up and running just fine after rebooting the router on the far end.  After 4-10 minutes of watching successful pings, the tunnel collapses.  If enabled, DPD will kick in and try restarting everything without success.  If DPD isn't enabled, no reattempt is made and the log shows that neither side realizes there's a problem.  The following log starts as I'm booting up the remote router.

    YYY = Remote WAN
    ZZZ = Local WAN

    Nov 3 14:10:15 racoon: [My VPN]: ERROR: YYY.YYY.YYY.YYY give up to get IPsec-SA due to time up to wait.
    Nov 3 14:10:16 racoon: [My VPN]: INFO: ISAKMP-SA deleted ZZZ.ZZZ.ZZZ.ZZZ[500]-YYY.YYY.YYY.YYY[500] spi:baa621aeae160a91:abd5f138029003a2
    Nov 3 14:10:35 racoon: [My VPN]: INFO: IPsec-SA request for YYY.YYY.YYY.YYY queued due to no phase1 found.
    Nov 3 14:10:35 racoon: [My VPN]: INFO: initiate new phase 1 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[500]<=>YYY.YYY.YYY.YYY[500]
    Nov 3 14:10:35 racoon: INFO: begin Identity Protection mode.
    Nov 3 14:11:00 racoon: [My VPN]: INFO: phase2 sa expired ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:11:00 racoon: INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Nov 3 14:11:01 racoon: [My VPN]: INFO: phase2 sa deleted ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:11:25 racoon: [My VPN]: INFO: phase2 sa expired ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:11:25 racoon: INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Nov 3 14:11:25 racoon: ERROR: phase1 negotiation failed due to time up. 5d250b264fdb02e9:0000000000000000
    Nov 3 14:11:26 racoon: [My VPN]: INFO: phase2 sa deleted ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:11:44 racoon: [My VPN]: INFO: respond new phase 1 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[500]<=>YYY.YYY.YYY.YYY[500]
    Nov 3 14:11:44 racoon: INFO: begin Identity Protection mode.
    Nov 3 14:11:44 racoon: INFO: received broken Microsoft ID: FRAGMENTATION
    Nov 3 14:11:44 racoon: INFO: received Vendor ID: DPD
    Nov 3 14:11:44 racoon: [My VPN]: INFO: ISAKMP-SA established ZZZ.ZZZ.ZZZ.ZZZ[500]-YYY.YYY.YYY.YYY[500] spi:91cd5b2be515d712:1db8011c56ad2119
    Nov 3 14:11:45 racoon: [My VPN]: INFO: initiate new phase 2 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[500]<=>YYY.YYY.YYY.YYY[500]
    Nov 3 14:11:45 racoon: [My VPN]: INFO: IPsec-SA established: ESP YYY.YYY.YYY.YYY[0]->ZZZ.ZZZ.ZZZ.ZZZ[0] spi=102725209(0x61f7659)
    Nov 3 14:11:45 racoon: [My VPN]: INFO: IPsec-SA established: ESP ZZZ.ZZZ.ZZZ.ZZZ[0]->YYY.YYY.YYY.YYY[0] spi=74950379(0x477a6eb)
    Nov 3 14:11:45 racoon: [My VPN]: INFO: respond new phase 2 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[0]<=>YYY.YYY.YYY.YYY[0]
    Nov 3 14:11:45 racoon: [My VPN]: INFO: IPsec-SA established: ESP YYY.YYY.YYY.YYY[0]->ZZZ.ZZZ.ZZZ.ZZZ[0] spi=25836632(0x18a3c58)
    Nov 3 14:11:45 racoon: [My VPN]: INFO: IPsec-SA established: ESP ZZZ.ZZZ.ZZZ.ZZZ[0]->YYY.YYY.YYY.YYY[0] spi=31349894(0x1de5c86)

    If DPD was disabled, this is basically where the log would stop.

    Nov 3 14:22:09 racoon: INFO: DPD: remote (ISAKMP-SA spi=91cd5b2be515d712:1db8011c56ad2119) seems to be dead.
    Nov 3 14:22:10 racoon: [My VPN]: INFO: IPsec-SA request for YYY.YYY.YYY.YYY queued due to no phase1 found.
    Nov 3 14:22:10 racoon: [My VPN]: INFO: initiate new phase 1 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[500]<=>YYY.YYY.YYY.YYY[500]
    Nov 3 14:22:10 racoon: INFO: begin Identity Protection mode.
    Nov 3 14:22:10 racoon: [My VPN]: INFO: ISAKMP-SA deleted ZZZ.ZZZ.ZZZ.ZZZ[500]-YYY.YYY.YYY.YYY[500] spi:91cd5b2be515d712:1db8011c56ad2119
    Nov 3 14:22:13 racoon: [My VPN]: INFO: respond new phase 1 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[500]<=>YYY.YYY.YYY.YYY[500]
    Nov 3 14:22:13 racoon: INFO: begin Identity Protection mode.
    Nov 3 14:22:13 racoon: INFO: received broken Microsoft ID: FRAGMENTATION
    Nov 3 14:22:13 racoon: INFO: received Vendor ID: DPD
    Nov 3 14:22:23 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:22:33 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:22:35 racoon: [My VPN]: INFO: phase2 sa expired ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:22:35 racoon: INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Nov 3 14:22:36 racoon: [My VPN]: INFO: phase2 sa deleted ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:22:43 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:22:53 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:23:00 racoon: [My VPN]: INFO: phase2 sa expired ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:23:00 racoon: INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Nov 3 14:23:00 racoon: ERROR: phase1 negotiation failed due to time up. 329badae6e35b166:0000000000000000
    Nov 3 14:23:01 racoon: [My VPN]: INFO: phase2 sa deleted ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:23:03 racoon: ERROR: phase1 negotiation failed due to time up. 96913e79ee5df682:73ce981105c4ff0b
    Nov 3 14:23:19 racoon: [My VPN]: INFO: respond new phase 1 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[500]<=>YYY.YYY.YYY.YYY[500]
    Nov 3 14:23:19 racoon: INFO: begin Identity Protection mode.
    Nov 3 14:23:19 racoon: INFO: received broken Microsoft ID: FRAGMENTATION
    Nov 3 14:23:19 racoon: INFO: received Vendor ID: DPD
    Nov 3 14:23:25 racoon: [My VPN]: INFO: phase2 sa expired ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:23:25 racoon: INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Nov 3 14:23:26 racoon: [My VPN]: INFO: phase2 sa deleted ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:23:29 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:23:49 last message repeated 2 times
    Nov 3 14:23:50 racoon: [My VPN]: INFO: phase2 sa expired ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:23:50 racoon: INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Nov 3 14:23:51 racoon: [My VPN]: INFO: phase2 sa deleted ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:23:59 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:24:09 racoon: ERROR: phase1 negotiation failed due to time up. 6276770ec6478771:744ffb4dd937c06b
    Nov 3 14:24:15 racoon: [My VPN]: INFO: phase2 sa expired ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:24:15 racoon: [My VPN]: INFO: IPsec-SA request for YYY.YYY.YYY.YYY queued due to no phase1 found.
    Nov 3 14:24:15 racoon: [My VPN]: INFO: initiate new phase 1 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[500]<=>YYY.YYY.YYY.YYY[500]
    Nov 3 14:24:15 racoon: INFO: begin Identity Protection mode.
    Nov 3 14:24:16 racoon: [My VPN]: INFO: phase2 sa deleted ZZZ.ZZZ.ZZZ.ZZZ-YYY.YYY.YYY.YYY
    Nov 3 14:24:25 racoon: [My VPN]: INFO: respond new phase 1 negotiation: ZZZ.ZZZ.ZZZ.ZZZ[500]<=>YYY.YYY.YYY.YYY[500]
    Nov 3 14:24:25 racoon: INFO: begin Identity Protection mode.
    Nov 3 14:24:25 racoon: INFO: received broken Microsoft ID: FRAGMENTATION
    Nov 3 14:24:25 racoon: INFO: received Vendor ID: DPD
    Nov 3 14:24:35 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:24:45 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:24:46 racoon: [My VPN]: ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP YYY.YYY.YYY.YYY[0]->ZZZ.ZZZ.ZZZ.ZZZ[0]
    Nov 3 14:24:46 racoon: INFO: delete phase 2 handler.
    Nov 3 14:24:55 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:25:05 racoon: [My VPN]: NOTIFY: the packet is retransmitted by YYY.YYY.YYY.YYY[500] (1).
    Nov 3 14:25:05 racoon: ERROR: phase1 negotiation failed due to time up. e534b133b1979018:0000000000000000

    P.S. Hardware for those interested in why I didn't get 2.0 running:  Motherboard Supermicro X7SPA-HF
    Some kind of kernel panic IIRC


Locked