VPN with Amazon AWS - Using Static Option (non bgp)

dloop · Oct 10, 2012, 5:20 AM

Running racoon in foreground. Can anyone interpret this for me?

2012-10-09 22:14:44: DEBUG: getsainfo params: loc='0.0.0.0/0' rmt='0.0.0.0/0' peer='205.251.233.121' client='205.251.233.121' id=1
2012-10-09 22:14:44: DEBUG: evaluating sainfo: loc='169.254.249.2/30', rmt='169.254.249.1/30', peer='ANY', id=1
2012-10-09 22:14:44: DEBUG: check and compare ids : value mismatch (IPv4_subnet)
2012-10-09 22:14:44: DEBUG: cmpid target: '0.0.0.0/0'
2012-10-09 22:14:44: DEBUG: cmpid source: '169.254.249.2/30'
2012-10-09 22:14:44: ERROR: failed to get sainfo.
2012-10-09 22:14:44: ERROR: failed to get sainfo.
2012-10-09 22:14:44: [205.251.233.121] ERROR: failed to pre-process ph2 packet (side: 1, status: 1).

dhatz · Oct 10, 2012, 12:49 PM

This is typically due to subnet mismatch.

Check (or share) the output of
setkey -D
setkey -DP

PS: I think Amazon VPC could be a pfSense "killer app" in addition to OpenVPN.

dloop · Oct 10, 2012, 3:24 PM

Thanks dhatz. I agree about being a killer app for pfsense

$ setkey -D
No SAD entries.

$ setkey -DP
192.168.1.0/24[any] 192.168.1.1[any] 255
in none
spid=10 seq=3 pid=6470
refcnt=1
169.254.249.1/30[any] 169.254.249.2/30[any] 255
in ipsec
esp/tunnel/205.251.233.121-50.46.180.79/unique#16390
spid=12 seq=2 pid=6470
refcnt=1
192.168.1.1[any] 192.168.1.0/24[any] 255
out none
spid=9 seq=1 pid=6470
refcnt=1
169.254.249.2/30[any] 169.254.249.1/30[any] 255
out ipsec
esp/tunnel/50.46.180.79-205.251.233.121/unique#16389
spid=11 seq=0 pid=6470
refcnt=1

Shanlar · Oct 10, 2012, 6:27 PM

I am also running into this issue. Receiving the same error as you, stating the phase 2 settings failed.

dloop · Oct 10, 2012, 7:45 PM

Well I rebuilt and scrubbed my configuration. I found I was blocking udp 500 from Amazon so I fixed that. Still getting error.

2012-10-10 11:35:03: DEBUG: add payload of len 8, next type 8
2012-10-10 11:35:03: DEBUG: add payload of len 20, next type 0
2012-10-10 11:35:03: DEBUG: begin encryption.
2012-10-10 11:35:03: DEBUG: encryption(aes)
2012-10-10 11:35:03: DEBUG: pad length = 12
2012-10-10 11:35:03: DEBUG:
0800000c 011101f4 322eb44f 00000018 611f4d05 f17d1c9c 59799bb6 dad61c08
0b8b01b2 d7b5cab4 efc5ea8f d29b8d0b
2012-10-10 11:35:03: DEBUG: encryption(aes)
2012-10-10 11:35:03: DEBUG: with key:
2012-10-10 11:35:03: DEBUG:
17222cca bb758cd7 29984592 62e85836
2012-10-10 11:35:03: DEBUG: encrypted payload by IV:
2012-10-10 11:35:03: DEBUG:
2a7daecc 3622bf1c 12fba892 5a476d69
2012-10-10 11:35:03: DEBUG: save IV for next:
2012-10-10 11:35:03: DEBUG:
4c61f482 1da042eb 13173b79 dbc241ca
2012-10-10 11:35:03: DEBUG: encrypted.
2012-10-10 11:35:03: DEBUG: 76 bytes from 50.46.180.79[500] to 205.251.233.121[500]
2012-10-10 11:35:03: DEBUG: sockname 50.46.180.79[500]
2012-10-10 11:35:03: DEBUG: send packet from 50.46.180.79[500]
2012-10-10 11:35:03: DEBUG: send packet to 205.251.233.121[500]
2012-10-10 11:35:03: DEBUG: 1 times of 76 bytes message will be sent to 205.251.233.121[500]
2012-10-10 11:35:03: DEBUG:
5ad3be5e 38bd4cd4 66bd7627 d32c8549 05100201 00000000 0000004c 2023af14
3bde68b6 e2a4ea11 cd404dc7 3f68af11 ddfb603e c2d451f5 e41e95ca 4c61f482
1da042eb 13173b79 dbc241ca
2012-10-10 11:35:03: DEBUG: compute IV for phase2
2012-10-10 11:35:03: DEBUG: phase1 last IV:
2012-10-10 11:35:03: DEBUG:
4c61f482 1da042eb 13173b79 dbc241ca d866a59f
2012-10-10 11:35:03: DEBUG: hash(sha1)
2012-10-10 11:35:03: DEBUG: encryption(aes)
2012-10-10 11:35:03: DEBUG: phase2 IV computed:
2012-10-10 11:35:03: DEBUG:
09cbc2a3 efdaf0e2 a8262fc2 11646e32
2012-10-10 11:35:03: DEBUG: HASH with:
2012-10-10 11:35:03: DEBUG:
d866a59f 0000001c 00000001 01106002 5ad3be5e 38bd4cd4 66bd7627 d32c8549
2012-10-10 11:35:03: DEBUG: hmac(hmac_sha1)
2012-10-10 11:35:03: DEBUG: HASH computed:
2012-10-10 11:35:03: DEBUG:
c7d6462e 498f8aa8 2582ced0 32e79d8b 5f256ece
2012-10-10 11:35:03: DEBUG: begin encryption.
2012-10-10 11:35:03: DEBUG: encryption(aes)
2012-10-10 11:35:03: DEBUG: pad length = 12
2012-10-10 11:35:03: DEBUG:
0b000018 c7d6462e 498f8aa8 2582ced0 32e79d8b 5f256ece 0000001c 00000001
01106002 5ad3be5e 38bd4cd4 66bd7627 d32c8549 f196b8ee ace8cda0 80a7ec0b
2012-10-10 11:35:03: DEBUG: encryption(aes)
2012-10-10 11:35:03: DEBUG: with key:
2012-10-10 11:35:03: DEBUG:
17222cca bb758cd7 29984592 62e85836
2012-10-10 11:35:03: DEBUG: encrypted payload by IV:
2012-10-10 11:35:03: DEBUG:
09cbc2a3 efdaf0e2 a8262fc2 11646e32
2012-10-10 11:35:03: DEBUG: save IV for next:
2012-10-10 11:35:03: DEBUG:
7f0885e4 ba0db1b9 e19fb9f4 0f58729b
2012-10-10 11:35:03: DEBUG: encrypted.
2012-10-10 11:35:03: DEBUG: 92 bytes from 50.46.180.79[500] to 205.251.233.121[500]
2012-10-10 11:35:03: DEBUG: sockname 50.46.180.79[500]
2012-10-10 11:35:03: DEBUG: send packet from 50.46.180.79[500]
2012-10-10 11:35:03: DEBUG: send packet to 205.251.233.121[500]
2012-10-10 11:35:03: DEBUG: 1 times of 92 bytes message will be sent to 205.251.233.121[500]
2012-10-10 11:35:03: DEBUG:
5ad3be5e 38bd4cd4 66bd7627 d32c8549 08100501 d866a59f 0000005c 6e212667
b08d602c aa38be4b 7507b81f 17d7c9a8 fb19262f f8691fc6 e1341948 96d6c932
8285471b cad5e64d e0e9945f 7f0885e4 ba0db1b9 e19fb9f4 0f58729b
2012-10-10 11:35:03: DEBUG: sendto Information notify.
2012-10-10 11:35:03: DEBUG: IV freed
2012-10-10 11:35:03: [205.251.233.121] INFO: received INITIAL-CONTACT
2012-10-10 11:35:03: DEBUG: call pfkey_send_dump
2012-10-10 11:35:03: DEBUG: pk_recv: retry[0] recv()
2012-10-10 11:35:03: INFO: ISAKMP-SA established 50.46.180.79[500]-205.251.233.121[500] spi:5ad3be5e38bd4cd4:66bd7627d32c8549
2012-10-10 11:35:03: DEBUG: ===
2012-10-10 11:35:03: DEBUG: ===
2012-10-10 11:35:03: DEBUG: 348 bytes message received from 205.251.233.121[500] to 50.46.180.79[500]
2012-10-10 11:35:03: DEBUG:
5ad3be5e 38bd4cd4 66bd7627 d32c8549 08102001 61ce059d 0000015c cc10bda4
3d94b73f ec87727b 2682893b e28a5a03 31de902c d6524117 05cf1082 af5f3f6b
881c0239 f299637b a954a38c 66a27f5e 747ec334 2d179cba f689e1bf 39b04bb1
72f42a46 aa8cdcc8 f593b5d2 3525dd43 e1356d33 6477e77e afdbe2a8 34ad2e0e
88e30def c2ef7301 39aab689 5caff8ca 3eb92d5c 7376ee0c 31077bcd b5635bb1
912cdab9 b0c8e358 4fa833c4 f8f52505 d0ebf1a3 953e27e9 428de6d9 fda6be58
0e43d045 e7cda69f e1170bf5 d2be75b5 2919b4f8 36ef8255 23ed1d3b 392c8852
6545e6ca 9c74d891 e4dfc9d8 d04c8b49 3818cab7 79fc219d fd7fb65d d5bcbf57
d4d989eb e5fc494e f7115ec0 c3b61b95 e49943e5 a5ab90b5 9ad82ea9 dc34bfa0
653a0822 d0c5ba7f 70a3b449 a17deba7 c6b3c18c 71037ee1 85e0b29a 9a519ac5
cb1fd895 b648ff70 44bbe502 8c0048b3 1c534d1c eea9e2c2 11651563
2012-10-10 11:35:03: DEBUG: compute IV for phase2
2012-10-10 11:35:03: DEBUG: phase1 last IV:
2012-10-10 11:35:03: DEBUG:
4c61f482 1da042eb 13173b79 dbc241ca 61ce059d
2012-10-10 11:35:03: DEBUG: hash(sha1)
2012-10-10 11:35:03: DEBUG: encryption(aes)
2012-10-10 11:35:03: DEBUG: phase2 IV computed:
2012-10-10 11:35:03: DEBUG:
6879ed02 0eea7c07 8af660d1 c089b241
2012-10-10 11:35:03: DEBUG: ===
2012-10-10 11:35:03: INFO: respond new phase 2 negotiation: 50.46.180.79[500]<=>205.251.233.121[500]
2012-10-10 11:35:03: DEBUG: begin decryption.
2012-10-10 11:35:03: DEBUG: encryption(aes)
2012-10-10 11:35:03: DEBUG: IV was saved for next processing:
2012-10-10 11:35:03: DEBUG:
8c0048b3 1c534d1c eea9e2c2 11651563
2012-10-10 11:35:03: DEBUG: encryption(aes)
2012-10-10 11:35:03: DEBUG: with key:
2012-10-10 11:35:03: DEBUG:
17222cca bb758cd7 29984592 62e85836
2012-10-10 11:35:03: DEBUG: decrypted payload by IV:
2012-10-10 11:35:03: DEBUG:
6879ed02 0eea7c07 8af660d1 c089b241
2012-10-10 11:35:03: DEBUG: decrypted payload, but not trimed.
2012-10-10 11:35:03: DEBUG:
01000018 b91f0e04 eaf3d32a e7b29e8d 5daa9e5e 95485f71 0a000038 00000001
00000001 0000002c 01030401 c9a3041a 00000020 010c0000 80050002 80060080
80010001 80020e10 80030002 80040001 04000044 dfe8ebac df449da2 01fa0286
4658a496 c051fada 4fc013a7 62d65478 5d0545b2 e2195835 926ed7c3 e1b0c3e6
3121daeb 3f48bf99 ab4cbc95 a213ff2c 91483f7e 05000084 41889540 1b30fbeb
884d7d3c df0577a9 bcf741b9 3dda9e99 160d732a 258d8433 0aba9885 82341ef2
1171af0f db31e94e 6a36b585 87e2f358 175ad490 042b9cd2 de15aa47 2582c65c
3b543d1c 248e8808 65f8739b 1cb1b096 572c3429 c7cd1609 f6a2e374 93b34d1a
ad76ea6d 637516f7 f9cfb3a6 9bdb2d7d b20193f9 6bae40bd 05000010 04000000
00000000 00000000 00000010 04000000 00000000 00000000 00000000 00000000
2012-10-10 11:35:03: DEBUG: padding len=1
2012-10-10 11:35:03: DEBUG: skip to trim padding.
2012-10-10 11:35:03: DEBUG: decrypted.
2012-10-10 11:35:03: DEBUG:
5ad3be5e 38bd4cd4 66bd7627 d32c8549 08102001 61ce059d 0000015c 01000018
b91f0e04 eaf3d32a e7b29e8d 5daa9e5e 95485f71 0a000038 00000001 00000001
0000002c 01030401 c9a3041a 00000020 010c0000 80050002 80060080 80010001
80020e10 80030002 80040001 04000044 dfe8ebac df449da2 01fa0286 4658a496
c051fada 4fc013a7 62d65478 5d0545b2 e2195835 926ed7c3 e1b0c3e6 3121daeb
3f48bf99 ab4cbc95 a213ff2c 91483f7e 05000084 41889540 1b30fbeb 884d7d3c
df0577a9 bcf741b9 3dda9e99 160d732a 258d8433 0aba9885 82341ef2 1171af0f
db31e94e 6a36b585 87e2f358 175ad490 042b9cd2 de15aa47 2582c65c 3b543d1c
248e8808 65f8739b 1cb1b096 572c3429 c7cd1609 f6a2e374 93b34d1a ad76ea6d
637516f7 f9cfb3a6 9bdb2d7d b20193f9 6bae40bd 05000010 04000000 00000000
00000000 00000010 04000000 00000000 00000000 00000000 00000000
2012-10-10 11:35:03: DEBUG: begin.
2012-10-10 11:35:03: DEBUG: seen nptype=8(hash)
2012-10-10 11:35:03: DEBUG: seen nptype=1(sa)
2012-10-10 11:35:03: DEBUG: seen nptype=10(nonce)
2012-10-10 11:35:03: DEBUG: seen nptype=4(ke)
2012-10-10 11:35:03: DEBUG: seen nptype=5(id)
2012-10-10 11:35:03: DEBUG: seen nptype=5(id)
2012-10-10 11:35:03: DEBUG: succeed.
2012-10-10 11:35:03: DEBUG: received IDci2:2012-10-10 11:35:03: DEBUG:
04000000 00000000 00000000
2012-10-10 11:35:03: DEBUG: received IDcr2:2012-10-10 11:35:03: DEBUG:
04000000 00000000 00000000
2012-10-10 11:35:03: DEBUG: HASH(1) validate:2012-10-10 11:35:03: DEBUG:
b91f0e04 eaf3d32a e7b29e8d 5daa9e5e 95485f71
2012-10-10 11:35:03: DEBUG: HASH with:
2012-10-10 11:35:03: DEBUG:
61ce059d 0a000038 00000001 00000001 0000002c 01030401 c9a3041a 00000020
010c0000 80050002 80060080 80010001 80020e10 80030002 80040001 04000044
dfe8ebac df449da2 01fa0286 4658a496 c051fada 4fc013a7 62d65478 5d0545b2
e2195835 926ed7c3 e1b0c3e6 3121daeb 3f48bf99 ab4cbc95 a213ff2c 91483f7e
05000084 41889540 1b30fbeb 884d7d3c df0577a9 bcf741b9 3dda9e99 160d732a
258d8433 0aba9885 82341ef2 1171af0f db31e94e 6a36b585 87e2f358 175ad490
042b9cd2 de15aa47 2582c65c 3b543d1c 248e8808 65f8739b 1cb1b096 572c3429
c7cd1609 f6a2e374 93b34d1a ad76ea6d 637516f7 f9cfb3a6 9bdb2d7d b20193f9
6bae40bd 05000010 04000000 00000000 00000000 00000010 04000000 00000000
00000000
2012-10-10 11:35:03: DEBUG: hmac(hmac_sha1)
2012-10-10 11:35:03: DEBUG: HASH computed:
2012-10-10 11:35:03: DEBUG:
b91f0e04 eaf3d32a e7b29e8d 5daa9e5e 95485f71
2012-10-10 11:35:03: DEBUG: getsainfo params: loc='0.0.0.0/0' rmt='0.0.0.0/0' peer='205.251.233.121' client='205.251.233.121' id=1
2012-10-10 11:35:03: DEBUG: evaluating sainfo: loc='169.254.249.2/30', rmt='169.254.249.1/30', peer='ANY', id=1
2012-10-10 11:35:03: DEBUG: check and compare ids : value mismatch (IPv4_subnet)
2012-10-10 11:35:03: DEBUG: cmpid target: '0.0.0.0/0'
2012-10-10 11:35:03: DEBUG: cmpid source: '169.254.249.2/30'
2012-10-10 11:35:03: ERROR: failed to get sainfo.
2012-10-10 11:35:03: ERROR: failed to get sainfo.
2012-10-10 11:35:03: [205.251.233.121] ERROR: failed to pre-process ph2 packet (side: 1, status: 1).
2012-10-10 11:35:03: DEBUG: IV freed
^C2012-10-10 11:35:05: INFO: caught signal 2
2012-10-10 11:35:05: DEBUG: compute IV for phase2
2012-10-10 11:35:05: DEBUG: phase1 last IV:
2012-10-10 11:35:05: DEBUG:

dloop · Oct 10, 2012, 7:36 PM

@Shanlar:

I am also running into this issue. Receiving the same error as you, stating the phase 2 settings failed.

Thanks for testing this too Shanlar. It's nice to know it's not just me.

Shanlar · Oct 10, 2012, 9:22 PM

Yup, no matter what I do, I continue to get the same error. Even switching to the BGP method gives me the same error.

Shanlar · Oct 11, 2012, 12:08 AM

2012-10-10 19:33:02: DEBUG: evaluating sainfo: loc='169.254.254.34/30', rmt='169.254.254.33/30', peer='ANY', id=4
2012-10-10 19:33:02: DEBUG: check and compare ids : value mismatch (IPv4_subnet)
2012-10-10 19:33:02: DEBUG: cmpid target: '0.0.0.0/0'
2012-10-10 19:33:02: DEBUG: cmpid source: '169.254.254.34/30'
2012-10-10 19:33:02: ERROR: failed to get sainfo.
2012-10-10 19:33:02: ERROR: failed to get sainfo.
2012-10-10 19:33:02: [87.238.85.40] ERROR: failed to pre-process ph2 packet (side: 1, status: 1).

I can't seem to figure out why cmpid target is 0.0.0.0/0. I have 6 other tunnels setup between Juniper boxes and pfSense, none of them have this issue.

Phonebuff · Oct 11, 2012, 12:36 PM

@Shanlar:

I can't seem to figure out why cmpid target is 0.0.0.0/0. I have 6 other tunnels setup between Juniper boxes and pfSense, none of them have this issue.

I think you will find that this line is the root of evil here –

2012-10-10 19:33:02: DEBUG: check and compare ids : value mismatch (IPv4_subnet)

Not sure what exactly is mismatched, but are the Subnet masks, /30 in the trace, set the same on both sides. I had an issue recently where they were not and that's all that was wrong.

==========================

Shanlar · Oct 11, 2012, 6:34 PM

cmpid target = AWS VPC
cmpid source = pfSense

The current issue is AWS VPC, for some reason, is sending me 0.0.0.0/0 for the subnet. This obviously won't match on my side. I've created the VPC manually and through the wizard, both times AWS keeps sending me the subnet 0.0.0.0/0.

Lloyd · Jan 9, 2013, 11:30 PM

Hi Shanlar,

Did you ever get this working? I have the same issue with Amazon sending the 0.0.0.0/0

Regards,

Lloyd

Shanlar · Jan 10, 2013, 1:03 AM

No I gave up and setup an openvpn box in my VPC on the same box running the NAT