On and Off again VPN using IPSec
-
Hi all.
Am using pfsense and a client is on cisco. While other links on my system go down and auto come back on, this specific link doesn't and it takes time only for it to connect when we least expect it to. Below are my Logs. What could be the issue?
Mar 7 14:06:09 racoon: DEBUG: purged SAs. Mar 7 14:06:09 racoon: DEBUG: IV freed Mar 7 14:06:09 racoon: [Client VPN]: INFO: ISAKMP-SA deleted 40.210.82.190[500]-210.20.110.160[500] spi:4dfa6e44d5965dfc:84d89f0357d42c7c Mar 7 14:06:09 racoon: INFO: purged ISAKMP-SA spi=4dfa6e44d5965dfc:84d89f0357d42c7c. Mar 7 14:06:09 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:06:09 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:06:09 racoon: DEBUG: call pfkey_send_dump Mar 7 14:06:09 racoon: INFO: purging ISAKMP-SA spi=4dfa6e44d5965dfc:84d89f0357d42c7c. Mar 7 14:06:09 racoon: [Client VPN]: [210.20.110.160] DEBUG: delete payload for protocol ISAKMP Mar 7 14:06:09 racoon: DEBUG: succeed. Mar 7 14:06:09 racoon: DEBUG: seen nptype=12(delete) Mar 7 14:06:09 racoon: DEBUG: seen nptype=8(hash) Mar 7 14:06:09 racoon: DEBUG: begin. Mar 7 14:06:09 racoon: DEBUG: hash validated. Mar 7 14:06:09 racoon: DEBUG: 9ef360c3 c40951de ad536a78 3bef168c d85e4e52 Mar 7 14:06:09 racoon: DEBUG: HASH computed: Mar 7 14:06:09 racoon: DEBUG: hmac(hmac_sha1) Mar 7 14:06:09 racoon: DEBUG: f9a9a0d1 0000001c 00000001 01100001 4dfa6e44 d5965dfc 84d89f03 57d42c7c Mar 7 14:06:09 racoon: DEBUG: HASH with: Mar 7 14:06:09 racoon: DEBUG: IV freed Mar 7 14:06:09 racoon: DEBUG: 4dfa6e44 d5965dfc 84d89f03 57d42c7c 08100501 f9a9a0d1 0000005c 0c000018 9ef360c3 c40951de ad536a78 3bef168c d85e4e52 0000001c 00000001 01100001 4dfa6e44 d5965dfc 84d89f03 57d42c7c 00000000 00000000 00000000 Mar 7 14:06:09 racoon: DEBUG: decrypted. Mar 7 14:06:09 racoon: DEBUG: skip to trim padding. Mar 7 14:06:09 racoon: DEBUG: padding len=1 Mar 7 14:06:09 racoon: DEBUG: 0c000018 9ef360c3 c40951de ad536a78 3bef168c d85e4e52 0000001c 00000001 01100001 4dfa6e44 d5965dfc 84d89f03 57d42c7c 00000000 00000000 00000000 Mar 7 14:06:09 racoon: DEBUG: decrypted payload, but not trimed. Mar 7 14:06:09 racoon: DEBUG: b0337beb 0d4e6743 5450fbbb b8015e38 Mar 7 14:06:09 racoon: DEBUG: decrypted payload by IV: Mar 7 14:06:09 racoon: DEBUG: 4b8527ae a61d602d e928bc06 b5d0b249 32fe8fb7 034207de f770d70f fe84cc09 Mar 7 14:06:09 racoon: DEBUG: with key: Mar 7 14:06:09 racoon: DEBUG: encryption(aes) Mar 7 14:06:09 racoon: DEBUG: 15821bd6 9bb1217e 64121531 b7212fa5 Mar 7 14:06:09 racoon: DEBUG: IV was saved for next processing: Mar 7 14:06:09 racoon: DEBUG: encryption(aes) Mar 7 14:06:09 racoon: DEBUG: begin decryption. Mar 7 14:06:09 racoon: DEBUG: b0337beb 0d4e6743 5450fbbb b8015e38 Mar 7 14:06:09 racoon: DEBUG: phase2 IV computed: Mar 7 14:06:09 racoon: DEBUG: encryption(aes) Mar 7 14:06:09 racoon: DEBUG: hash(sha1) Mar 7 14:06:09 racoon: DEBUG: b5239361 8b7a28c9 8a7ac436 457a9b3c f9a9a0d1 Mar 7 14:06:09 racoon: DEBUG: phase1 last IV: Mar 7 14:06:09 racoon: DEBUG: compute IV for phase2 Mar 7 14:06:09 racoon: DEBUG: receive Information. Mar 7 14:06:09 racoon: DEBUG: 4dfa6e44 d5965dfc 84d89f03 57d42c7c 08100501 f9a9a0d1 0000005c 3092e0c7 5d2a1583 e9590417 f345557a 9a7f84c7 00496c67 07925b41 e33e52c1 e22d5494 7fc77d56 a38723c6 0743acca 15821bd6 9bb1217e 64121531 b7212fa5 Mar 7 14:06:09 racoon: DEBUG: 92 bytes message received from 210.20.110.160[500] to 40.210.82.190[500] Mar 7 14:06:09 racoon: DEBUG: === Mar 7 14:06:09 racoon: DEBUG: === Mar 7 14:06:09 racoon: [Client VPN]: INFO: ISAKMP-SA established 40.210.82.190[500]-210.20.110.160[500] spi:4dfa6e44d5965dfc:84d89f0357d42c7c Mar 7 14:06:09 racoon: DEBUG: 4dfa6e44 d5965dfc 84d89f03 57d42c7c 08100400 00000000 00000064 82000018 c5fe123d bf420577 eb640f4b 9f1b3c98 4c9baffe 82000018 8ed13bd3 df9a3f33 1c971878 a8c2e111 aa5cc816 00000018 a28790ce 528e5a3a f4c2ee1c a7067eb7 2b1ca334 Mar 7 14:06:09 racoon: DEBUG: 1 times of 100 bytes message will be sent to 210.20.110.160[500] Mar 7 14:06:09 racoon: DEBUG: send packet to 210.20.110.160[500] Mar 7 14:06:09 racoon: DEBUG: send packet from 40.210.82.190[500] Mar 7 14:06:09 racoon: DEBUG: sockname 40.210.82.190[500] Mar 7 14:06:09 racoon: DEBUG: 100 bytes from 40.210.82.190[500] to 210.20.110.160[500] Mar 7 14:06:09 racoon: DEBUG: add payload of len 20, next type 0 Mar 7 14:06:09 racoon: DEBUG: add payload of len 20, next type 130 Mar 7 14:06:09 racoon: DEBUG: add payload of len 20, next type 130 Mar 7 14:06:09 racoon: DEBUG: hash(sha1) Mar 7 14:06:09 racoon: [Self]: [40.210.82.190] INFO: Hashing 40.210.82.190[500] with algo #2 Mar 7 14:06:09 racoon: DEBUG: hash(sha1) Mar 7 14:06:09 racoon: [Client VPN]: [210.20.110.160] INFO: Hashing 210.20.110.160[500] with algo #2 Mar 7 14:06:09 racoon: INFO: Adding remote and local NAT-D payloads. Mar 7 14:06:09 racoon: DEBUG: c5fe123d bf420577 eb640f4b 9f1b3c98 4c9baffe Mar 7 14:06:09 racoon: DEBUG: HASH (init) computed: Mar 7 14:06:09 racoon: DEBUG: hmac(hmac_sha1) Mar 7 14:06:09 racoon: DEBUG: 490ccf39 eb4a8bbf 3af5956c fb3895f2 5189a53e 02e1a920 b4e5342b b0f30b24 c30cfbe8 c841fa06 5800bf8a 6a121ded 646cbc81 e7890afb 7f1c8fb4 10f01f33 b78536ab da01cde7 4dff1623 e61eb8e4 3396248e 02f29901 719eae7b 6f51d850 9d78cacd 4f682f0d 6831250b bfb17414 773a4c08 0c9842ea af93d041 dcbb976a 4b57f3ed a028c0b3 a29a48db 2b88f566 70f35727 82087b50 abba8d15 91d8b698 07484acf d834d753 1b7acbce a529e885 07ffd0f8 696c2b0f b678933d 50b942fa 4f6e30f8 ce97b910 c20b64a2 836ea9da a3fb75ae fedeaeac dfc35184 d9352ebc 6bdb95b2 e93af303 a2f54234 16b13ea5 129e46d0 b2d419b3 8ce4aac6 a8430ce5 f6c3262d 40083d8e 408570ff 1d0778c1 92ecaba8 9b8e7f04 392f018f cb5d07cc 1e63a7c6 a6d4b27f a2d31f0c c48f9c02 554c123b 8145411a 75c64d09 78c8e878 1969a974 b63ae36f 50eee7ba d5ab7488 b9e204a1 18039fd2 7cd012c7 6feb275c afe66b2b d9118b72 fcfe47f0 dfaee7d2 4e74ba50 701fb1a8 edff0b61 bd9de9fe 4dfa6e44 d5965dfc 84d89f03 57d42c7c 00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 800c7080 80010007 800e010 Mar 7 14:06:09 racoon: DEBUG: HASH with: Mar 7 14:06:09 racoon: DEBUG: generate HASH_I Mar 7 14:06:09 racoon: DEBUG: === Mar 7 14:06:09 racoon: DEBUG: HASH for PSK validated. Mar 7 14:06:09 racoon: DEBUG: 9009afad 2ccc1256 ec5a5995 8c87487e 6ed360e5 Mar 7 14:06:09 racoon: DEBUG: HASH (init) computed: Mar 7 14:06:09 racoon: DEBUG: hmac(hmac_sha1) Mar 7 14:06:09 racoon: DEBUG: 4f6e30f8 ce97b910 c20b64a2 836ea9da a3fb75ae fedeaeac dfc35184 d9352ebc 6bdb95b2 e93af303 a2f54234 16b13ea5 129e46d0 b2d419b3 8ce4aac6 a8430ce5 f6c3262d 40083d8e 408570ff 1d0778c1 92ecaba8 9b8e7f04 392f018f cb5d07cc 1e63a7c6 a6d4b27f a2d31f0c c48f9c02 554c123b 8145411a 75c64d09 78c8e878 1969a974 b63ae36f 50eee7ba d5ab7488 b9e204a1 18039fd2 7cd012c7 6feb275c afe66b2b d9118b72 fcfe47f0 dfaee7d2 4e74ba50 701fb1a8 edff0b61 bd9de9fe 490ccf39 eb4a8bbf 3af5956c fb3895f2 5189a53e 02e1a920 b4e5342b b0f30b24 c30cfbe8 c841fa06 5800bf8a 6a121ded 646cbc81 e7890afb 7f1c8fb4 10f01f33 b78536ab da01cde7 4dff1623 e61eb8e4 3396248e 02f29901 719eae7b 6f51d850 9d78cacd 4f682f0d 6831250b bfb17414 773a4c08 0c9842ea af93d041 dcbb976a 4b57f3ed a028c0b3 a29a48db 2b88f566 70f35727 82087b50 abba8d15 91d8b698 07484acf d834d753 1b7acbce a529e885 07ffd0f8 696c2b0f b678933d 50b942fa 84d89f03 57d42c7c 4dfa6e44 d5965dfc 00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 800c7080 80010007 800e010 Mar 7 14:06:09 racoon: DEBUG: HASH with: Mar 7 14:06:09 racoon: DEBUG: 9009afad 2ccc1256 ec5a5995 8c87487e 6ed360e5 Mar 7 14:06:09 racoon: DEBUG: HASH received: Mar 7 14:06:09 racoon: DEBUG: b5239361 8b7a28c9 8a7ac436 457a9b3c Mar 7 14:06:09 racoon: DEBUG: IV computed: Mar 7 14:06:09 racoon: DEBUG: encryption(aes)
Another error am getting is as below:
Mar 7 14:38:12 racoon: DEBUG: ignore the acquire because ph2 found Mar 7 14:38:12 racoon: [Unknown Gateway/Dynamic]: DEBUG: suitable outbound SP found: 192.168.21.50/32[0] 172.16.25.100/32[0] proto=any dir=out. Mar 7 14:38:12 racoon: DEBUG: got pfkey ACQUIRE message Mar 7 14:38:12 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:38:10 racoon: DEBUG: ignore the acquire because ph2 found Mar 7 14:38:10 racoon: [Unknown Gateway/Dynamic]: DEBUG: suitable outbound SP found: 192.168.21.50/32[0] 172.16.25.100/32[0] proto=any dir=out. Mar 7 14:38:10 racoon: DEBUG: got pfkey ACQUIRE message Mar 7 14:38:10 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:38:09 racoon: DEBUG: ignore the acquire because ph2 found Mar 7 14:38:09 racoon: [Unknown Gateway/Dynamic]: DEBUG: suitable outbound SP found: 192.168.21.50/32[0] 172.16.25.100/32[0] proto=any dir=out. Mar 7 14:38:09 racoon: DEBUG: got pfkey ACQUIRE message Mar 7 14:38:09 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:38:08 racoon: DEBUG: ignore the acquire because ph2 found Mar 7 14:38:08 racoon: [Unknown Gateway/Dynamic]: DEBUG: suitable outbound SP found: 192.168.21.50/32[0] 172.16.25.100/32[0] proto=any dir=out. Mar 7 14:38:08 racoon: DEBUG: got pfkey ACQUIRE message Mar 7 14:38:08 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:38:06 racoon: DEBUG: ignore the acquire because ph2 found Mar 7 14:38:06 racoon: [Unknown Gateway/Dynamic]: DEBUG: suitable outbound SP found: 192.168.21.50/32[0] 172.16.25.100/32[0] proto=any dir=out. Mar 7 14:38:06 racoon: DEBUG: got pfkey ACQUIRE message Mar 7 14:38:06 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:38:05 racoon: DEBUG: ignore the acquire because ph2 found Mar 7 14:38:05 racoon: [Unknown Gateway/Dynamic]: DEBUG: suitable outbound SP found: 192.168.21.50/32[0] 172.16.25.100/32[0] proto=any dir=out. Mar 7 14:38:05 racoon: DEBUG: got pfkey ACQUIRE message Mar 7 14:38:05 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:38:04 racoon: DEBUG: ignore the acquire because ph2 found Mar 7 14:38:04 racoon: [Unknown Gateway/Dynamic]: DEBUG: suitable outbound SP found: 192.168.21.50/32[0] 172.16.4.160/32[0] proto=any dir=out. Mar 7 14:38:04 racoon: DEBUG: got pfkey ACQUIRE message Mar 7 14:38:04 racoon: DEBUG: pk_recv: retry[0] recv() Mar 7 14:38:04 racoon: DEBUG: ignore the acquire because ph2 found Mar 7 14:38:04 racoon: [Unknown Gateway/Dynamic]: DEBUG: suitable outbound SP found: 192.168.21.50/32[0] 172.16.25.100/32[0] proto=any dir=out.
Thanks.
-
Have you tested to see if the tunnel will properly re-establish if you attempt to do it from the cisco side?
I had some issues a long time ago where the cisco clock was off or something and it would cause issues where the re-negotiation would fail unless it was sent from the cisco system to the pf system.
If I remember correctly, we fixed it by setting the cisco to use the same time server as the pf-sense system. Strange and should not have caused an issue… but stranger things have happened ;)
-E
-
I am having the same problem with this, it will not re-establish from CISCO side, no problem from pfsense to CISCO site