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_Troubleshooting

    Here 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=out

    But 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)


Locked