IPsec not working, time out & "Unknown Gateway/Dynamic"



  • I'm desperately trying to get ipsec working on my pfsense 2.0, I simply must have it working friday morning!
    I have found several other questions about the same problem but not one single answer..

    What happens is:
    I have ipsec configured, one phase1 & one phase2 entry.
    When I enable IPsec, SPD are added both ways, No SAD
    "Connect VPN" doesn't connect, "status" always yellow, same log messages are repeated over and over.

    It seems phase 1 doesn't succeed so that's where I've been looking mostly.
    MD5 & 3DES are used, I have tried both ESP & AH, no difference
    Also tried both Aggressive & Main mode.
    Firewall-log shows nothing blocked, ports open:
    out = all,
    in = 500, 4500, 21, AH, ESP, GRE

    IP:s changed in log & conf, they are correct.
    1.2.3.80 = remote side
    1.2.3.95 = remote network (single host)
    6.7.8.210 = public ip on my pfsense.
    192.168.150.0/24 = my local network

    Log:
    Only errors I can see is
    "racoon: [Connection-Name]: [1.2.3.80] ERROR: phase2 negotiation failed due to time up waiting for phase1 [Remote Side not responding]. ESP 1.2.3.80[0]->6.7.8.210[0]"
    and after that a bunch of
    "racoon: [Unknown Gateway/Dynamic]:"

    • But according to what's logged earlier there has been communications between endpoints!

    Here's complete log from one try:

    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey REGISTER message
    Jan 25 11:08:13 mail racoon: INFO: unsupported PF_KEY message REGISTER
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey X_SPDDELETE message
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548148: 192.168.150.1/32[0] 192.168.150.0/24[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548288: 192.168.150.0/24[0] 192.168.150.1/32[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x285483c8: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey X_SPDDELETE message
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548148: 192.168.150.1/32[0] 192.168.150.0/24[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548288: 192.168.150.0/24[0] 192.168.150.1/32[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548648: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey X_SPDADD message
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548148: 192.168.150.1/32[0] 192.168.150.0/24[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548288: 192.168.150.0/24[0] 192.168.150.1/32[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey X_SPDADD message
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548148: 192.168.150.1/32[0] 192.168.150.0/24[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548288: 192.168.150.0/24[0] 192.168.150.1/32[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe754: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x285483c8: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey X_SPDDUMP message
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey X_SPDDUMP message
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe734: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548148: 192.168.150.0/24[0] 192.168.150.1/32[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey X_SPDDUMP message
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe734: 192.168.150.1/32[0] 192.168.150.0/24[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548148: 192.168.150.0/24[0] 192.168.150.1/32[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe734: 192.168.150.1/32[0] 192.168.150.0/24[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548288: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey X_SPDDUMP message
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe734: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548148: 192.168.150.0/24[0] 192.168.150.1/32[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe734: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548288: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:13 mail racoon: DEBUG: sub:0xbfbfe734: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: db :0x28548508: 192.168.150.1/32[0] 192.168.150.0/24[0] proto=any dir=out
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[1] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[2] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: reading config file /var/etc/racoon.conf
    Jan 25 11:08:13 mail racoon: DEBUG: hmac(modp1024)
    Jan 25 11:08:13 mail racoon: DEBUG: no check of compression algorithm; not supported in sadb message.
    Jan 25 11:08:13 mail racoon: DEBUG: getsainfo params: loc='192.168.150.0/24' rmt='1.2.3.95' peer='NULL' client='NULL' id=1
    Jan 25 11:08:13 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:13 mail racoon: DEBUG: got pfkey REGISTER message
    Jan 25 11:08:13 mail racoon: INFO: unsupported PF_KEY message REGISTER
    Jan 25 11:08:14 mail racoon: DEBUG: pk_recv: retry[0] recv() 
    Jan 25 11:08:14 mail racoon: DEBUG: got pfkey ACQUIRE message
    Jan 25 11:08:14 mail racoon: DEBUG: suitable outbound SP found: 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out.
    Jan 25 11:08:14 mail racoon: DEBUG: sub:0xbfbfe758: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:14 mail racoon: DEBUG: db :0x28548148: 192.168.150.0/24[0] 192.168.150.1/32[0] proto=any dir=in
    Jan 25 11:08:14 mail racoon: DEBUG: sub:0xbfbfe758: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:14 mail racoon: DEBUG: db :0x28548288: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in
    Jan 25 11:08:14 mail racoon: DEBUG: suitable inbound SP found: 1.2.3.95/32[0] 192.168.150.0/24[0] proto=any dir=in.
    Jan 25 11:08:14 mail racoon: DEBUG: new acquire 192.168.150.0/24[0] 1.2.3.95/32[0] proto=any dir=out
    Jan 25 11:08:14 mail racoon: [1.2.3.80] DEBUG: configuration "1.2.3.80[500]" selected.
    Jan 25 11:08:14 mail racoon: DEBUG: getsainfo params: loc='192.168.150.0/24' rmt='1.2.3.95' peer='NULL' client='NULL' id=1
    Jan 25 11:08:14 mail racoon: DEBUG: evaluating sainfo: loc='192.168.150.0/24', rmt='1.2.3.95', peer='ANY', id=1
    Jan 25 11:08:14 mail racoon: DEBUG: check and compare ids : values matched (IPv4_subnet)
    Jan 25 11:08:14 mail racoon: DEBUG: cmpid target: '192.168.150.0/24'
    Jan 25 11:08:14 mail racoon: DEBUG: cmpid source: '192.168.150.0/24'
    Jan 25 11:08:14 mail racoon: DEBUG: check and compare ids : values matched (IPv4_address)
    Jan 25 11:08:14 mail racoon: DEBUG: cmpid target: '1.2.3.95'
    Jan 25 11:08:14 mail racoon: DEBUG: cmpid source: '1.2.3.95'
    Jan 25 11:08:14 mail racoon: DEBUG: selected sainfo: loc='192.168.150.0/24', rmt='1.2.3.95', peer='ANY', id=1
    Jan 25 11:08:14 mail racoon: DEBUG:  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=16482:16481)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=AES encklen=256 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=AES encklen=256 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=AES encklen=192 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=AES encklen=192 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=AES encklen=128 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=AES encklen=128 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=256 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=256 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=248 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=248 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=240 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=240 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=232 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=232 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=224 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=224 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=216 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=216 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=208 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=208 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=200 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=200 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=192 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=192 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=184 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=184 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=176 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=176 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=168 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=168 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=160 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=160 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=152 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=152 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=144 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=144 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=136 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=136 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=128 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=BLOWFISH encklen=128 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=CAST encklen=128 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=CAST encklen=128 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=DES encklen=0 authtype=hmac-sha)
    Jan 25 11:08:14 mail racoon: DEBUG:   (trns_id=DES encklen=0 authtype=hmac-md5)
    Jan 25 11:08:14 mail racoon: DEBUG: in post_acquire
    Jan 25 11:08:14 mail racoon: [1.2.3.80] DEBUG: configuration "1.2.3.80[500]" selected.
    Jan 25 11:08:14 mail racoon: INFO: IPsec-SA request for 1.2.3.80 queued due to no phase1 found.
    Jan 25 11:08:14 mail racoon: DEBUG: ===
    Jan 25 11:08:14 mail racoon: INFO: initiate new phase 1 negotiation: 6.7.8.210[500]<=>1.2.3.80[500]
    Jan 25 11:08:14 mail racoon: INFO: begin Aggressive mode.
    Jan 25 11:08:14 mail racoon: DEBUG: new cookie: fbd9b737ba2d0dcf 
    Jan 25 11:08:14 mail racoon: DEBUG: use ID type of IPv4_address
    Jan 25 11:08:14 mail racoon: DEBUG: compute DH's private.
    Jan 25 11:08:14 mail racoon: DEBUG:  50ffe7c9 019740d3 e947c8fb ec7f5d8b 4dff18e8 9d3de332 0500adfd 73f45ce2 2cdbcef5 18531ca8 b28a27d0 5630d289 00daeb11 d18f9dab ea39a7f2 fbe9f9bb 48616bd7 80c93755 fc2f5b3d 871b6e4d b427f3f8 fa3e691b e69847d6 d08a39a7 2992e517 01f0178f 6929ba02 923fb199 02f4a2d4 f777d21c 1811a78b 7a5713ff
    Jan 25 11:08:14 mail racoon: DEBUG: compute DH's public.
    Jan 25 11:08:14 mail racoon: DEBUG:  1717a96b 9ac61285 3a130390 19cf0430 388a6466 8c85a561 e9e7b282 d4c191d6 23d5c6a1 bbb4005a df9cd2a4 30b9d611 d40b07e8 3e88e6e5 8d46c2f2 89cd2a8d 5e70b03e f284b4a0 785cf158 46284e38 4e6d8672 9678e603 f65e6cdf 09a7d424 0ba175dc 5fc0428b 08c6a900 a4adf64c 99ca03f6 31f1f1cb 322666a0 9bf6ed03
    Jan 25 11:08:14 mail racoon: DEBUG: authmethod is pre-shared key
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 48, next type 4
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 128, next type 10
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 16, next type 5
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 8, next type 13
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 20, next type 13
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 16, next type 13
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 16, next type 13
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 16, next type 13
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 16, next type 13
    Jan 25 11:08:14 mail racoon: DEBUG: add payload of len 16, next type 0
    Jan 25 11:08:14 mail racoon: DEBUG: 368 bytes from 6.7.8.210[500] to 1.2.3.80[500]
    Jan 25 11:08:14 mail racoon: DEBUG: sockname 6.7.8.210[500]
    Jan 25 11:08:14 mail racoon: DEBUG: send packet from 6.7.8.210[500]
    Jan 25 11:08:14 mail racoon: DEBUG: send packet to 1.2.3.80[500]
    Jan 25 11:08:14 mail racoon: DEBUG: 1 times of 368 bytes message will be sent to 1.2.3.80[500]
    Jan 25 11:08:14 mail racoon: DEBUG:  fbd9b737 ba2d0dcf 00000000 00000000 01100400 00000000 00000170 04000034 00000001 00000001 00000028 01010001 00000020 01010000 800b0001 800c7080 80010005 80030001 80020001 80040002 0a000084 1717a96b 9ac61285 3a130390 19cf0430 388a6466 8c85a561 e9e7b282 d4c191d6 23d5c6a1 bbb4005a df9cd2a4 30b9d611 d40b07e8 3e88e6e5 8d46c2f2 89cd2a8d 5e70b03e f284b4a0 785cf158 46284e38 4e6d8672 9678e603 f65e6cdf 09a7d424 0ba175dc 5fc0428b 08c6a900 a4adf64c 99ca03f6 31f1f1cb 322666a0 9bf6ed03 05000014 dc616c43 32ba4eb6 29f84d49 c29a3afb 0d00000c 011101f4 c3b2a5d2 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 0d000014 4a131c81 07035845 5c5728f2 0e95452f 0d000014 cd604643 35df21f8 7cfdb2fc 68b6a448 0d000014 90cb8091 3ebb696e 086381b5 ec427b1f 0d000014 4485152d 18b6bbcd 0be8a846 9579ddcc 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jan 25 11:08:14 mail racoon: DEBUG: resend phase1 packet fbd9b737ba2d0dcf:0000000000000000
    Jan 25 11:08:24 mail racoon: DEBUG: 368 bytes from 6.7.8.210[500] to 1.2.3.80[500]
    Jan 25 11:08:24 mail racoon: DEBUG: sockname 6.7.8.210[500]
    Jan 25 11:08:24 mail racoon: DEBUG: send packet from 6.7.8.210[500]
    Jan 25 11:08:24 mail racoon: DEBUG: send packet to 1.2.3.80[500]
    Jan 25 11:08:24 mail racoon: DEBUG: 1 times of 368 bytes message will be sent to 1.2.3.80[500]
    Jan 25 11:08:24 mail racoon: DEBUG:  fbd9b737 ba2d0dcf 00000000 00000000 01100400 00000000 00000170 04000034 00000001 00000001 00000028 01010001 00000020 01010000 800b0001 800c7080 80010005 80030001 80020001 80040002 0a000084 1717a96b 9ac61285 3a130390 19cf0430 388a6466 8c85a561 e9e7b282 d4c191d6 23d5c6a1 bbb4005a df9cd2a4 30b9d611 d40b07e8 3e88e6e5 8d46c2f2 89cd2a8d 5e70b03e f284b4a0 785cf158 46284e38 4e6d8672 9678e603 f65e6cdf 09a7d424 0ba175dc 5fc0428b 08c6a900 a4adf64c 99ca03f6 31f1f1cb 322666a0 9bf6ed03 05000014 dc616c43 32ba4eb6 29f84d49 c29a3afb 0d00000c 011101f4 c3b2a5d2 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 0d000014 4a131c81 07035845 5c5728f2 0e95452f 0d000014 cd604643 35df21f8 7cfdb2fc 68b6a448 0d000014 90cb8091 3ebb696e 086381b5 ec427b1f 0d000014 4485152d 18b6bbcd 0be8a846 9579ddcc 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jan 25 11:08:24 mail racoon: DEBUG: resend phase1 packet fbd9b737ba2d0dcf:0000000000000000
    Jan 25 11:08:34 mail racoon: DEBUG: 368 bytes from 6.7.8.210[500] to 1.2.3.80[500]
    Jan 25 11:08:34 mail racoon: DEBUG: sockname 6.7.8.210[500]
    Jan 25 11:08:34 mail racoon: DEBUG: send packet from 6.7.8.210[500]
    Jan 25 11:08:34 mail racoon: DEBUG: send packet to 1.2.3.80[500]
    Jan 25 11:08:34 mail racoon: DEBUG: 1 times of 368 bytes message will be sent to 1.2.3.80[500]
    Jan 25 11:08:34 mail racoon: DEBUG:  fbd9b737 ba2d0dcf 00000000 00000000 01100400 00000000 00000170 04000034 00000001 00000001 00000028 01010001 00000020 01010000 800b0001 800c7080 80010005 80030001 80020001 80040002 0a000084 1717a96b 9ac61285 3a130390 19cf0430 388a6466 8c85a561 e9e7b282 d4c191d6 23d5c6a1 bbb4005a df9cd2a4 30b9d611 d40b07e8 3e88e6e5 8d46c2f2 89cd2a8d 5e70b03e f284b4a0 785cf158 46284e38 4e6d8672 9678e603 f65e6cdf 09a7d424 0ba175dc 5fc0428b 08c6a900 a4adf64c 99ca03f6 31f1f1cb 322666a0 9bf6ed03 05000014 dc616c43 32ba4eb6 29f84d49 c29a3afb 0d00000c 011101f4 c3b2a5d2 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 0d000014 4a131c81 07035845 5c5728f2 0e95452f 0d000014 cd604643 35df21f8 7cfdb2fc 68b6a448 0d000014 90cb8091 3ebb696e 086381b5 ec427b1f 0d000014 4485152d 18b6bbcd 0be8a846 9579ddcc 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jan 25 11:08:34 mail racoon: DEBUG: resend phase1 packet fbd9b737ba2d0dcf:0000000000000000
    Jan 25 11:08:44 mail racoon: DEBUG: 368 bytes from 6.7.8.210[500] to 1.2.3.80[500]
    Jan 25 11:08:44 mail racoon: DEBUG: sockname 6.7.8.210[500]
    Jan 25 11:08:44 mail racoon: DEBUG: send packet from 6.7.8.210[500]
    Jan 25 11:08:44 mail racoon: DEBUG: send packet to 1.2.3.80[500]
    Jan 25 11:08:44 mail racoon: DEBUG: 1 times of 368 bytes message will be sent to 1.2.3.80[500]
    Jan 25 11:08:44 mail racoon: DEBUG:  fbd9b737 ba2d0dcf 00000000 00000000 01100400 00000000 00000170 04000034 00000001 00000001 00000028 01010001 00000020 01010000 800b0001 800c7080 80010005 80030001 80020001 80040002 0a000084 1717a96b 9ac61285 3a130390 19cf0430 388a6466 8c85a561 e9e7b282 d4c191d6 23d5c6a1 bbb4005a df9cd2a4 30b9d611 d40b07e8 3e88e6e5 8d46c2f2 89cd2a8d 5e70b03e f284b4a0 785cf158 46284e38 4e6d8672 9678e603 f65e6cdf 09a7d424 0ba175dc 5fc0428b 08c6a900 a4adf64c 99ca03f6 31f1f1cb 322666a0 9bf6ed03 05000014 dc616c43 32ba4eb6 29f84d49 c29a3afb 0d00000c 011101f4 c3b2a5d2 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 0d000014 4a131c81 07035845 5c5728f2 0e95452f 0d000014 cd604643 35df21f8 7cfdb2fc 68b6a448 0d000014 90cb8091 3ebb696e 086381b5 ec427b1f 0d000014 4485152d 18b6bbcd 0be8a846 9579ddcc 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jan 25 11:08:44 mail racoon: DEBUG: resend phase1 packet fbd9b737ba2d0dcf:0000000000000000
    Jan 25 11:08:45 mail racoon: [1.2.3.80] ERROR: phase2 negotiation failed due to time up waiting for phase1\. ESP 1.2.3.80[0]->6.7.8.210[0] 
    Jan 25 11:08:45 mail racoon: INFO: delete phase 2 handler.
    Jan 25 11:08:54 mail racoon: DEBUG: 368 bytes from 6.7.8.210[500] to 1.2.3.80[500]
    Jan 25 11:08:54 mail racoon: DEBUG: sockname 6.7.8.210[500]
    Jan 25 11:08:54 mail racoon: DEBUG: send packet from 6.7.8.210[500]
    Jan 25 11:08:54 mail racoon: DEBUG: send packet to 1.2.3.80[500]
    Jan 25 11:08:54 mail racoon: DEBUG: 1 times of 368 bytes message will be sent to 1.2.3.80[500]
    Jan 25 11:08:54 mail racoon: DEBUG:  fbd9b737 ba2d0dcf 00000000 00000000 01100400 00000000 00000170 04000034 00000001 00000001 00000028 01010001 00000020 01010000 800b0001 800c7080 80010005 80030001 80020001 80040002 0a000084 1717a96b 9ac61285 3a130390 19cf0430 388a6466 8c85a561 e9e7b282 d4c191d6 23d5c6a1 bbb4005a df9cd2a4 30b9d611 d40b07e8 3e88e6e5 8d46c2f2 89cd2a8d 5e70b03e f284b4a0 785cf158 46284e38 4e6d8672 9678e603 f65e6cdf 09a7d424 0ba175dc 5fc0428b 08c6a900 a4adf64c 99ca03f6 31f1f1cb 322666a0 9bf6ed03 05000014 dc616c43 32ba4eb6 29f84d49 c29a3afb 0d00000c 011101f4 c3b2a5d2 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 0d000014 4a131c81 07035845 5c5728f2 0e95452f 0d000014 cd604643 35df21f8 7cfdb2fc 68b6a448 0d000014 90cb8091 3ebb696e 086381b5 ec427b1f 0d000014 4485152d 18b6bbcd 0be8a846 9579ddcc 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jan 25 11:08:54 mail racoon: DEBUG: resend phase1 packet fbd9b737ba2d0dcf:0000000000000000
    Jan 25 11:09:04 mail racoon: ERROR: phase1 negotiation failed due to time up. fbd9b737ba2d0dcf:0000000000000000
    
    Log on firewalls webpage also shows:
    Jan 25 14:11:15 	racoon: DEBUG: resend phase1 packet 1fe4fc0d57fc9f4b:0000000000000000
    Jan 25 14:11:06 	racoon: [Cekab]: [1.2.3.80] ERROR: phase2 negotiation failed due to time up waiting for phase1 [Remote Side not responding]. AH 1.2.3.80[0]->6.7.8.210[0]
    Jan 25 14:11:06 	racoon: INFO: delete phase 2 handler.
    Jan 25 14:11:15 	racoon: [Unknown Gateway/Dynamic]: DEBUG: 368 bytes from 6.7.8.210[500] to 1.2.3.80[500]
    Jan 25 14:11:15 	racoon: [Unknown Gateway/Dynamic]: DEBUG: sockname 6.7.8.210[500]
    Jan 25 14:11:15 	racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet from 6.7.8.210[500]
    Jan 25 14:11:15 	racoon: [Unknown Gateway/Dynamic]: DEBUG: send packet to 1.2.3.80[500]
    Jan 25 14:11:15 	racoon: [Unknown Gateway/Dynamic]: DEBUG: 1 times of 368 bytes message will be sent to 1.2.3.80[500]
    Jan 25 14:11:15 	racoon: DEBUG: 1fe4fc0d 57fc9f4b 00000000 00000000 01100400 00000000 00000170 04000034 00000001 00000001 00000028 01010001 00000020 01010000 800b0001 800c7080 80010005 80030001 80020001 80040002 0a000084 e1db30f8 35d685af 4f4e24e2 0867dc04 ef5fd32c 5ab96fe7 f5ebdf80 4dfea616 363e37df e7e864b1 13c7a381 9d557e7f 2ec41556 83e0da85 97044bda f3da6201 9d8e5cbf b6926a9a 305d6812 a68d84c4 2b4819d8 b2e9f55b f20d7883 6c987b43 460ab16f 41bb7661 47e3cc50 ed7176e4 6011c03f 36ad9083 8d5f2046 411a4d34 05000014 b040b197 94673648 62425c64 29fd6f29 0d00000c 011101f4 c3b2a5d2 0d000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 80000000 0d000014 4a131c81 07035845 5c5728f2 0e95452f 0d000014 cd604643 35df21f8 7cfdb2fc 68b6a448 0d000014 90cb8091 3ebb696e 086381b5 ec427b1f 0d000014 4485152d 18b6bbcd 0be8a846 9579ddcc 00000014 afcad713 68a1f1c9 6b8696fc 77570100
    Jan 25 11:08:54 mail racoon: DEBUG: resend phase1 packet fbd9b737ba2d0dcf:0000000000000000
    Jan 25 11:09:04 mail racoon: ERROR: phase1 negotiation failed due to time up. fbd9b737ba2d0dcf:0000000000000000
    

    And racoon.conf

    # This file is automatically generated. Do not edit
    path pre_shared_key "/var/etc/psk.txt";
    
    path certificate  "/var/etc";
    
    listen
    {
    	adminsock "/var/db/racoon/racoon.sock" "root" "wheel" 0660;
    	isakmp 6.7.8.210 [500];
    	isakmp_natt 6.7.8.210 [4500];
    }
    
    remote 1.2.3.80
    {
    	ph1id 1;
    	exchange_mode aggressive;
    	my_identifier address 6.7.8.210;
    	peers_identifier address 1.2.3.80;
    	ike_frag on;
    	generate_policy = off;
    	initial_contact = on;
    	nat_traversal = on;
    
    	support_proxy on;
    	proposal_check claim;
    
    	proposal
    	{
    		authentication_method pre_shared_key;
    		encryption_algorithm 3des;
    		hash_algorithm md5;
    		dh_group 2;
    		lifetime time 28800 secs;
    	}
    }
    
    sainfo subnet 192.168.150.0/24 any subnet 1.2.3.95/32 any
    {
    	remoteid 1;
    	encryption_algorithm aes 256, aes 192, aes 128, blowfish 256, blowfish 248, blowfish 240, blowfish 232, blowfish 224, blowfish 216, blowfish 208, blowfish 200, blowfish 192, blowfish 184, blowfish 176, blowfish 168, blowfish 160, blowfish 152, blowfish 144, blowfish 136, blowfish 128, 3des, cast128, des;
    	authentication_algorithm hmac_sha1,hmac_md5;
    
    	lifetime time 3600 secs;
    	compression_algorithm deflate;
    }
    

    I have no control of remote endpoint, belongs to a big company.



  • "Unknown gateway/dynamic" would indicate they're sending you traffic on an IP other than the one you actually have configured on your end for the IPsec. Packet capture on WAN filtering on port 500 would be telling.



  • I missed giving some information I think is important, sorry:
    My pfSense has several ip-adresses on WAN:
    6.7.8.212 is primary, domainname mail.domain.se
    6.7.8.210, 211, & 213 are IP aliases (Virtual ip)
    6.7.8.210 is our endpoint of this tunnel, domainname test.domain.se

    Now I have tried using both WAN and 6.7.8.10 for local interface, my identifier as follows:
    If WAN specified for endpoint then "ip adress "specifying 6.7.8.210
    If 6.7.8.210 specified for endpoint then  tried both "My ip" and "ip adress" specifying 6.7.8.210
    Here is a tcpdump output for port 500 on bge0 (WAN interface)

    [b]Endpoint: 6.7.8.210 (=test.domain.se)[/b]
    12:01:47.345274 IP test.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident
    12:01:47.359234 IP 1.2.3.80.isakmp > test.domain.se.isakmp: isakmp: phase 1 R ident
    12:01:47.376394 IP test.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident
    12:01:47.391994 IP 1.2.3.80.isakmp > test.domain.se.isakmp: isakmp: phase 1 R ident
    12:01:47.408535 IP test.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident[E]
    12:01:47.427240 IP 1.2.3.80.isakmp > test.domain.se.isakmp: isakmp: phase 2/others R inf
    12:01:57.410725 IP test.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident[E]
    12:02:07.412674 IP test.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident[E]
    12:02:17.414613 IP test.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident[E]
    12:02:27.415911 IP test.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident[E]
    
    [b]Endpoint: WAN (6.7.8.212, mail.domain.se) [/b]
    12:08:06.045682 IP mail.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident
    12:08:06.061835 IP 1.2.3.80.isakmp > mail.domain.se.isakmp: isakmp: phase 1 R inf
    12:08:16.047614 IP mail.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident
    12:08:26.049540 IP mail.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident
    12:08:36.051835 IP mail.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident
    12:08:46.053770 IP mail.domain.se.isakmp > 1.2.3.80.isakmp: isakmp: phase 1 I ident
    
    

    One more thing, other side requires Main mode.
    When I tried Aggressive, I got a message from some tech guy on other side:
    "Looks like you've got Aggressive Mode on your vpn gw:
    (From their log:)
    IKE Tunnel_Name fwcluster 22 IKE
    fw11.domain.se Tunnel_Name IKE: Main Mode Sent Notification to Peer: Aggressive Mode is not supported
    So obviously there is contact!

    And if it's a routing problem:
    I have WAN adress 6.7.8.212 as default GW, shouldn't need to add a GW for this tunnel?



  • I have checked some more, there was a good guide at http://www.fejf.de/blog/fejf/fejfs_blog/tips/
    Now wireshark gives me the 'notification payload message type' "PAYLOAD-MALFORMED (16)"  which might be a problem with the key.
    As I previously realized I can't use '+' in keys for openvpn I have one question:
    Could someone please tell me which characters are not allowed / possible to use?
    I do so hope I can finally get this fixed by tomorrow morning, else I'll have to ditch pfSense. Don't want to, don't have the time to…



  • All characters are valid.



  • Nope, they are not!
    I solved this issue by removing all special characters and use only letters and numbers!

    And as I mentioned, when I a few weeks ago set up some OpenVPN connections (roadwarrior), I realized '+' could not be used.
    It's ok to input it - but tunnel simple doesn't connect.



  • @pingulino:

    Nope, they are not!
    I solved this issue by removing all special characters and use only letters and numbers!

    Then the problem was on the remote end. I just setup one of my VPNs with every special character on the US keyboard in the key along with a number of letters and numbers and it's working as it should.

    @pingulino:

    And as I mentioned, when I a few weeks ago set up some OpenVPN connections (roadwarrior), I realized '+' could not be used.
    It's ok to input it - but tunnel simple doesn't connect.

    OpenVPN doesn't even offer manually specified keys, if you're using shared keys they have to be generated by OpenVPN.



  • Now this is interesting!
    I'm starting a new thread about this character problem, it might be useful.


Log in to reply