Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

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

    IPsec
    1
    1
    2.1k
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • A
      AkkerKid
      last edited by

      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

      1 Reply Last reply Reply Quote 0
      • First post
        Last post
      Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.