HELP Please: IPSEC to/from Amazon VPN
-
I am very close to getting this working. Could you please suggest some debug tips to get me the last way?
I'm following guides here:
http://www.seattleit.net/blog/pfsense-ipsec-vpn-gateway-amazon-vpc-bgp-routing/and here:
http://complaintsincorporated.com/2012/07/27/amazon-vpc-adventure-customer-gateway-on-the-cheap/I have the tunnels up and BOTH ends (pfSense) and Amazon show GREEN.
I can't ping across however!!
How can I debug this further? I've spent much time searching the forum. I've read the the IPSEC Troubleshooting page:
http://doc.pfsense.org/index.php/IPsec_TroubleshootingHere is racooon interactive;
###.###.###.### = WAN IP
Foreground mode.
2013-01-26 09:02:49: INFO: @(#)ipsec-tools 0.8.0 (http://ipsec-tools.sourceforge.net)
2013-01-26 09:02:49: INFO: @(#)This product linked OpenSSL 0.9.8n 24 Mar 2010 (http://www.openssl.org/)
2013-01-26 09:02:49: INFO: Reading configuration from "/var/etc/racoon.conf"
2013-01-26 09:02:49: DEBUG: call pfkey_send_register for AH
2013-01-26 09:02:49: DEBUG: call pfkey_send_register for ESP
2013-01-26 09:02:49: DEBUG: call pfkey_send_register for IPCOMP
2013-01-26 09:02:49: DEBUG: reading config file /var/etc/racoon.conf
2013-01-26 09:02:49: DEBUG: no check of compression algorithm; not supported in sadb message.
2013-01-26 09:02:49: DEBUG: getsainfo params: loc='169.254.249.6/30' rmt='169.254.249.5/30' peer='NULL' client='NULL' id=1
2013-01-26 09:02:49: DEBUG: no check of compression algorithm; not supported in sadb message.
2013-01-26 09:02:49: DEBUG: getsainfo params: loc='169.254.249.2/30' rmt='169.254.249.1/30' peer='NULL' client='NULL' id=2
2013-01-26 09:02:49: DEBUG: evaluating sainfo: loc='169.254.249.6/30', rmt='169.254.249.5/30', peer='ANY', id=1
2013-01-26 09:02:49: DEBUG: remoteid mismatch: 1 != 2
2013-01-26 09:02:49: DEBUG: open /var/db/racoon/racoon.sock as racoon management.
2013-01-26 09:02:49: INFO: ###.###.###.###[4500] used for NAT-T
2013-01-26 09:02:49: INFO: ###.###.###.###[4500] used as isakmp port (fd=7)
2013-01-26 09:02:49: INFO: ###.###.###.###[500] used for NAT-T
2013-01-26 09:02:49: INFO: ###.###.###.###[500] used as isakmp port (fd=8)
2013-01-26 09:02:49: DEBUG: pk_recv: retry[0] recv()
2013-01-26 09:02:49: DEBUG: got pfkey X_SPDDUMP message
2013-01-26 09:02:49: DEBUG: pk_recv: retry[0] recv()
2013-01-26 09:02:49: DEBUG: got pfkey X_SPDDUMP message
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.5/30[0] 169.254.249.6/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: db :0x28548148: 192.168.1.0/24[0] 192.168.1.1/32[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: pk_recv: retry[0] recv()
2013-01-26 09:02:49: DEBUG: got pfkey X_SPDDUMP message
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.1/30[0] 169.254.249.2/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: db :0x28548148: 192.168.1.0/24[0] 192.168.1.1/32[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.1/30[0] 169.254.249.2/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: db :0x28548288: 169.254.249.5/30[0] 169.254.249.6/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: pk_recv: retry[0] recv()
2013-01-26 09:02:49: DEBUG: got pfkey X_SPDDUMP message
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 192.168.1.1/32[0] 192.168.1.0/24[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548148: 192.168.1.0/24[0] 192.168.1.1/32[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 192.168.1.1/32[0] 192.168.1.0/24[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548288: 169.254.249.5/30[0] 169.254.249.6/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 192.168.1.1/32[0] 192.168.1.0/24[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548508: 169.254.249.1/30[0] 169.254.249.2/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: pk_recv: retry[0] recv()
2013-01-26 09:02:49: DEBUG: got pfkey X_SPDDUMP message
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.6/30[0] 169.254.249.5/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548148: 192.168.1.0/24[0] 192.168.1.1/32[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.6/30[0] 169.254.249.5/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548288: 169.254.249.5/30[0] 169.254.249.6/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.6/30[0] 169.254.249.5/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548508: 169.254.249.1/30[0] 169.254.249.2/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.6/30[0] 169.254.249.5/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548788: 192.168.1.1/32[0] 192.168.1.0/24[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: pk_recv: retry[0] recv()
2013-01-26 09:02:49: DEBUG: got pfkey X_SPDDUMP message
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.2/30[0] 169.254.249.1/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548148: 192.168.1.0/24[0] 192.168.1.1/32[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.2/30[0] 169.254.249.1/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548288: 169.254.249.5/30[0] 169.254.249.6/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.2/30[0] 169.254.249.1/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548508: 169.254.249.1/30[0] 169.254.249.2/30[0] proto=any dir=in
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.2/30[0] 169.254.249.1/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x28548788: 192.168.1.1/32[0] 192.168.1.0/24[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: sub:0xbfbfe5b4: 169.254.249.2/30[0] 169.254.249.1/30[0] proto=any dir=out
2013-01-26 09:02:49: DEBUG: db :0x285488c8: 169.254.249.6/30[0] 169.254.249.5/30[0] proto=any dir=outBut when I run racoon normally and check the logs I see this every 10 seconds:
###.###.###.### = WAN IP
Jan 26 09:24:43 racoon: [Unknown Gateway/Dynamic]: DEBUG: 92 bytes from ###.###.###.###[500] to 205.251.233.121[500]
Jan 26 09:24:43 racoon: [Unknown Gateway/Dynamic]: DEBUG: sockname ###.###.###.###[500]
Jan 26 09:24:43 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet from ###.###.###.###[500]
Jan 26 09:24:43 racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet to 205.251.233.121[500]
Jan 26 09:24:43 racoon: [Unknown Gateway/Dynamic]: DEBUG: 1 times of 92 bytes message will be sent to 205.251.233.121[500]Any debugging guidance would be appreciated.
-
I little more to the puzzle.
When I ping FROM and Amazon server TO a server on my LAN, I can see the icmp packet reach my LAN server with wireshark, but the request doesn't make it's way back to the source.
I am so close….
-
A better trace.
[2.0.2-RELEASE][admin@pfsense.localdomain]/root(11): racoon -F -v -f /var/etc/racoon.conf
Foreground mode.
2013-01-26 18:06:35: INFO: @(#)ipsec-tools 0.8.0 (http://ipsec-tools.sourceforge.net)
2013-01-26 18:06:35: INFO: @(#)This product linked OpenSSL 0.9.8n 24 Mar 2010 (http://www.openssl.org/)
2013-01-26 18:06:35: INFO: Reading configuration from "/var/etc/racoon.conf"
2013-01-26 18:06:35: INFO: ###.###.###.###[4500] used for NAT-T
2013-01-26 18:06:35: INFO: ###.###.###.###[4500] used as isakmp port (fd=7)
2013-01-26 18:06:35: INFO: ###.###.###.###[500] used for NAT-T
2013-01-26 18:06:35: INFO: ###.###.###.###[500] used as isakmp port (fd=8)
2013-01-26 18:06:36: INFO: IPsec-SA request for 205.251.233.121 queued due to no phase1 found.
2013-01-26 18:06:36: INFO: initiate new phase 1 negotiation: ###.###.###.###[500]<=>205.251.233.121[500]
2013-01-26 18:06:36: INFO: begin Identity Protection mode.
2013-01-26 18:06:36: INFO: IPsec-SA request for 205.251.233.122 queued due to no phase1 found.
2013-01-26 18:06:36: INFO: initiate new phase 1 negotiation: ###.###.###.###[500]<=>205.251.233.122[500]
2013-01-26 18:06:36: INFO: begin Identity Protection mode.
2013-01-26 18:06:36: INFO: received Vendor ID: DPD
2013-01-26 18:06:36: INFO: received Vendor ID: DPD
2013-01-26 18:06:36: INFO: ISAKMP-SA established ###.###.###.###[500]-205.251.233.121[500] spi:1ee34d6e99489278:653e1800428e4e9e
2013-01-26 18:06:36: INFO: ISAKMP-SA established ###.###.###.###[500]-205.251.233.122[500] spi:f1ff1e51933d7b6a:7c457666c24352b8
2013-01-26 18:06:37: INFO: initiate new phase 2 negotiation: ###.###.###.###[500]<=>205.251.233.121[500]
2013-01-26 18:06:37: INFO: initiate new phase 2 negotiation: ###.###.###.###[500]<=>205.251.233.122[500]
2013-01-26 18:06:37: INFO: IPsec-SA established: ESP ###.###.###.###[500]->205.251.233.121[500] spi=61646745(0x3aca799)
2013-01-26 18:06:37: INFO: IPsec-SA established: ESP ###.###.###.###[500]->205.251.233.121[500] spi=70676050(0x4366e52)
2013-01-26 18:06:37: INFO: IPsec-SA established: ESP ###.###.###.###[500]->205.251.233.122[500] spi=223058808(0xd4b9b78)
2013-01-26 18:06:37: INFO: IPsec-SA established: ESP ###.###.###.###[500]->205.251.233.122[500] spi=4066502990(0xf261e94e)