IPSEC tunnel issues to a Cisco RV320

stevetoza

Hi All,

Looking for some help with an IPSEC tunnel thats been driving me crazy for 3 days, I have checked both Phase 1 and Phase 2 they exactly match (attached images of both sides) also attached logs from Pfsense, the tunnel just doesn't seem to want to connect and its driving round the bend.

Was wondering if someone could cast their eye over at the logs and settings to see if theres anything I have missed.

0_1527343798786_cisco rv320.png
0_1527343809889_pfsense phase 1.png
0_1527343821891_pfsense phase 2.png

Pfsense Logs

May 26 14:49:18	charon		07[ENC] <con2000|180> parsed ID_PROT response 0 [ SA V ]
May 26 14:49:18	charon		07[IKE] <con2000|180> received DPD vendor ID
May 26 14:49:18	charon		07[CFG] <con2000|180> selecting proposal:
May 26 14:49:18	charon		07[CFG] <con2000|180> proposal matches
May 26 14:49:18	charon		07[CFG] <con2000|180> received proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
May 26 14:49:18	charon		07[CFG] <con2000|180> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
May 26 14:49:18	charon		07[CFG] <con2000|180> selected proposal: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
May 26 14:49:18	charon		07[IKE] <con2000|180> reinitiating already active tasks
May 26 14:49:18	charon		07[IKE] <con2000|180> ISAKMP_VENDOR task
May 26 14:49:18	charon		07[IKE] <con2000|180> MAIN_MODE task
May 26 14:49:18	charon		07[ENC] <con2000|180> generating ID_PROT request 0 [ KE No ]
May 26 14:49:18	charon		07[NET] <con2000|180> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (196 bytes)
May 26 14:49:18	charon		07[NET] <con2000|180> received packet: from xx.159.28.xx[500] to xx.159.77.xx[500] (180 bytes)
May 26 14:49:18	charon		07[ENC] <con2000|180> parsed ID_PROT response 0 [ KE No ]
May 26 14:49:18	charon		07[IKE] <con2000|180> reinitiating already active tasks
May 26 14:49:18	charon		07[IKE] <con2000|180> ISAKMP_VENDOR task
May 26 14:49:18	charon		07[IKE] <con2000|180> MAIN_MODE task
May 26 14:49:18	charon		07[ENC] <con2000|180> generating ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ]
May 26 14:49:18	charon		07[NET] <con2000|180> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (108 bytes)
May 26 14:49:18	charon		07[NET] <con2000|180> received packet: from xx.159.28.xx[500] to xx.159.77.xx[500] (76 bytes)
May 26 14:49:18	charon		07[ENC] <con2000|180> parsed ID_PROT response 0 [ ID HASH ]
May 26 14:49:18	charon		07[IKE] <con2000|180> IKE_SA con2000[180] established between xx.159.77.xx[xx.159.77.xx]...xx.159.28.xx[xx.159.28.xx]
May 26 14:49:18	charon		07[IKE] <con2000|180> IKE_SA con2000[180] state change: CONNECTING => ESTABLISHED
May 26 14:49:18	charon		07[IKE] <con2000|180> activating new tasks
May 26 14:49:18	charon		07[IKE] <con2000|180> activating QUICK_MODE task
May 26 14:49:18	charon		07[CFG] <con2000|180> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ
May 26 14:49:18	charon		07[CFG] <con2000|180> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ
May 26 14:49:18	charon		07[CFG] <con2000|180> proposing traffic selectors for us:
May 26 14:49:18	charon		07[CFG] <con2000|180> 192.168.50.0/24|/0
May 26 14:49:18	charon		07[CFG] <con2000|180> proposing traffic selectors for other:
May 26 14:49:18	charon		07[CFG] <con2000|180> 192.168.10.0/24|/0
May 26 14:49:18	charon		07[ENC] <con2000|180> generating QUICK_MODE request 298453xx43 [ HASH SA No KE ID ID ]
May 26 14:49:18	charon		07[NET] <con2000|180> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (316 bytes)
May 26 14:49:18	charon		15[NET] <con2000|180> received packet: from xx.159.28.xx[500] to xx.159.77.xx[500] (92 bytes)
May 26 14:49:18	charon		15[ENC] <con2000|180> parsed INFORMATIONAL_V1 request 2420651128 [ HASH D ]
May 26 14:49:18	charon		15[IKE] <con2000|180> received DELETE for IKE_SA con2000[180]
May 26 14:49:18	charon		15[IKE] <con2000|180> deleting IKE_SA con2000[180] between xx.159.77.xx[xx.159.77.xx]...xx.159.28.xx[xx.159.28.xx]
May 26 14:49:18	charon		15[IKE] <con2000|180> IKE_SA con2000[180] state change: ESTABLISHED => DELETING
May 26 14:49:18	charon		15[CHD] <con2000|180> CHILD_SA con2000{181} state change: CREATED => DESTROYING
May 26 14:49:18	charon		15[IKE] <con2000|180> queueing ISAKMP_VENDOR task
May 26 14:49:18	charon		15[IKE] <con2000|180> queueing ISAKMP_CERT_PRE task
May 26 14:49:18	charon		15[IKE] <con2000|180> queueing MAIN_MODE task
May 26 14:49:18	charon		15[IKE] <con2000|180> queueing ISAKMP_CERT_POST task
May 26 14:49:18	charon		15[IKE] <con2000|180> queueing ISAKMP_NATD task
May 26 14:49:18	charon		15[IKE] <con2000|180> activating new tasks
May 26 14:49:18	charon		15[IKE] <con2000|180> activating ISAKMP_VENDOR task
May 26 14:49:18	charon		15[IKE] <con2000|180> activating ISAKMP_CERT_PRE task

May 26 14:49:32	charon		15[CFG] <con2000|266> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ
May 26 14:49:32	charon		15[CFG] <con2000|266> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ
May 26 14:49:32	charon		15[CFG] <con2000|266> proposing traffic selectors for us:
May 26 14:49:32	charon		15[CFG] <con2000|266> 192.168.50.0/24|/0
May 26 14:49:32	charon		15[CFG] <con2000|266> proposing traffic selectors for other:
May 26 14:49:32	charon		15[CFG] <con2000|266> 192.168.10.0/24|/0
May 26 14:49:32	charon		15[ENC] <con2000|266> generating QUICK_MODE request 1959359xx5 [ HASH SA No KE ID ID ]
May 26 14:49:32	charon		15[NET] <con2000|266> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (316 bytes)
May 26 14:49:32	charon		06[NET] <con2000|266> received packet: from xx.159.28.xx[500] to xx.159.77.xx[500] (92 bytes)
May 26 14:49:32	charon		06[ENC] <con2000|266> parsed INFORMATIONAL_V1 request 840093170 [ HASH D ]
May 26 14:49:32	charon		06[IKE] <con2000|266> received DELETE for IKE_SA con2000[266]
May 26 14:49:32	charon		06[IKE] <con2000|266> deleting IKE_SA con2000[266] between xx.159.77.xx[xx.159.77.xx]...xx.159.28.xx[xx.159.28.xx]
May 26 14:49:32	charon		06[IKE] <con2000|266> IKE_SA con2000[266] state change: ESTABLISHED => DELETING
May 26 14:49:32	charon		06[CHD] <con2000|266> CHILD_SA con2000{267} state change: CREATED => DESTROYING
May 26 14:49:32	charon		06[IKE] <con2000|266> queueing ISAKMP_VENDOR task
May 26 14:49:32	charon		06[IKE] <con2000|266> queueing ISAKMP_CERT_PRE task
May 26 14:49:32	charon		06[IKE] <con2000|266> queueing MAIN_MODE task
May 26 14:49:32	charon		06[IKE] <con2000|266> queueing ISAKMP_CERT_POST task
May 26 14:49:32	charon		06[IKE] <con2000|266> queueing ISAKMP_NATD task
May 26 14:49:32	charon		06[IKE] <con2000|266> activating new tasks
May 26 14:49:32	charon		06[IKE] <con2000|266> activating ISAKMP_VENDOR task
May 26 14:49:32	charon		06[IKE] <con2000|266> activating ISAKMP_CERT_PRE task
May 26 14:49:32	charon		06[IKE] <con2000|266> activating MAIN_MODE task
May 26 14:49:32	charon		06[IKE] <con2000|266> activating ISAKMP_CERT_POST task
May 26 14:49:32	charon		06[IKE] <con2000|266> activating ISAKMP_NATD task
May 26 14:49:32	charon		06[IKE] <con2000|266> sending XAuth vendor ID
May 26 14:49:32	charon		06[IKE] <con2000|266> sending DPD vendor ID
May 26 14:49:32	charon		06[IKE] <con2000|266> sending FRAGMENTATION vendor ID
May 26 14:49:32	charon		06[IKE] <con2000|266> sending NAT-T (RFC 3947) vendor ID
May 26 14:49:32	charon		06[IKE] <con2000|266> sending draft-ietf-ipsec-nat-t-ike-02\n vendor ID
May 26 14:49:32	charon		06[IKE] <con2000|266> initiating Main Mode IKE_SA con2000[267] to xx.159.28.xx
May 26 14:49:32	charon		06[IKE] <con2000|266> IKE_SA con2000[267] state change: CREATED => CONNECTING
May 26 14:49:32	charon		06[CFG] <con2000|266> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
May 26 14:49:32	charon		06[ENC] <con2000|266> generating ID_PROT request 0 [ SA V V V V V ]
May 26 14:49:32	charon		06[NET] <con2000|266> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (180 bytes)
May 26 14:49:32	charon		06[IKE] <con2000|266> IKE_SA con2000[266] state change: DELETING => DELETING
May 26 14:49:32	charon		06[IKE] <con2000|266> IKE_SA con2000[266] state change: DELETING => DESTROYING
May 26 14:49:32	charon		06[NET] <con2000|267> received packet: from xx.159.28.xx[500] to xx.159.77.xx[500] (104 bytes)
May 26 14:49:32	charon		06[ENC] <con2000|267> parsed ID_PROT response 0 [ SA V ]
May 26 14:49:32	charon		06[IKE] <con2000|267> received DPD vendor ID
May 26 14:49:32	charon		06[CFG] <con2000|267> selecting proposal:
May 26 14:49:32	charon		06[CFG] <con2000|267> proposal matches
May 26 14:49:32	charon		06[CFG] <con2000|267> received proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
May 26 14:49:32	charon		06[CFG] <con2000|267> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
May 26 14:49:32	charon		06[CFG] <con2000|267> selected proposal: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
May 26 14:49:32	charon		06[IKE] <con2000|267> reinitiating already active tasks
May 26 14:49:32	charon		06[IKE] <con2000|267> ISAKMP_VENDOR task
May 26 14:49:32	charon		06[IKE] <con2000|267> MAIN_MODE task
May 26 14:49:32	charon		06[ENC] <con2000|267> generating ID_PROT request 0 [ KE No ]
May 26 14:49:32	charon		06[NET] <con2000|267> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (196 bytes)

RV320 Logs

2018-05-26, 14:43:42	VPN Log	[g2gips0] #1220: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1221: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1222: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1223: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1224: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1225: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1226: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1227: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1228: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1229: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1230: [Tunnel Established] sent MR3, ISAKMP SA established
2018-05-26, 14:43:42	VPN Log	[g2gips0] #1231: [Tunnel Established] sent MR3, ISAKMP SA established

Thanks
Steve

stevetoza

Bit further along ... Seems if the Cisco RV320 initialises the tunnel the tunnel comes up and everything is working fine, but if I initialise the tunnel on the pfSense side by pinging that subnet this is when the tunnel fails to come up

if the pfsense side is the IKEv1 responder = IPSEC tunnel comes up and works
if the pfsense side is the IKEv1 initiator = IPSEC tunnel fails to come up

Derelict

Try unchecking that disable renegotiation checkbox on the pfSense phase 1.

stevetoza

@derelict - That fixes it! Thank you :) , cant believe I was one check box away from getting it working

stevetoza

@derelict - I notice that this IPSEC tunnel tries to keep itself up all the time now, my other IPSEC tunnel disconnects after so long when theres no traffic. There any other settings I need to change on the pfsense to get the same behaviour. Thanks

Derelict

Something is keeping it up or you are not waiting long enough. Your P1 lifetime is 24 hours. P2 is 6 hours.

The P2 Automatically ping host setting is used to generate traffic interesting to IPsec and keep a tunnel up. You do not have that set.

stevetoza

@derelict - Restarted the Cisco router the other end, initiated some traffic and have left it for a couple of hours and the tunnel is still up

ESTABLISHED 10197 seconds (02:49:57) ago

Checked the Pfsense logs and seems pfsense is sending packets to the cisco side and back keeping the tunnel up

15[IKE] <con2000|2> activating new tasks
May 27 22:09:52	charon		15[IKE] <con2000|2> activating ISAKMP_DPD task
May 27 22:09:52	charon		15[ENC] <con2000|2> generating INFORMATIONAL_V1 request 591633065 [ HASH N(DPD) ]
May 27 22:09:52	charon		15[NET] <con2000|2> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (92 bytes)
May 27 22:09:52	charon		15[IKE] <con2000|2> activating new tasks
May 27 22:09:52	charon		15[IKE] <con2000|2> nothing to initiate
May 27 22:09:52	charon		15[NET] <con2000|2> received packet: from xx.159.28.xx[500] to xx.159.77.xx[500] (92 bytes)
May 27 22:09:52	charon		15[ENC] <con2000|2> parsed INFORMATIONAL_V1 request 2024435232 [ HASH N(DPD_ACK) ]
May 27 22:09:52	charon		15[IKE] <con2000|2> activating new tasks
May 27 22:09:52	charon		15[IKE] <con2000|2> nothing to initiate
May 27 22:09:54	charon		10[CFG] vici client 253 connected
May 27 22:09:54	charon		12[CFG] vici client 253 registered for: list-sa
May 27 22:09:54	charon		10[CFG] vici client 253 requests: list-sas
May 27 22:09:54	charon		12[CFG] vici client 253 disconnected
May 27 22:10:00	charon		10[CFG] vici client 254 connected
May 27 22:10:00	charon		08[CFG] vici client 254 registered for: list-sa
May 27 22:10:00	charon		08[CFG] vici client 254 requests: list-sas
May 27 22:10:00	charon		08[CFG] vici client 254 disconnected
May 27 22:10:02	charon		08[IKE] <con2000|2> sending DPD request
May 27 22:10:02	charon		08[IKE] <con2000|2> queueing ISAKMP_DPD task
May 27 22:10:02	charon		08[IKE] <con2000|2> activating new tasks
May 27 22:10:02	charon		08[IKE] <con2000|2> activating ISAKMP_DPD task
May 27 22:10:02	charon		08[ENC] <con2000|2> generating INFORMATIONAL_V1 request 4117561926 [ HASH N(DPD) ]
May 27 22:10:02	charon		08[NET] <con2000|2> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (92 bytes)
May 27 22:10:02	charon		08[IKE] <con2000|2> activating new tasks
May 27 22:10:02	charon		08[IKE] <con2000|2> nothing to initiate
May 27 22:10:02	charon		08[NET] <con2000|2> received packet: from xx.159.28.xx[500] to xx.159.77.xx[500] (92 bytes)
May 27 22:10:02	charon		08[ENC] <con2000|2> parsed INFORMATIONAL_V1 request 3487328383 [ HASH N(DPD_ACK) ]
May 27 22:10:02	charon		08[IKE] <con2000|2> activating new tasks
May 27 22:10:02	charon		08[IKE] <con2000|2> nothing to initiate
May 27 22:10:05	charon		10[CFG] vici client 255 connected
May 27 22:10:05	charon		06[CFG] vici client 255 registered for: list-sa
May 27 22:10:05	charon		06[CFG] vici client 255 requests: list-sas
May 27 22:10:05	charon		08[CFG] vici client 255 disconnected
May 27 22:10:10	charon		10[CFG] vici client 256 connected
May 27 22:10:10	charon		14[CFG] vici client 256 registered for: list-sa
May 27 22:10:10	charon		14[CFG] vici client 256 requests: list-sas
May 27 22:10:10	charon		14[CFG] vici client 256 disconnected
May 27 22:10:12	charon		10[IKE] <con2000|2> sending DPD request
May 27 22:10:12	charon		10[IKE] <con2000|2> queueing ISAKMP_DPD task
May 27 22:10:12	charon		10[IKE] <con2000|2> activating new tasks
May 27 22:10:12	charon		10[IKE] <con2000|2> activating ISAKMP_DPD task
May 27 22:10:12	charon		10[ENC] <con2000|2> generating INFORMATIONAL_V1 request 3558210549 [ HASH N(DPD) ]
May 27 22:10:12	charon		10[NET] <con2000|2> sending packet: from xx.159.77.xx[500] to xx.159.28.xx[500] (92 bytes)
May 27 22:10:12	charon		10[IKE] <con2000|2> activating new tasks
May 27 22:10:12	charon		10[IKE] <con2000|2> nothing to initiate
May 27 22:10:12	charon		14[NET] <con2000|2> received packet: from xx.159.28.xx[500] to xx.159.77.xx[500] (92 bytes)
May 27 22:10:12	charon		14[ENC] <con2000|2> parsed INFORMATIONAL_V1 request 3190363268 [ HASH N(DPD_ACK) ]
May 27 22:10:12	charon		14[IKE] <con2000|2> activating new tasks
May 27 22:10:12	charon		14[IKE] <con2000|2> nothing to initiate

The tunnel was going down previously before I replaced the router this side from a cisco rv320 with a pfsense router.

Thanks
Steve

Derelict

Like I said. Your timeouts are 24 hours and 6 hours.

Why are you sweating this?

What you are seeing is dead peer detection, not traffic that should keep the tunnel up.

stevetoza

@derelict - have amended the timeouts - was expecting the same as the other ipsec tunnel to the cisco asa. Its cool :)

Would like to say thanks for all the help! :) Loving Pfsense so far

cukal

@stevetoza Off-Topic but here goes. We've experienced all sorts of things with the Cisco RV325 series. Stability however isn’t one of them when running several heavy traffic IPSec tunnels. We swapped out our RV320/325's for virtual pfSense appliances. After a lengthy support thread with a very helpful Cisco support guy they swapped all our units for the new RV340 which is a significantly better hardware platform but since we've been bitten quite a few times by RV320's just going dark on us we now use them as expensive switches. SNMP showed that each time they went offline it was because of pure memory starvation. An RV325 unit with 5 IPSec tunnels and a bunch of local attached stuff would keep running for max 2-3 weeks and then would slowly die, first the web-console would stop responding (and it's already painstakingly slow) and a few hours later all the IPSec tunnels would become unresponsive. There's no automation for these boxes and we don't have managed PDU's so instead of driving to the site location to switch them literally off & back on I rolled some selenium GUI manipulation to power-cycle them every week like that. Seriously. Also had to power cycle twice because sometimes the first reboot wouldn't bring up the IPSec tunnels and when that happened they would never become active, only a secondary reboot would fix that.
Seeing your print screen of the web-console throws me back to a lonely, dark and painful place ;)