IPsec VPN not working as expected…



  • Hi,

    Having a CARP array running with pfSense 2.0-RELEASE at our main site which connects to a variety of VPN routers at remote locations. One of these is a pfSense 1.2.3 which is having some problems routing traffic through the tunnel from either side.
    We currently have some problems with the line at the main site where it drops for a sec or two and then resumes. Of course, this causes the tunnels to drop but all of them renegotiate back and traffic through the tunnels resume. Except for the one mentioned above.
    When this line drop occurs, the tunnel is brought back online and is listed as connected on both boxes but no traffic flows through it. Restarting on either side will fix the issue.

    A snip from the log of the master device on the main site gives this right after the connection drop:

    Feb 16 10:56:34SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: DPD: remote (ISAKMP-SA spi=65d28a597f7b9b1d:8dbba2fcc075afd9) seems to be dead.
    Feb 16 10:56:34SEBHCFW01racoon:INFO: ISAKMP-SA deleted 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:65d28a597f7b9b1d:8dbba2fcc075afd9
    Feb 16 10:56:34SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: DPD: remote (ISAKMP-SA spi=65d28a597f7b9b1d:8dbba2fcc075afd9) seems to be dead.
    Feb 16 10:56:34SEBHCFW01racoon:INFO: ISAKMP-SA deleted 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:65d28a597f7b9b1d:8dbba2fcc075afd9
    Feb 16 10:56:34SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: DPD: remote (ISAKMP-SA spi=65d28a597f7b9b1d:8dbba2fcc075afd9) seems to be dead.
    Feb 16 10:56:34SEBHCFW01racoon:INFO: ISAKMP-SA deleted 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:65d28a597f7b9b1d:8dbba2fcc075afd9
    Feb 16 10:56:41SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:41SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:41SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:42SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 10:56:42SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 10:56:42SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 10:56:42SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 10:56:42SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 10:56:42SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 10:56:45SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:45SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:45SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:50SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:50SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:50SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:55SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:55SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:56:55SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:57:00SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:57:00SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:57:00SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: unknown Informational exchange received.
    Feb 16 10:57:02SEBHCFW01racoon:INFO: ISAKMP-SA established 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:77393778567126b4:09489131368cb4eb
    Feb 16 10:57:02SEBHCFW01racoon:INFO: ISAKMP-SA established 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:77393778567126b4:09489131368cb4eb
    Feb 16 10:57:02SEBHCFW01racoon:INFO: ISAKMP-SA established 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:77393778567126b4:09489131368cb4eb
    Feb 16 10:57:03SEBHCFW01racoon:INFO: initiate new phase 2 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 10:57:03SEBHCFW01racoon:INFO: initiate new phase 2 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 10:57:03SEBHCFW01racoon:INFO: initiate new phase 2 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 10:57:03SEBHCFW01racoon:INFO: IPsec-SA established: ESP 212.xxx.xxx.xxx[500]->195.xxx.xxx.xxx[500] spi=266821798(0xfe760a6)
    Feb 16 10:57:03SEBHCFW01racoon:INFO: IPsec-SA established: ESP 212.xxx.xxx.xxx[500]->195.xxx.xxx.xxx[500] spi=241821523(0xe69e753)
    Feb 16 10:57:03SEBHCFW01racoon:INFO: IPsec-SA established: ESP 212.xxx.xxx.xxx[500]->195.xxx.xxx.xxx[500] spi=266821798(0xfe760a6)
    Feb 16 10:57:03SEBHCFW01racoon:INFO: IPsec-SA established: ESP 212.xxx.xxx.xxx[500]->195.xxx.xxx.xxx[500] spi=241821523(0xe69e753)
    Feb 16 10:57:03SEBHCFW01racoon:INFO: IPsec-SA established: ESP 212.xxx.xxx.xxx[500]->195.xxx.xxx.xxx[500] spi=266821798(0xfe760a6)
    Feb 16 10:57:03SEBHCFW01racoon:INFO: IPsec-SA established: ESP 212.xxx.xxx.xxx[500]->195.xxx.xxx.xxx[500] spi=241821523(0xe69e753)
    Feb 16 11:57:23SEBHCFW01racoon:INFO: ISAKMP-SA deleted 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:77393778567126b4:09489131368cb4eb
    Feb 16 11:57:23SEBHCFW01racoon:INFO: ISAKMP-SA deleted 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:77393778567126b4:09489131368cb4eb
    Feb 16 11:57:23SEBHCFW01racoon:INFO: ISAKMP-SA deleted 212.xxx.xxx.xxx[500]-195.xxx.xxx.xxx[500] spi:77393778567126b4:09489131368cb4eb
    Feb 16 11:57:26SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:57:26SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 11:57:26SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:57:26SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 11:57:26SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:57:26SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 11:57:58SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:57:58SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:57:58SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:58:20SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:58:20SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 11:58:20SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:58:20SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 11:58:20SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:58:20SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 11:58:52SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:58:52SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:58:52SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:59:08SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Feb 16 11:59:08SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Feb 16 11:59:08SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Feb 16 11:59:40SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:59:40SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:59:40SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 11:59:47SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:59:47SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 11:59:47SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:59:47SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 11:59:47SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 11:59:47SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 12:00:19SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 12:00:19SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 12:00:19SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 12:00:20SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Feb 16 12:00:20SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Feb 16 12:00:20SEBHCFW01racoon:[195.xxx.xxx.xxx] INFO: request for establishing IPsec-SA was queued due to no phase1 found.
    Feb 16 12:00:52SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 12:00:52SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 12:00:52SEBHCFW01racoon:[195.xxx.xxx.xxx] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 195.xxx.xxx.xxx[0]->212.xxx.xxx.xxx[0]
    Feb 16 12:01:19SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 12:01:19SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]
    Feb 16 12:01:19SEBHCFW01racoon:INFO: IPsec-SA request for 195.xxx.xxx.xxx queued due to no phase1 found.
    Feb 16 12:01:19SEBHCFW01racoon:INFO: initiate new phase 1 negotiation: 212.xxx.xxx.xxx[500]<=>195.xxx.xxx.xxx[500]

    Any suggestions?

    Regards,
    Anders


Log in to reply