IPSec VPN randomly stops working.



  • I am having a strange issue.

    When I boot my pfsense device my IPsec VPN works. About an hour or so later it stops.

    My Client says this:
    peer configured
    iskamp proposal configured
    esp proposal configured
    client configured
    local id configured
    remote id configured
    gateway is not responding

    pre-shared key configured
    bringing up tunnel …
    tunnel disabled
    detached from key daemon

    My server says that there is a timeout negotiating the phase 1 encryption. I will be able to post the actual logs tomorrow.

    This happened after the upgrade to 2.0.3. Has anyone experienced this/have a fix for it?

    Thanks,


  • Banned

    There is a detailed IPsec log, including the possibility to enable debug logging.



  • @doktornotor:

    There is a detailed IPsec log, including the possibility to enable debug logging.

    Here is a successful connection after a reboot of the pfsense appliance.
    Jul 18 15:31:08 racoon: [213.143.58.28] DEBUG: rescheduling send_r_u (5).
    Jul 18 15:31:08 racoon: [213.143.58.28] DEBUG: DPD R-U-There sent (0)
    Jul 18 15:31:08 racoon: DEBUG: IV freed
    Jul 18 15:31:08 racoon: DEBUG: sendto Information notify.
    Jul 18 15:31:08 racoon: DEBUG: 00000000 1a98f78d 5dcec8f1 37eba533 7fb2b769 08100501 f44e363b 0000005c de8fd206 08831883 6b592284 64c2d6e7 57adbea3 7b01e2d3 af516bf3 1d161a9e 609b4de9 389f429f e9e6463d 86b7c7b1 7dcf30b9 2e53193f 41c2161f 2af9a3f9
    Jul 18 15:31:08 racoon: [Unknown Gateway/Dynamic]: DEBUG: 1 times of 96 bytes message will be sent to 213.143.58.28[46900]
    Jul 18 15:31:08 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet to 213.143.58.28[46900]
    Jul 18 15:31:08 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet from xxx.xxx.xxx.xxx[4500]
    Jul 18 15:31:08 racoon: [Unknown Gateway/Dynamic]: DEBUG: sockname xxx.xxx.xxx.xxx[4500]
    Jul 18 15:31:08 racoon: [Unknown Gateway/Dynamic]: DEBUG: 96 bytes from xxx.xxx.xxx.xxx[4500] to 213.143.58.28[46900]
    Jul 18 15:31:08 racoon: DEBUG: Adding NON-ESP marker
    Jul 18 15:31:08 racoon: DEBUG: encrypted.
    Jul 18 15:31:08 racoon: DEBUG: 7dcf30b9 2e53193f 41c2161f 2af9a3f9
    Jul 18 15:31:08 racoon: DEBUG: save IV for next:
    Jul 18 15:31:08 racoon: DEBUG: f0495a3d fa82f6f8 ea405391 3d60f5e1
    Jul 18 15:31:08 racoon: DEBUG: encrypted payload by IV:
    Jul 18 15:31:08 racoon: DEBUG: 6c0fb568 1a5e89e7 16b5a269 dc771288
    Jul 18 15:31:08 racoon: DEBUG: with key:
    Jul 18 15:31:08 racoon: DEBUG: encryption(aes)
    Jul 18 15:31:08 racoon: DEBUG: 0b000018 fb7d8e1a 9d58d751 b3108265 83ce274e 775edbd3 00000020 00000001 01108d28 1a98f78d 5dcec8f1 37eba533 7fb2b769 000001a8 93a798b8 c4a2ee07
    Jul 18 15:31:08 racoon: DEBUG: pad length = 8
    Jul 18 15:31:08 racoon: DEBUG: encryption(aes)
    Jul 18 15:31:08 racoon: DEBUG: begin encryption.
    Jul 18 15:31:08 racoon: DEBUG: fb7d8e1a 9d58d751 b3108265 83ce274e 775edbd3
    Jul 18 15:31:08 racoon: DEBUG: HASH computed:
    Jul 18 15:31:08 racoon: DEBUG: hmac(hmac_sha1)
    Jul 18 15:31:08 racoon: DEBUG: f44e363b 00000020 00000001 01108d28 1a98f78d 5dcec8f1 37eba533 7fb2b769 000001a8
    Jul 18 15:31:08 racoon: DEBUG: HASH with:
    Jul 18 15:31:08 racoon: DEBUG: f0495a3d fa82f6f8 ea405391 3d60f5e1
    Jul 18 15:31:08 racoon: DEBUG: phase2 IV computed:
    Jul 18 15:31:08 racoon: DEBUG: encryption(aes)
    Jul 18 15:31:08 racoon: DEBUG: hash(sha1)
    Jul 18 15:31:08 racoon: DEBUG: dc5d9085 24ad3702 6e6720d1 bd83c9ab f44e363b
    Jul 18 15:31:08 racoon: DEBUG: phase1 last IV:
    Jul 18 15:31:08 racoon: DEBUG: compute IV for phase2
    Jul 18 15:31:08 racoon: [213.143.58.28] DEBUG: DPD monitoring….
    Jul 18 15:30:58 racoon: DEBUG: this policy did not exist for removal: "0.0.0.0/0[0] 10.0.1.1/32[0] proto=any dir=out"
    Jul 18 15:30:58 racoon: DEBUG: db :0x285473c8: 10.0.1.1/32[0] 0.0.0.0/0[0] proto=any dir=in
    Jul 18 15:30:58 racoon: DEBUG: sub:0xbfbfe764: 0.0.0.0/0[0] 10.0.1.1/32[0] proto=any dir=out
    Jul 18 15:30:58 racoon: [Unknown Gateway/Dynamic]: DEBUG: db :0x28547288: 192.168.1.1/32[0] 192.168.0.0/16[0] proto=any dir=out
    Jul 18 15:30:58 racoon: DEBUG: sub:0xbfbfe764: 0.0.0.0/0[0] 10.0.1.1/32[0] proto=any dir=out
    Jul 18 15:30:58 racoon: [Unknown Gateway/Dynamic]: DEBUG: db :0x28547148: 192.168.0.0/16[0] 192.168.1.1/32[0] proto=any dir=in
    Jul 18 15:30:58 racoon: DEBUG: sub:0xbfbfe764: 0.0.0.0/0[0] 10.0.1.1/32[0] proto=any dir=out
    Jul 18 15:30:58 racoon: DEBUG: got pfkey X_SPDUPDATE message
    Jul 18 15:30:58 racoon: DEBUG: pk_recv: retry[0] recv()
    Jul 18 15:30:58 racoon: DEBUG: this policy did not exist for removal: "10.0.1.1/32[0] 0.0.0.0/0[0] proto=any dir=in"
    Jul 18 15:30:58 racoon: [Unknown Gateway/Dynamic]: DEBUG: db :0x28547288: 192.168.1.1/32[0] 192.168.0.0/16[0] proto=any dir=out
    Jul 18 15:30:58 racoon: DEBUG: sub:0xbfbfe764: 10.0.1.1/32[0] 0.0.0.0/0[0] proto=any dir=in
    Jul 18 15:30:58 racoon: [Unknown Gateway/Dynamic]: DEBUG: db :0x28547148: 192.168.0.0/16[0] 192.168.1.1/32[0] proto=any dir=in

    This is what happens after an hour or so of it running:

    Jul 18 15:26:36 racoon: DEBUG: IV freed
    Jul 18 15:26:36 racoon: ERROR: phase1 negotiation failed due to time up. f463eeebc55d9437:a313717fe3406d24
    Jul 18 15:26:26 racoon: DEBUG: resend phase1 packet f463eeebc55d9437:a313717fe3406d24
    Jul 18 15:26:26 racoon: DEBUG: f463eeeb c55d9437 a313717f e3406d24 01100400 00000000 000001a4 0400003c 00000001 00000001 00000030 01010001 00000028 01010000 80010007 800e0080 80020002 80040002 8003fde9 800b0001 000c0004 00015180 0a000084 d20dbe00 06afd31e 63266237 51f286e0 3a92c8af db3ec823 0054ac41 5be78a39 79d7ad9e af074622 cc73b014 d1b6cf63 fbcfe586 86cad8e6 bc9f5681 a3d42d4b d3337a91 700914f6 97d6ad0f f9f1126b 573d7d25 7af41a3f 5504b3d9 15feb27d 9c7195bb 13e60877 fcfd6d41 9e1a429b 0c90fae1 3ebf7d21 c89d55a7 b8d746d5 05000014 ee4bc668 bcfc9db4 195786a3 3c9b3733 0800000c 011101f4 501838e0 0d000018 34673cce 63ad9dfc 06dd1b05 1ef3ad4a 79492baa 0d00000c 09002689 dfd6b712 0d000014 12f5f28c 457168a9 702d9fe2 74cc0100 14000014 4a131c81 07035845 5c5728f2 0e95452f 14000018 af0b8ecb 13fbc9c0 3ddc7126 5ea2df86 b315bfe0 0d000018 8dfa8e9a 45fb3f9a d80c4b37 858595b4 e72a4c51 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jul 18 15:26:26 racoon: [Unknown Gateway/Dynamic]: DEBUG: 1 times of 420 bytes message will be sent to 213.143.58.28[28087]
    Jul 18 15:26:26 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet to 213.143.58.28[28087]
    Jul 18 15:26:26 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet from xxx.xxx.xxx.xxx[500]
    Jul 18 15:26:26 racoon: [Unknown Gateway/Dynamic]: DEBUG: sockname xxx.xxx.xxx.xxx[500]
    Jul 18 15:26:26 racoon: [Unknown Gateway/Dynamic]: DEBUG: 420 bytes from xxx.xxx.xxx.xxx[500] to 213.143.58.28[28087]
    Jul 18 15:26:16 racoon: DEBUG: resend phase1 packet f463eeebc55d9437:a313717fe3406d24
    Jul 18 15:26:16 racoon: DEBUG: f463eeeb c55d9437 a313717f e3406d24 01100400 00000000 000001a4 0400003c 00000001 00000001 00000030 01010001 00000028 01010000 80010007 800e0080 80020002 80040002 8003fde9 800b0001 000c0004 00015180 0a000084 d20dbe00 06afd31e 63266237 51f286e0 3a92c8af db3ec823 0054ac41 5be78a39 79d7ad9e af074622 cc73b014 d1b6cf63 fbcfe586 86cad8e6 bc9f5681 a3d42d4b d3337a91 700914f6 97d6ad0f f9f1126b 573d7d25 7af41a3f 5504b3d9 15feb27d 9c7195bb 13e60877 fcfd6d41 9e1a429b 0c90fae1 3ebf7d21 c89d55a7 b8d746d5 05000014 ee4bc668 bcfc9db4 195786a3 3c9b3733 0800000c 011101f4 501838e0 0d000018 34673cce 63ad9dfc 06dd1b05 1ef3ad4a 79492baa 0d00000c 09002689 dfd6b712 0d000014 12f5f28c 457168a9 702d9fe2 74cc0100 14000014 4a131c81 07035845 5c5728f2 0e95452f 14000018 af0b8ecb 13fbc9c0 3ddc7126 5ea2df86 b315bfe0 0d000018 8dfa8e9a 45fb3f9a d80c4b37 858595b4 e72a4c51 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jul 18 15:26:16 racoon: [Unknown Gateway/Dynamic]: DEBUG: 1 times of 420 bytes message will be sent to 213.143.58.28[28087]
    Jul 18 15:26:16 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet to 213.143.58.28[28087]
    Jul 18 15:26:16 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet from xxx.xxx.xxx.xxx[500]
    Jul 18 15:26:16 racoon: [Unknown Gateway/Dynamic]: DEBUG: sockname xxx.xxx.xxx.xxx[500]
    Jul 18 15:26:16 racoon: [Unknown Gateway/Dynamic]: DEBUG: 420 bytes from xxx.xxx.xxx.xxx[500] to 213.143.58.28[28087]
    Jul 18 15:26:06 racoon: DEBUG: resend phase1 packet f463eeebc55d9437:a313717fe3406d24
    Jul 18 15:26:06 racoon: DEBUG: f463eeeb c55d9437 a313717f e3406d24 01100400 00000000 000001a4 0400003c 00000001 00000001 00000030 01010001 00000028 01010000 80010007 800e0080 80020002 80040002 8003fde9 800b0001 000c0004 00015180 0a000084 d20dbe00 06afd31e 63266237 51f286e0 3a92c8af db3ec823 0054ac41 5be78a39 79d7ad9e af074622 cc73b014 d1b6cf63 fbcfe586 86cad8e6 bc9f5681 a3d42d4b d3337a91 700914f6 97d6ad0f f9f1126b 573d7d25 7af41a3f 5504b3d9 15feb27d 9c7195bb 13e60877 fcfd6d41 9e1a429b 0c90fae1 3ebf7d21 c89d55a7 b8d746d5 05000014 ee4bc668 bcfc9db4 195786a3 3c9b3733 0800000c 011101f4 501838e0 0d000018 34673cce 63ad9dfc 06dd1b05 1ef3ad4a 79492baa 0d00000c 09002689 dfd6b712 0d000014 12f5f28c 457168a9 702d9fe2 74cc0100 14000014 4a131c81 07035845 5c5728f2 0e95452f 14000018 af0b8ecb 13fbc9c0 3ddc7126 5ea2df86 b315bfe0 0d000018 8dfa8e9a 45fb3f9a d80c4b37 858595b4 e72a4c51 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jul 18 15:26:06 racoon: [Unknown Gateway/Dynamic]: DEBUG: 1 times of 420 bytes message will be sent to 213.143.58.28[28087]
    Jul 18 15:26:06 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet to 213.143.58.28[28087]
    Jul 18 15:26:06 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet from xxx.xxx.xxx.xxx[500]
    Jul 18 15:26:06 racoon: [Unknown Gateway/Dynamic]: DEBUG: sockname xxx.xxx.xxx.xxx[500]
    Jul 18 15:26:06 racoon: [Unknown Gateway/Dynamic]: DEBUG: 420 bytes from xxx.xxx.xxx.xxx[500] to 213.143.58.28[28087]
    Jul 18 15:25:56 racoon: DEBUG: resend phase1 packet f463eeebc55d9437:a313717fe3406d24
    Jul 18 15:25:56 racoon: DEBUG: f463eeeb c55d9437 a313717f e3406d24 01100400 00000000 000001a4 0400003c 00000001 00000001 00000030 01010001 00000028 01010000 80010007 800e0080 80020002 80040002 8003fde9 800b0001 000c0004 00015180 0a000084 d20dbe00 06afd31e 63266237 51f286e0 3a92c8af db3ec823 0054ac41 5be78a39 79d7ad9e af074622 cc73b014 d1b6cf63 fbcfe586 86cad8e6 bc9f5681 a3d42d4b d3337a91 700914f6 97d6ad0f f9f1126b 573d7d25 7af41a3f 5504b3d9 15feb27d 9c7195bb 13e60877 fcfd6d41 9e1a429b 0c90fae1 3ebf7d21 c89d55a7 b8d746d5 05000014 ee4bc668 bcfc9db4 195786a3 3c9b3733 0800000c 011101f4 501838e0 0d000018 34673cce 63ad9dfc 06dd1b05 1ef3ad4a 79492baa 0d00000c 09002689 dfd6b712 0d000014 12f5f28c 457168a9 702d9fe2 74cc0100 14000014 4a131c81 07035845 5c5728f2 0e95452f 14000018 af0b8ecb 13fbc9c0 3ddc7126 5ea2df86 b315bfe0 0d000018 8dfa8e9a 45fb3f9a d80c4b37 858595b4 e72a4c51 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jul 18 15:25:56 racoon: [Unknown Gateway/Dynamic]: DEBUG: 1 times of 420 bytes message will be sent to 213.143.58.28[28087]
    Jul 18 15:25:56 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet to 213.143.58.28[28087]
    Jul 18 15:25:56 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet from xxx.xxx.xxx.xxx[500]
    Jul 18 15:25:56 racoon: [Unknown Gateway/Dynamic]: DEBUG: sockname xxx.xxx.xxx.xxx[500]
    Jul 18 15:25:56 racoon: [Unknown Gateway/Dynamic]: DEBUG: 420 bytes from xxx.xxx.xxx.xxx[500] to 213.143.58.28[28087]
    Jul 18 15:25:46 racoon: DEBUG: resend phase1 packet f463eeebc55d9437:a313717fe3406d24
    Jul 18 15:25:46 racoon: DEBUG: f463eeeb c55d9437 a313717f e3406d24 01100400 00000000 000001a4 0400003c 00000001 00000001 00000030 01010001 00000028 01010000 80010007 800e0080 80020002 80040002 8003fde9 800b0001 000c0004 00015180 0a000084 d20dbe00 06afd31e 63266237 51f286e0 3a92c8af db3ec823 0054ac41 5be78a39 79d7ad9e af074622 cc73b014 d1b6cf63 fbcfe586 86cad8e6 bc9f5681 a3d42d4b d3337a91 700914f6 97d6ad0f f9f1126b 573d7d25 7af41a3f 5504b3d9 15feb27d 9c7195bb 13e60877 fcfd6d41 9e1a429b 0c90fae1 3ebf7d21 c89d55a7 b8d746d5 05000014 ee4bc668 bcfc9db4 195786a3 3c9b3733 0800000c 011101f4 501838e0 0d000018 34673cce 63ad9dfc 06dd1b05 1ef3ad4a 79492baa 0d00000c 09002689 dfd6b712 0d000014 12f5f28c 457168a9 702d9fe2 74cc0100 14000014 4a131c81 07035845 5c5728f2 0e95452f 14000018 af0b8ecb 13fbc9c0 3ddc7126 5ea2df86 b315bfe0 0d000018 8dfa8e9a 45fb3f9a d80c4b37 858595b4 e72a4c51 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jul 18 15:25:46 racoon: [Unknown Gateway/Dynamic]: DEBUG: 1 times of 420 bytes message will be sent to 213.143.58.28[28087]
    Jul 18 15:25:46 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet to 213.143.58.28[28087]
    Jul 18 15:25:46 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet from xxx.xxx.xxx.xxx[500]
    Jul 18 15:25:46 racoon: [Unknown Gateway/Dynamic]: DEBUG: sockname xxx.xxx.xxx.xxx[500]
    Jul 18 15:25:46 racoon: [Unknown Gateway/Dynamic]: DEBUG: 420 bytes from xxx.xxx.xxx.xxx[500] to 213.143.58.28[28087]
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 16, next type 0
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 20, next type 13
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 20, next type 13
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 20, next type 20
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 16, next type 20
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 16, next type 13
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 8, next type 13
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 20, next type 13
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 8, next type 8
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 16, next type 5
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 128, next type 10
    Jul 18 15:25:46 racoon: DEBUG: add payload of len 56, next type 4
    Jul 18 15:25:46 racoon: INFO: Adding xauth VID payload.



  • Read most of this 1st IPSEC page and postings - you are not the only one.



  • I found a raccoon in my IPsec VPN server.
    I try to stick with openvpn.

    IPsec and PPTP are just really touchy protocols. 
    Very fast but easily broken by a litany of conditions.



  • @pinoyboy:

    Read most of this 1st IPSEC page and postings - you are not the only one.

    I take some comfort in knowing I am not alone…though I wish I was...then it would be easier to fix ;)

    I have been reading the forums and trying various configuration changes...without much success.

    I did read somewhere that this is all supposedly fixed in 2.0.4?



  • Suppose to be fixed in 2.1 (with specific and tested settings).  For now, the sites that needed a robust IPSEC connectivity, we went back to 1.2.3; that's rock solid.  There's no need for very specific settings to get it to work since it just works.  I'm not a fan of software that requires exact settings to work; flexibility and availability of various options are there for a reason.



  • @pinoyboy:

    Suppose to be fixed in 2.1 (with specific and tested settings).  For now, the sites that needed a robust IPSEC connectivity, we went back to 1.2.3; that's rock solid.  There's no need for very specific settings to get it to work since it just works.  I'm not a fan of software that requires exact settings to work; flexibility and availability of various options are there for a reason.

    Would you happen to have a link to those specific and tested settings?



  • Do a search on IPSEC with Jimp as poster.  Also, if that doesn't work, try 1.2.3.



  • @pinoyboy:

    Do a search on IPSEC with Jimp as poster.  Also, if that doesn't work, try 1.2.3.

    Thanks for the info. I will try to find it.

    On a side note, do you know if 1.2.3 supports vlan tagging for pppoe?



  • 2.0.2 is rock solid.  2.0.3 is the version that contains the bug, hence my thread about it you'll find in this forum.  You shouldn't need to go back to 1.x for solid IPSec.



  • @Pentangle:

    2.0.2 is rock solid.  2.0.3 is the version that contains the bug, hence my thread about it you'll find in this forum.  You shouldn't need to go back to 1.x for solid IPSec.

    I'll give it a shot. I wonder how this device will handle downgrading from 2.1 to 2.0.2



  • PfSense 2.0.2 seems to be working great. IPSec seems to be stable over the last couple of days.

    There seems to be one issue, which maybe some of you have encountered, Enabling UPNP seems to break ipsec.