Here is another debug output and tcpdump for the same problem. Following the advice from Stuart Henderson I change the debug levels to
isakmpd -D0=29 -D1=49 -D2=10 -D3=30 -D6=99 -D7=99 -D8=99 -D9=30 -D10=20 -K -L Here again the tcpdump and the new debug output 16:08:35.114550 0.0.0.0.500 > 217.86.184.8.500: [udp sum ok] isakmp v1.0 exchange ID_PROT cookie: 1a0208d771df46ef->0000000000000000 msgid: 00000000 len: 184 payload: SA len: 56 DOI: 1(IPSEC) situation: IDENTITY_ONLY payload: PROPOSAL len: 44 proposal: 1 proto: ISAKMP spisz: 0 xforms: 1 payload: TRANSFORM len: 36 transform: 0 ID: ISAKMP attribute ENCRYPTION_ALGORITHM = AES_CBC attribute HASH_ALGORITHM = MD5 attribute AUTHENTICATION_METHOD = PRE_SHARED attribute GROUP_DESCRIPTION = MODP_1024 attribute LIFE_TYPE = SECONDS attribute LIFE_DURATION = 3600 attribute KEY_LENGTH = 128 payload: VENDOR len: 20 payload: VENDOR len: 20 (supports v2 NAT-T, draft-ietf-ipsec-nat-t-ike-02) payload: VENDOR len: 20 (supports v3 NAT-T, draft-ietf-ipsec-nat-t-ike-03) payload: VENDOR len: 20 (supports NAT-T, RFC 3947) payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 212) 16:08:35.184157 217.86.184.8.500 > 217.110.66.79.500: [udp sum ok] isakmp v1.0 exchange ID_PROT cookie: 1a0208d771df46ef->be3ad6b901947e8e msgid: 00000000 len: 116 payload: SA len: 56 DOI: 1(IPSEC) situation: IDENTITY_ONLY payload: PROPOSAL len: 44 proposal: 1 proto: ISAKMP spisz: 0 xforms: 1 payload: TRANSFORM len: 36 transform: 1 ID: ISAKMP attribute ENCRYPTION_ALGORITHM = AES_CBC attribute KEY_LENGTH = 128 attribute HASH_ALGORITHM = MD5 attribute GROUP_DESCRIPTION = MODP_1024 attribute AUTHENTICATION_METHOD = PRE_SHARED attribute LIFE_TYPE = SECONDS attribute LIFE_DURATION = 3600 payload: VENDOR len: 12 payload: VENDOR len: 20 (supports NAT-T, RFC 3947) [ttl 0] (id 1, len 144) 16:08:35.275577 217.110.66.79.500 > 217.86.184.8.500: [udp sum ok] isakmp v1.0 exchange ID_PROT cookie: 1a0208d771df46ef->be3ad6b901947e8e msgid: 00000000 len: 220 payload: KEY_EXCH len: 132 payload: NONCE len: 20 payload: NAT-D len: 20 payload: NAT-D len: 20 [ttl 0] (id 1, len 248) 16:08:35.363848 217.86.184.8.500 > 217.110.66.79.500: [udp sum ok] isakmp v1.0 exchange ID_PROT cookie: 1a0208d771df46ef->be3ad6b901947e8e msgid: 00000000 len: 268 payload: KEY_EXCH len: 132 payload: NAT-D len: 20 payload: NAT-D len: 20 payload: NONCE len: 24 payload: VENDOR len: 12 payload: VENDOR len: 12 (supports draft-ietf-ipsra-isakmp-xauth-06.txt) payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 296) 16:08:35.454563 217.110.66.79.4500 > 217.86.184.8.4500: [bad udp cksum c9d0!] udpencap: isakmp v1.0 exchange ID_PROT cookie: 1a0208d771df46ef->be3ad6b901947e8e msgid: 00000000 len: 88 payload: ID len: 12 type: IPV4_ADDR = 217.110.66.79 payload: HASH len: 20 payload: NOTIFICATION len: 28 notification: INITIAL CONTACT (1a0208d771df46ef->be3ad6b901947e8e) [ttl 0] (id 1, len 120) 16:08:35.523331 217.86.184.8.4500 > 217.110.66.79.4500: [bad udp cksum 1c00!] udpencap: isakmp v1.0 exchange ID_PROT cookie: 1a0208d771df46ef->be3ad6b901947e8e msgid: 00000000 len: 60 payload: ID len: 12 type: IPV4_ADDR = 192.168.50.253 payload: HASH len: 20 [ttl 0] (id 1, len 92) 16:08:35.615285 217.110.66.79.4500 > 217.86.184.8.4500: [udp sum ok] udpencap: isakmp v1.0 exchange QUICK_MODE cookie: 1a0208d771df46ef->be3ad6b901947e8e msgid: ceee06b6 len: 288 payload: HASH len: 20 payload: SA len: 56 DOI: 1(IPSEC) situation: IDENTITY_ONLY payload: PROPOSAL len: 44 proposal: 1 proto: IPSEC_ESP spisz: 4 xforms: 1 SPI: 0x4dc1e13b payload: TRANSFORM len: 32 transform: 1 ID: AES attribute LIFE_TYPE = SECONDS attribute LIFE_DURATION = 1200 attribute ENCAPSULATION_MODE = TUNNEL attribute AUTHENTICATION_ALGORITHM = HMAC_MD5 attribute GROUP_DESCRIPTION = 2 attribute KEY_LENGTH = 128 payload: NONCE len: 20 payload: KEY_EXCH len: 132 payload: ID len: 16 type: IPV4_ADDR_SUBNET = 129.143.250.128/255.255.255.128 payload: ID len: 16 type: IPV4_ADDR_SUBNET = 192.168.199.0/255.255.255.0 [ttl 0] (id 1, len 320) 0000: 4500 0140 0001 0000 0011 0c90 d96e 424f e...@.........nbo 0010: d956 b808 1194 1194 012c e314 0000 0000 .V.......,...... 0020: 1a02 08d7 71df 46ef be3a d6b9 0194 7e8e ....q.F..:....~. 0030: 0810 2000 ceee 06b6 0000 0120 0100 0014 .. ........ .... 0040: b426 9d84 d41a fd04 d183 345e d70b 7f94 .&........4^.... 0050: 0a00 0038 0000 0001 0000 0001 0000 002c ...8..........., 0060: 0103 0401 4dc1 e13b 0000 0020 010c 0000 ....M..;... .... 0070: 8001 0001 8002 04b0 8004 0001 8005 0001 ................ 0080: 8003 0002 8006 0080 0400 0014 c127 33f7 .............'3. 0090: 6971 d438 4675 9740 a12b 2918 0500 0084 iq.8Fu.@.+)..... 00a0: 6f28 842c 3b78 4933 a0fa 7bac b973 df89 o(.,;xI3..{..s.. 00b0: 5005 a7f1 9899 55af 7461 917c 9e31 fe7e P.....U.ta.|.1.~ 00c0: 2e38 c163 0f89 8ce5 1e99 62bd 5952 0ea5 .8.c......b.YR.. 00d0: cd34 c93c aebe 9499 f542 3810 6126 adc9 .4.<.....B8.a&.. 00e0: 2ff7 b6b2 acf6 3972 2064 88cd c70b 47be /.....9r d....G. 00f0: 9304 3e93 2ccd 6480 ebb6 cbd8 a0fa f71c ..>.,.d......... 0100: 5285 c487 8056 3642 7da0 99e1 ea82 f785 R....V6B}....... 0110: acb4 6056 2093 ff0c 5f0e 0ef3 3b9f 8abe ..`V ..._...;... 0120: 0500 0010 0400 0000 818f fa80 ffff ff80 ................ 0130: 0000 0010 0400 0000 c0a8 c700 ffff ff00 ................ /var/log/daemon Sep 9 11:00:01 q-dsl newsyslog[27262]: logfile turned over Sep 9 16:08:07 q-dsl isakmpd[25639]: isakmpd: starting Sep 9 16:08:07 q-dsl isakmpd[13061]: monitor_init: privileges dropped for child process Sep 9 16:08:08 q-dsl isakmpd[13061]: policy_init: initializing Sep 9 16:08:08 q-dsl isakmpd[13061]: virtual_listen_lookup: no match Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee80840 socket 9 ip ::1 port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80bc0 socket 10 ip ::1 port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: virtual_listen_lookup: no match Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee80040 socket 11 ip fe80:6::1 port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80a40 socket 12 ip fe80:6::1 port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: virtual_listen_lookup: no match Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee80cc0 socket 13 ip 127.0.0.1 port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80a00 socket 14 ip 127.0.0.1 port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: virtual_listen_lookup: no match Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee80d40 socket 15 ip 129.143.250.181 port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80c80 socket 16 ip 129.143.250.181 port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: virtual_listen_lookup: no match Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee80480 socket 17 ip fe80:1::200:24ff:fec9:5924 port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80740 socket 18 ip fe80:1::200:24ff:fec9:5924 port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: virtual_listen_lookup: no match Sep 9 16:08:08 q-dsl isakmpd[13061]: virtual_listen_lookup: no match Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee80d80 socket 19 ip 217.110.66.79 port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80880 socket 20 ip 217.110.66.79 port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: virtual_listen_lookup: no match Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee805c0 socket 21 ip fe80:3::200:24ff:fec9:5926 port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80940 socket 22 ip fe80:3::200:24ff:fec9:5926 port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee80ac0 socket 23 ip 0.0.0.0 port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80f00 socket 24 ip 0.0.0.0 port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_make: transport 0x7ee80080 socket 25 ip :: port 500 Sep 9 16:08:08 q-dsl isakmpd[13061]: udp_encap_make: transport 0x7ee80380 socket 26 ip :: port 4500 Sep 9 16:08:08 q-dsl isakmpd[13061]: nat_t_setup_hashes: MD5("draft-ietf-ipsec-nat-t-ike-02 ") (16 bytes) Sep 9 16:08:08 q-dsl isakmpd[13061]: nat_t_setup_hashes: Sep 9 16:08:08 q-dsl isakmpd[13061]: 90cb8091 3ebb696e 086381b5 ec427b1f Sep 9 16:08:08 q-dsl isakmpd[13061]: nat_t_setup_hashes: MD5("draft-ietf-ipsec-nat-t-ike-03") (16 bytes) Sep 9 16:08:08 q-dsl isakmpd[13061]: nat_t_setup_hashes: Sep 9 16:08:08 q-dsl isakmpd[13061]: 7d9419a6 5310ca6f 2c179d92 15529d56 Sep 9 16:08:08 q-dsl isakmpd[13061]: nat_t_setup_hashes: MD5("RFC 3947") (16 bytes) Sep 9 16:08:08 q-dsl isakmpd[13061]: nat_t_setup_hashes: Sep 9 16:08:08 q-dsl isakmpd[13061]: 4a131c81 07035845 5c5728f2 0e95452f Sep 9 16:08:08 q-dsl isakmpd[13061]: setup_vendor_hashes: MD5("OpenBSD-5.2") (16 bytes) Sep 9 16:08:08 q-dsl isakmpd[13061]: setup_vendor_hashes: Sep 9 16:08:08 q-dsl isakmpd[13061]: b8f26eaa 4cbf1b9a 150a3f12 dd64d183 Sep 9 16:08:08 q-dsl isakmpd[13061]: log_packet_init: starting IKE packet capture to file "/var/run/isakmpd.pcap" Sep 9 16:08:25 q-dsl isakmpd[13061]: ui_teardown: teardown connection "from-129.143.250.128/25-to-192.168.199.0/24", phase 2 Sep 9 16:08:25 q-dsl isakmpd[13061]: sa_find: no SA matched query Sep 9 16:08:35 q-dsl last message repeated 2 times Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_establish_p1: 0x848b5200 peer-217.86.184.8 phase1-peer-217.86.184.8 policy initiator phase 1 doi 1 exchange 2 step 0 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_establish_p1: icookie 1a0208d771df46ef rcookie 0000000000000000 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_establish_p1: msgid 00000000 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 1 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_enter: SA 0x848b5a00 added to SA list Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 2 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_create: sa 0x848b5a00 phase 1 added to exchange 0x848b5200 (peer-217.86.184.8) Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 3 references Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required SA Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_run: exchange 0x848b5200 finished step 0, advancing... Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_lookup_by_name: peer-217.86.184.8 == peer-217.86.184.8 && 1 == 1? Sep 9 16:08:35 q-dsl isakmpd[13061]: transport_send_messages: message 0x848b3700 scheduled for retransmission 1 in 7 secs Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_remove: SA 0x848b5a00 removed from SA list Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 3 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 3 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_enter: SA 0x848b5a00 added to SA list Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 3 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 3 references Sep 9 16:08:35 q-dsl isakmpd[13061]: check_vendor_openbsd: bad size 8 != 16 Sep 9 16:08:35 q-dsl isakmpd[13061]: dpd_check_vendor_payload: bad size 8 != 16 Sep 9 16:08:35 q-dsl isakmpd[13061]: nat_t_check_vendor_payload: NAT-T capable peer detected Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required SA Sep 9 16:08:35 q-dsl isakmpd[13061]: message_negotiate_sa: transform 1 proto 1 proposal 1 ok Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 0 type 1 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 0 type 14 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 0 type 2 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 0 type 4 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 0 type 3 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 0 type 11 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 0 type 12 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 1 type 1 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 1 type 2 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 1 type 3 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 1 type 4 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 1 type 11 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 1 type 12 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_xf_attrs: phase 1 mode 1 type 14 len 2 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_proto_xf: attr_map xf 0x84610b00 proto 0x7ee800c0 pa 0x821b1770 found 1 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_validate_proto_xf: req_attr xf 0x84610b00 proto 0x7ee800c0 pa 0x821b1770 found 1 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_add_transform: proto 0x7ee800c0 no 1 proto 1 chosen 0x84610b00 sa 0x848b5a00 id 1 Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_validate_prop: success Sep 9 16:08:35 q-dsl isakmpd[13061]: message_negotiate_sa: proposal 1 succeeded Sep 9 16:08:35 q-dsl isakmpd[13061]: ipsec_decode_transform: transform 1 chosen Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_handle_leftover_payloads: unexpected payload VENDOR Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_run: exchange 0x848b5200 finished step 1, advancing... Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 4 references Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_nonce: NONCE_i: Sep 9 16:08:35 q-dsl isakmpd[13061]: 6c78b0a2 ee6dde80 5cfe978a c002cb83 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required KEY_EXCH Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required NONCE Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_run: exchange 0x848b5200 finished step 2, advancing... Sep 9 16:08:35 q-dsl isakmpd[13061]: transport_send_messages: message 0x848b3500 scheduled for retransmission 1 in 7 secs Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 5 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 5 references Sep 9 16:08:35 q-dsl isakmpd[13061]: check_vendor_openbsd: bad size 8 != 16 Sep 9 16:08:35 q-dsl isakmpd[13061]: dpd_check_vendor_payload: bad size 8 != 16 Sep 9 16:08:35 q-dsl isakmpd[13061]: check_vendor_openbsd: bad size 8 != 16 Sep 9 16:08:35 q-dsl isakmpd[13061]: dpd_check_vendor_payload: bad size 8 != 16 Sep 9 16:08:35 q-dsl isakmpd[13061]: dpd_check_vendor_payload: DPD capable peer detected Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required KEY_EXCH Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required NONCE Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_nonce: NONCE_r: Sep 9 16:08:35 q-dsl isakmpd[13061]: e7197160 d2640f5d 69c58f2e b23131de 3b58b6ce Sep 9 16:08:35 q-dsl isakmpd[13061]: nat_t_exchange_check_nat_d: NAT detected, we're behind it Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_post_exchange_KE_NONCE: g^xy: Sep 9 16:08:35 q-dsl isakmpd[13061]: 0de45abe 195582d8 5bbd1fb8 e5b00223 aca62701 aa7bd7a5 732c3d59 bffa3dcc Sep 9 16:08:35 q-dsl isakmpd[13061]: 7fea9113 2febc78e 5136fb19 a006822e 7d778bcd dc27a245 d1bbe78a b81b3ff9 Sep 9 16:08:35 q-dsl isakmpd[13061]: df96289a 327d3333 192f37e1 83f77bc2 ff3ddd96 80f7ce90 aa2dbfaa d3f94368 Sep 9 16:08:35 q-dsl isakmpd[13061]: 4bfbf25b 00e87b75 39051354 44c75a3a cfc6e8ee b5364d44 aaa9cd61 42a3bf6f Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_post_exchange_KE_NONCE: SKEYID: Sep 9 16:08:35 q-dsl isakmpd[13061]: e932bcf0 a41254e5 8987237a 20c8607d Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_post_exchange_KE_NONCE: SKEYID_d: Sep 9 16:08:35 q-dsl isakmpd[13061]: 085d4c5f 3316fd6e 0a5a35ab 05ebe01e Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_post_exchange_KE_NONCE: SKEYID_a: Sep 9 16:08:35 q-dsl isakmpd[13061]: 9173a4bc 015433d6 25464272 8fbe7d58 Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_post_exchange_KE_NONCE: SKEYID_e: Sep 9 16:08:35 q-dsl isakmpd[13061]: 1148c23b c1f90aaf 0985a1f9 7631df16 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_handle_leftover_payloads: unexpected payload VENDOR Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_handle_leftover_payloads: unexpected payload VENDOR Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 4 references Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_run: exchange 0x848b5200 finished step 3, advancing... Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 4 references Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_send_ID: IPV4_ADDR: Sep 9 16:08:35 q-dsl isakmpd[13061]: d96e424f Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required ID Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required AUTH Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_run: exchange 0x848b5200 finished step 4, advancing... Sep 9 16:08:35 q-dsl isakmpd[13061]: virtual_send_message: enabling NAT-T encapsulation for this exchange Sep 9 16:08:35 q-dsl isakmpd[13061]: transport_send_messages: message 0x848b3500 scheduled for retransmission 1 in 7 secs Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 5 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 5 references Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required ID Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required AUTH Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_recv_ID: IPV4_ADDR: Sep 9 16:08:35 q-dsl isakmpd[13061]: c0a832fd Sep 9 16:08:35 q-dsl isakmpd[13061]: ike_phase_1_recv_AUTH: computed HASH_R: Sep 9 16:08:35 q-dsl isakmpd[13061]: 0bf90b96 c8a57da2 30dd87c1 3980a0ae Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 4 references Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_finalize: 0x848b5200 peer-217.86.184.8 phase1-peer-217.86.184.8 policy initiator phase 1 doi 1 exchange 2 step 5 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_finalize: icookie 1a0208d771df46ef rcookie be3ad6b901947e8e Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_finalize: msgid 00000000 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_find: no SA matched query Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_finalize: phase 1 done: initiator id 217.110.66.79, responder id 192.168.50.253, src: 217.110.66.79 dst: 217.86.184.8 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 4 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 5 references Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_establish_finalize: finalizing exchange 0x848b5200 with arg 0x7ee80e40 (from-129.143.250.128/25-to-192.168.199.0/24) & fail = 0 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_lookup_by_name: from-129.143.250.128/25-to-192.168.199.0/24 == peer-217.86.184.8 && 2 == 1? Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_find: return SA 0x848b5a00 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_establish_p2: 0x848b5800 from-129.143.250.128/25-to-192.168.199.0/24 phase2-from-129.143.250.128/25-to-192.168.199.0/24 policy initiator phase 2 doi 1 exchange 32 step 0 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_establish_p2: icookie 1a0208d771df46ef rcookie be3ad6b901947e8e Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_establish_p2: msgid ceee06b6 sa_list Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5400 now has 1 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_enter: SA 0x848b5400 added to SA list Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5400 now has 2 references Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_create: sa 0x848b5400 phase 2 added to exchange 0x848b5800 (from-129.143.250.128/25-to-192.168.199.0/24) Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 6 references Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_nonce: NONCE_i: Sep 9 16:08:35 q-dsl isakmpd[13061]: c12733f7 6971d438 46759740 a12b2918 Sep 9 16:08:35 q-dsl isakmpd[13061]: initiator_send_HASH_SA_NONCE: IDic: Sep 9 16:08:35 q-dsl isakmpd[13061]: c01d1b82 04000000 818ffa80 ffffff80 Sep 9 16:08:35 q-dsl isakmpd[13061]: initiator_send_HASH_SA_NONCE: IDrc: Sep 9 16:08:35 q-dsl isakmpd[13061]: 01000000 04000000 c0a8c700 ffffff00 Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required HASH Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required SA Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_validate: checking for required NONCE Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_run: exchange 0x848b5800 finished step 0, advancing... Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_find: no SA matched query Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 6 references Sep 9 16:08:35 q-dsl isakmpd[13061]: exchange_free_aux: freeing exchange 0x848b5200 Sep 9 16:08:35 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 5 references Sep 9 16:08:35 q-dsl isakmpd[13061]: virtual_send_message: enabling NAT-T encapsulation for this exchange Sep 9 16:08:35 q-dsl isakmpd[13061]: transport_send_messages: message 0x848b3500 scheduled for retransmission 1 in 7 secs Sep 9 16:08:42 q-dsl isakmpd[13061]: transport_send_messages: message 0x848b3500 scheduled for retransmission 2 in 9 secs Sep 9 16:08:42 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 5 references Sep 9 16:08:42 q-dsl isakmpd[13061]: message_recv: phase 1 message after ISAKMP SA is ready Sep 9 16:08:42 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 5 references Sep 9 16:08:51 q-dsl isakmpd[13061]: transport_send_messages: message 0x848b3500 scheduled for retransmission 3 in 11 secs Sep 9 16:08:51 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 5 references Sep 9 16:08:51 q-dsl isakmpd[13061]: message_recv: phase 1 message after ISAKMP SA is ready Sep 9 16:08:51 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 5 references Sep 9 16:09:02 q-dsl isakmpd[13061]: transport_send_messages: giving up on exchange from-129.143.250.128/25-to-192.168.199.0/24, no response from peer 217.86.184.8:4500 Sep 9 16:09:02 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 4 references Sep 9 16:09:02 q-dsl isakmpd[13061]: sa_reference: SA 0x848b5a00 now has 4 references Sep 9 16:09:02 q-dsl isakmpd[13061]: message_recv: phase 1 message after ISAKMP SA is ready Sep 9 16:09:02 q-dsl isakmpd[13061]: sa_release: SA 0x848b5a00 had 4 references Sep 9 16:09:35 q-dsl isakmpd[13061]: sa_find: no SA matched query Sep 9 16:09:35 q-dsl isakmpd[13061]: exchange_lookup_by_name: from-129.143.250.128/25-to-192.168.199.0/24 == from-129.143.250.128/25-to-192.168.199.0/24 && 2 == 2? Sep 9 16:09:35 q-dsl isakmpd[13061]: exchange_establish: from-129.143.250.128/25-to-192.168.199.0/24 exchange already exists as 0x848b5800 Sep 9 16:09:39 q-dsl isakmpd[13061]: ui_shutdown_daemon: received shutdown command Sep 9 16:09:39 q-dsl isakmpd[13061]: isakmpd: shutting down... > -----Ursprüngliche Nachricht----- > Von: owner-m...@openbsd.org [mailto:owner-m...@openbsd.org] Im > Auftrag von Christoph Leser > Gesendet: Montag, 9. September 2013 12:13 > An: misc@openbsd.org > Betreff: Help with ISAKMP Nat Traversal Problem needed > > Hello misc, > > My openBSD Gateway seems to have a problem with ISAKMP Nat Traversal > to a remote Sonicwall. The ISAKMP Exchange fails in pase 2. > > The remote Sonicwall is behind a NAT device. > > Before I blame one side or the other for misbehavior, I would like you to > take a look at the traces I will provide here and help me with the proper > interpretation. > > The setup is simple: > > openBSD has direct access to the internet with IP address 217.110.66.79 > > SonicWall is behind IP address 217.86.184.8 > > My /etc/ipsec.conf is > > ike active esp tunnel from 129.143.250.128/25 to 192.168.199.0/24 peer > 217.86.184.8 main auth hmac-md5 enc aes-128 group modp1024 quick auth > hmac-md5 enc aes-128 group modp1024 psk 'xyz' > > What I think happens here is that openBSD recognizes that a NAT device is > between Sonicwall and itself. And switches to NAT encapsulation. And > Sonciwall only proposes NAT-T with RFC3947. ( Also see the NAT related > messages in the debug output below ) > > But in the phase 2 transform proposal openBSD requests 'TUNNEL' > encapsulation mode instead of 'UDP-encapsulated-TUNNEL' as required by > RFC-3947. ( See bytes 78-7b in the hexdump of the first quick mode packet, > it reads 80040001 instead of 80040003 ). > > Here is tcpdump output from /var/run/isakmpd.pcap ( I have removed the > hexdump part from all but the last packet for brevity ) > > 10:36:51.578451 0.0.0.0.500 > 217.86.184.8.500: [udp sum ok] isakmp v1.0 > exchange ID_PROT > cookie: daf885a1cd119c2d->0000000000000000 msgid: 00000000 len: > 184 > payload: SA len: 56 DOI: 1(IPSEC) situation: IDENTITY_ONLY > payload: PROPOSAL len: 44 proposal: 1 proto: ISAKMP spisz: 0 > xforms: 1 > payload: TRANSFORM len: 36 > transform: 0 ID: ISAKMP > attribute ENCRYPTION_ALGORITHM = AES_CBC > attribute HASH_ALGORITHM = MD5 > attribute AUTHENTICATION_METHOD = PRE_SHARED > attribute GROUP_DESCRIPTION = MODP_1024 > attribute LIFE_TYPE = SECONDS > attribute LIFE_DURATION = 3600 > attribute KEY_LENGTH = 128 > payload: VENDOR len: 20 > payload: VENDOR len: 20 (supports v2 NAT-T, draft-ietf-ipsec-nat-t- > ike-02) > payload: VENDOR len: 20 (supports v3 NAT-T, draft-ietf-ipsec-nat-t- > ike-03) > payload: VENDOR len: 20 (supports NAT-T, RFC 3947) > payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 212) > > 10:36:51.651586 217.86.184.8.500 > 217.110.66.79.500: [udp sum ok] isakmp > v1.0 exchange ID_PROT > cookie: daf885a1cd119c2d->3264ac29e5082e4c msgid: 00000000 len: > 116 > payload: SA len: 56 DOI: 1(IPSEC) situation: IDENTITY_ONLY > payload: PROPOSAL len: 44 proposal: 1 proto: ISAKMP spisz: 0 > xforms: 1 > payload: TRANSFORM len: 36 > transform: 1 ID: ISAKMP > attribute ENCRYPTION_ALGORITHM = AES_CBC > attribute KEY_LENGTH = 128 > attribute HASH_ALGORITHM = MD5 > attribute GROUP_DESCRIPTION = MODP_1024 > attribute AUTHENTICATION_METHOD = PRE_SHARED > attribute LIFE_TYPE = SECONDS > attribute LIFE_DURATION = 3600 > payload: VENDOR len: 12 > payload: VENDOR len: 20 (supports NAT-T, RFC 3947) [ttl 0] (id 1, len > 144) > > 10:36:51.745502 217.110.66.79.500 > 217.86.184.8.500: [udp sum ok] isakmp > v1.0 exchange ID_PROT > cookie: daf885a1cd119c2d->3264ac29e5082e4c msgid: 00000000 len: > 220 > payload: KEY_EXCH len: 132 > payload: NONCE len: 20 > payload: NAT-D len: 20 > payload: NAT-D len: 20 [ttl 0] (id 1, len 248) > > 10:36:51.833947 217.86.184.8.500 > 217.110.66.79.500: [udp sum ok] isakmp > v1.0 exchange ID_PROT > cookie: daf885a1cd119c2d->3264ac29e5082e4c msgid: 00000000 len: > 268 > payload: KEY_EXCH len: 132 > payload: NAT-D len: 20 > payload: NAT-D len: 20 > payload: NONCE len: 24 > payload: VENDOR len: 12 > payload: VENDOR len: 12 (supports draft-ietf-ipsra-isakmp-xauth- > 06.txt) > payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 296) > > 10:36:51.927437 217.110.66.79.4500 > 217.86.184.8.4500: [bad udp cksum > aaf3!] udpencap: isakmp v1.0 exchange ID_PROT > cookie: daf885a1cd119c2d->3264ac29e5082e4c msgid: 00000000 len: > 88 > payload: ID len: 12 type: IPV4_ADDR = 217.110.66.79 > payload: HASH len: 20 > payload: NOTIFICATION len: 28 > notification: INITIAL CONTACT (daf885a1cd119c2d- > >3264ac29e5082e4c) [ttl 0] (id 1, len 120) > > 10:36:51.998066 217.86.184.8.4500 > 217.110.66.79.4500: [bad udp cksum > 1c00!] udpencap: isakmp v1.0 exchange ID_PROT > cookie: daf885a1cd119c2d->3264ac29e5082e4c msgid: 00000000 len: > 60 > payload: ID len: 12 type: IPV4_ADDR = 192.168.50.253 > payload: HASH len: 20 [ttl 0] (id 1, len 92) > > 10:36:52.092038 217.110.66.79.4500 > 217.86.184.8.4500: [udp sum ok] > udpencap: isakmp v1.0 exchange QUICK_MODE > cookie: daf885a1cd119c2d->3264ac29e5082e4c msgid: 15222280 len: > 288 > payload: HASH len: 20 > payload: SA len: 56 DOI: 1(IPSEC) situation: IDENTITY_ONLY > payload: PROPOSAL len: 44 proposal: 1 proto: IPSEC_ESP spisz: 4 > xforms: 1 SPI: 0x95d528a5 > payload: TRANSFORM len: 32 > transform: 1 ID: AES > attribute LIFE_TYPE = SECONDS > attribute LIFE_DURATION = 1200 > attribute ENCAPSULATION_MODE = TUNNEL > attribute AUTHENTICATION_ALGORITHM = HMAC_MD5 > attribute GROUP_DESCRIPTION = 2 > attribute KEY_LENGTH = 128 > payload: NONCE len: 20 > payload: KEY_EXCH len: 132 > payload: ID len: 16 type: IPV4_ADDR_SUBNET = > 129.143.250.128/255.255.255.128 > payload: ID len: 16 type: IPV4_ADDR_SUBNET = > 192.168.199.0/255.255.255.0 [ttl 0] (id 1, len 320) > 0000: 4500 0140 0001 0000 0011 0c90 d96e 424f e...@.........nbo > 0010: d956 b808 1194 1194 012c 285b 0000 0000 .V.......,([.... > 0020: daf8 85a1 cd11 9c2d 3264 ac29 e508 2e4c .......-2d.)...L > 0030: 0810 2000 1522 2280 0000 0120 0100 0014 .. .."".... .... > 0040: 1db1 7091 0a7b b345 84d2 11a9 1e43 b16f ..p..{.E.....C.o > 0050: 0a00 0038 0000 0001 0000 0001 0000 002c ...8..........., > 0060: 0103 0401 95d5 28a5 0000 0020 010c 0000 ......(.... .... > 0070: 8001 0001 8002 04b0 8004 0001 8005 0001 ................ > 0080: 8003 0002 8006 0080 0400 0014 168c 87e4 ................ > 0090: d36c 1705 2104 c48d 9afb 55a6 0500 0084 .l..!.....U..... > 00a0: 077a f2a2 1433 6161 54cd 51e4 7702 a0bd .z...3aaT.Q.w... > 00b0: f392 1d96 d7fe 4183 5caf 53ac c8d5 e6c7 ......A.\.S..... > 00c0: 92c7 9af0 697d fbd0 c0da 14e0 11fc c7a9 ....i}.......... > 00d0: 4578 37f8 f25e 8b24 f869 f24d bea9 5daa Ex7..^.$.i.M..]. > 00e0: 5417 4604 377a 8a42 18ab d528 238e 3115 T.F.7z.B...(#.1. > 00f0: 0120 f7b1 ca65 7260 d108 28da d4af 69ed . ...er`..(...i. > 0100: cc46 8258 fcf5 22ee e517 8a47 9851 eb49 .F.X.."....G.Q.I > 0110: 26b7 20bd 4657 2838 ad01 9a13 a5d1 dab8 &. .FW(8........ > 0120: 0500 0010 0400 0000 818f fa80 ffff ff80 ................ > 0130: 0000 0010 0400 0000 c0a8 c700 ffff ff00 ................ > > > And here is the debug output from isakmpd -D 6=99 -D7=99 -D8=99 -D2=50 - > K -L > > Sep 9 10:36:35 q-dsl isakmpd[9931]: isakmpd: starting Sep 9 10:36:36 q-dsl > isakmpd[8122]: nat_t_setup_hashes: MD5("draft-ietf-ipsec-nat-t-ike-02 ") > (16 bytes) Sep 9 10:36:36 q-dsl isakmpd[8122]: nat_t_setup_hashes: > Sep 9 10:36:36 q-dsl isakmpd[8122]: 90cb8091 3ebb696e 086381b5 ec427b1f > Sep 9 10:36:36 q-dsl isakmpd[8122]: nat_t_setup_hashes: MD5("draft-ietf- > ipsec-nat-t-ike-03") (16 bytes) Sep 9 10:36:36 q-dsl isakmpd[8122]: > nat_t_setup_hashes: > Sep 9 10:36:36 q-dsl isakmpd[8122]: 7d9419a6 5310ca6f 2c179d92 15529d56 > Sep 9 10:36:36 q-dsl isakmpd[8122]: nat_t_setup_hashes: MD5("RFC 3947") > (16 bytes) Sep 9 10:36:36 q-dsl isakmpd[8122]: nat_t_setup_hashes: > Sep 9 10:36:36 q-dsl isakmpd[8122]: 4a131c81 07035845 5c5728f2 0e95452f > Sep 9 10:36:36 q-dsl isakmpd[8122]: setup_vendor_hashes: MD5("OpenBSD- > 5.2") (16 bytes) Sep 9 10:36:36 q-dsl isakmpd[8122]: setup_vendor_hashes: > Sep 9 10:36:36 q-dsl isakmpd[8122]: b8f26eaa 4cbf1b9a 150a3f12 dd64d183 > Sep 9 10:36:36 q-dsl isakmpd[8122]: log_packet_init: starting IKE packet > capture to file "/var/run/isakmpd.pcap" > Sep 9 10:36:41 q-dsl isakmpd[8122]: sa_find: no SA matched query Sep 9 > 10:36:51 q-dsl last message repeated 2 times Sep 9 10:36:51 q-dsl > isakmpd[8122]: exchange_establish_p1: 0x7e39c700 peer-217.86.184.8 > phase1-peer-217.86.184.8 policy initiator phase 1 doi 1 exchange 2 step 0 > Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_establish_p1: icookie > daf885a1cd119c2d rcookie 0000000000000000 Sep 9 10:36:51 q-dsl > isakmpd[8122]: exchange_establish_p1: msgid 00000000 Sep 9 10:36:51 q-dsl > isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 1 references Sep 9 > 10:36:51 q-dsl isakmpd[8122]: sa_enter: SA 0x7e39ca00 added to SA list Sep > 9 10:36:51 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 2 > references Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_create: sa 0x7e39ca00 > phase 1 added to exchange 0x7e39c700 (peer-217.86.184.8) Sep 9 10:36:51 q- > dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 3 references Sep 9 > 10:36:51 q-dsl isakmpd[8122]: exchange_validate: checking for required SA > Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_run: exchange 0x7e39c700 > finished step 0, advancing... > Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_lookup_by_name: peer- > 217.86.184.8 == peer-217.86.184.8 && 1 == 1? > Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_remove: SA 0x7e39ca00 removed > from SA list Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_release: SA 0x7e39ca00 > had 3 references Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_reference: SA > 0x7e39ca00 now has 3 references Sep 9 10:36:51 q-dsl isakmpd[8122]: > sa_enter: SA 0x7e39ca00 added to SA list Sep 9 10:36:51 q-dsl > isakmpd[8122]: message_free: freeing 0x7e39f000 Sep 9 10:36:51 q-dsl > isakmpd[8122]: sa_release: SA 0x7e39ca00 had 3 references Sep 9 10:36:51 > q-dsl isakmpd[8122]: message_parse_payloads: offset 28 payload SA Sep 9 > 10:36:51 q-dsl isakmpd[8122]: message_parse_payloads: offset 84 payload > VENDOR Sep 9 10:36:51 q-dsl isakmpd[8122]: message_parse_payloads: > offset 96 payload VENDOR Sep 9 10:36:51 q-dsl isakmpd[8122]: > sa_reference: SA 0x7e39ca00 now has 3 references Sep 9 10:36:51 q-dsl > isakmpd[8122]: message_parse_payloads: offset 40 payload PROPOSAL Sep > 9 10:36:51 q-dsl isakmpd[8122]: message_parse_payloads: offset 48 payload > TRANSFORM Sep 9 10:36:51 q-dsl isakmpd[8122]: Transform 1's attributes > Sep 9 10:36:51 q-dsl isakmpd[8122]: Attribute ENCRYPTION_ALGORITHM > value 7 Sep 9 10:36:51 q-dsl isakmpd[8122]: Attribute KEY_LENGTH value 128 > Sep 9 10:36:51 q-dsl isakmpd[8122]: Attribute HASH_ALGORITHM value 1 > Sep 9 10:36:51 q-dsl isakmpd[8122]: Attribute GROUP_DESCRIPTION value 2 > Sep 9 10:36:51 q-dsl isakmpd[8122]: Attribute AUTHENTICATION_METHOD > value 1 Sep 9 10:36:51 q-dsl isakmpd[8122]: Attribute LIFE_TYPE value 1 Sep > 9 10:36:51 q-dsl isakmpd[8122]: Attribute LIFE_DURATION value 3600 Sep 9 > 10:36:51 q-dsl isakmpd[8122]: check_vendor_openbsd: bad size 8 != 16 Sep 9 > 10:36:51 q-dsl isakmpd[8122]: dpd_check_vendor_payload: bad size 8 != 16 > Sep 9 10:36:51 q-dsl isakmpd[8122]: message_validate_vendor: vendor ID > seen Sep 9 10:36:51 q-dsl isakmpd[8122]: nat_t_check_vendor_payload: > NAT-T capable peer detected Sep 9 10:36:51 q-dsl isakmpd[8122]: > exchange_validate: checking for required SA Sep 9 10:36:51 q-dsl > isakmpd[8122]: message_negotiate_sa: transform 1 proto 1 proposal 1 ok > Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_validate_xf_attrs: phase 1 mode 0 > type 1 len 2 Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_validate_xf_attrs: phase > 1 mode 0 type 14 len 2 Sep 9 10:36:51 q-dsl isakmpd[8122]: > sa_validate_xf_attrs: phase 1 mode 0 type 2 len 2 Sep 9 10:36:51 q-dsl > isakmpd[8122]: sa_validate_xf_attrs: phase 1 mode 0 type 4 len 2 Sep 9 > 10:36:51 q-dsl isakmpd[8122]: sa_validate_xf_attrs: phase 1 mode 0 type 3 > len 2 Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_validate_xf_attrs: phase 1 > mode 0 type 11 len 2 Sep 9 10:36:51 q-dsl isakmpd[8122]: > sa_validate_xf_attrs: phase 1 mode 0 type 12 len 2 Sep 9 10:36:51 q-dsl > isakmpd[8122]: sa_validate_xf_attrs: phase 1 mode 1 type 1 len 2 Sep 9 > 10:36:51 q-dsl isakmpd[8122]: sa_validate_xf_attrs: phase 1 mode 1 type 2 > len 2 Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_validate_xf_attrs: phase 1 > mode 1 type 3 len 2 Sep 9 10:36:51 q-dsl isakmpd[8122]: > sa_validate_xf_attrs: phase 1 mode 1 type 4 len 2 Sep 9 10:36:51 q-dsl > isakmpd[8122]: sa_validate_xf_attrs: phase 1 mode 1 type 11 len 2 Sep 9 > 10:36:51 q-dsl isakmpd[8122]: sa_validate_xf_attrs: phase 1 mode 1 type 12 > len 2 Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_validate_xf_attrs: phase 1 > mode 1 type 14 len 2 Sep 9 10:36:51 q-dsl isakmpd[8122]: > sa_validate_proto_xf: attr_map xf 0x869c5800 proto 0x85f087c0 pa > 0x82e2bb30 found 1 Sep 9 10:36:51 q-dsl isakmpd[8122]: > sa_validate_proto_xf: req_attr xf 0x869c5800 proto 0x85f087c0 pa > 0x82e2bb30 found 1 Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_add_transform: > proto 0x85f087c0 no 1 proto 1 chosen 0x869c5800 sa 0x7e39ca00 id 1 Sep 9 > 10:36:51 q-dsl isakmpd[8122]: ike_phase_1_validate_prop: success Sep 9 > 10:36:51 q-dsl isakmpd[8122]: message_negotiate_sa: proposal 1 succeeded > Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_handle_leftover_payloads: > unexpected payload VENDOR Sep 9 10:36:51 q-dsl isakmpd[8122]: > exchange_run: exchange 0x7e39c700 finished step 1, advancing... > Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 4 > references Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_nonce: NONCE_i: > Sep 9 10:36:51 q-dsl isakmpd[8122]: 860ed9d8 039cf270 c5dc0ff1 26d1086d > Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_validate: checking for > required KEY_EXCH Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_validate: > checking for required NONCE Sep 9 10:36:51 q-dsl isakmpd[8122]: > exchange_run: exchange 0x7e39c700 finished step 2, advancing... > Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 5 > references Sep 9 10:36:51 q-dsl isakmpd[8122]: message_free: freeing > 0x7e39f700 Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_release: SA 0x7e39ca00 > had 5 references Sep 9 10:36:51 q-dsl isakmpd[8122]: > message_parse_payloads: offset 28 payload KEY_EXCH Sep 9 10:36:51 q-dsl > isakmpd[8122]: message_parse_payloads: offset 160 payload NAT_D Sep 9 > 10:36:51 q-dsl isakmpd[8122]: message_parse_payloads: offset 180 payload > NAT_D Sep 9 10:36:51 q-dsl isakmpd[8122]: message_parse_payloads: offset > 200 payload NONCE Sep 9 10:36:51 q-dsl isakmpd[8122]: > message_parse_payloads: offset 224 payload VENDOR Sep 9 10:36:51 q-dsl > isakmpd[8122]: message_parse_payloads: offset 236 payload VENDOR Sep 9 > 10:36:51 q-dsl isakmpd[8122]: message_parse_payloads: offset 248 payload > VENDOR Sep 9 10:36:51 q-dsl isakmpd[8122]: check_vendor_openbsd: bad > size 8 != 16 Sep 9 10:36:51 q-dsl isakmpd[8122]: dpd_check_vendor_payload: > bad size 8 != 16 Sep 9 10:36:51 q-dsl isakmpd[8122]: > message_validate_vendor: vendor ID seen Sep 9 10:36:51 q-dsl > isakmpd[8122]: check_vendor_openbsd: bad size 8 != 16 Sep 9 10:36:51 q-dsl > isakmpd[8122]: dpd_check_vendor_payload: bad size 8 != 16 Sep 9 10:36:51 > q-dsl isakmpd[8122]: message_validate_vendor: vendor ID seen Sep 9 > 10:36:51 q-dsl isakmpd[8122]: dpd_check_vendor_payload: DPD capable > peer detected Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_validate: > checking for required KEY_EXCH Sep 9 10:36:51 q-dsl isakmpd[8122]: > exchange_validate: checking for required NONCE Sep 9 10:36:51 q-dsl > isakmpd[8122]: exchange_nonce: NONCE_r: > Sep 9 10:36:51 q-dsl isakmpd[8122]: 88ee8a64 40c442d3 fc9ca727 99c569df > 522786a6 Sep 9 10:36:51 q-dsl isakmpd[8122]: nat_t_exchange_check_nat_d: > NAT detected, we're behind it Sep 9 10:36:51 q-dsl isakmpd[8122]: > ike_phase_1_post_exchange_KE_NONCE: g^xy: > Sep 9 10:36:51 q-dsl isakmpd[8122]: 136de78f b8acda57 853e5fdd 59429df4 > 168791f7 aba30f64 fc9ba6a9 14f3a9dc Sep 9 10:36:51 q-dsl isakmpd[8122]: > cf1c899e fce4fca5 101ddc0b 32500505 de025e3f 6c9af45d 199c7a28 cbaeb116 > Sep 9 10:36:51 q-dsl isakmpd[8122]: d0ba0a99 5374372c 8974a4d2 5be7c2be > d2a64c4c 9bf8a765 40196f4a 902629e3 Sep 9 10:36:51 q-dsl isakmpd[8122]: > 947e4b7f f25ce3c7 8c0c7512 a92bdb0a 07bf32cd 8ef1a56c 87ae6226 917f4f0d > Sep 9 10:36:51 q-dsl isakmpd[8122]: > ike_phase_1_post_exchange_KE_NONCE: SKEYID: > Sep 9 10:36:51 q-dsl isakmpd[8122]: c5053a12 4f706994 49673142 0d71cd17 > Sep 9 10:36:51 q-dsl isakmpd[8122]: > ike_phase_1_post_exchange_KE_NONCE: SKEYID_d: > Sep 9 10:36:51 q-dsl isakmpd[8122]: 8300ac8c 34c3e8e2 c78dbb8e a5539481 > Sep 9 10:36:51 q-dsl isakmpd[8122]: > ike_phase_1_post_exchange_KE_NONCE: SKEYID_a: > Sep 9 10:36:51 q-dsl isakmpd[8122]: 4b9395f3 1719c087 4812fb3d 585ade9c > Sep 9 10:36:51 q-dsl isakmpd[8122]: > ike_phase_1_post_exchange_KE_NONCE: SKEYID_e: > Sep 9 10:36:51 q-dsl isakmpd[8122]: fd20805e 7dad1fa6 b158a3cf 75d14bc5 > Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_handle_leftover_payloads: > unexpected payload VENDOR Sep 9 10:36:51 q-dsl isakmpd[8122]: > exchange_handle_leftover_payloads: unexpected payload VENDOR Sep 9 > 10:36:51 q-dsl isakmpd[8122]: message_free: freeing 0x7e39f580 Sep 9 > 10:36:51 q-dsl isakmpd[8122]: sa_release: SA 0x7e39ca00 had 4 references > Sep 9 10:36:51 q-dsl isakmpd[8122]: exchange_run: exchange 0x7e39c700 > finished step 3, advancing... > Sep 9 10:36:51 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 4 > references Sep 9 10:36:51 q-dsl isakmpd[8122]: ike_phase_1_send_ID: > IPV4_ADDR: > Sep 9 10:36:51 q-dsl isakmpd[8122]: d96e424f Sep 9 10:36:51 q-dsl > isakmpd[8122]: exchange_validate: checking for required ID Sep 9 10:36:51 > q-dsl isakmpd[8122]: exchange_validate: checking for required AUTH Sep 9 > 10:36:51 q-dsl isakmpd[8122]: exchange_run: exchange 0x7e39c700 finished > step 4, advancing... > Sep 9 10:36:51 q-dsl isakmpd[8122]: virtual_send_message: enabling NAT-T > encapsulation for this exchange Sep 9 10:36:51 q-dsl isakmpd[8122]: > sa_reference: SA 0x7e39ca00 now has 5 references Sep 9 10:36:51 q-dsl > isakmpd[8122]: message_free: freeing 0x7e39f680 Sep 9 10:36:51 q-dsl > isakmpd[8122]: sa_release: SA 0x7e39ca00 had 5 references Sep 9 10:36:51 > q-dsl isakmpd[8122]: message_parse_payloads: offset 28 payload ID Sep 9 > 10:36:51 q-dsl isakmpd[8122]: message_parse_payloads: offset 40 payload > HASH Sep 9 10:36:51 q-dsl isakmpd[8122]: ipsec_validate_id_information: > proto 0 port 0 type 1 Sep 9 10:36:51 q-dsl isakmpd[8122]: > ipsec_validate_id_information: IPv4: > Sep 9 10:36:51 q-dsl isakmpd[8122]: c0a832fd Sep 9 10:36:51 q-dsl > isakmpd[8122]: exchange_validate: checking for required ID Sep 9 10:36:51 > q-dsl isakmpd[8122]: exchange_validate: checking for required AUTH Sep 9 > 10:36:51 q-dsl isakmpd[8122]: ike_phase_1_recv_ID: IPV4_ADDR: > Sep 9 10:36:51 q-dsl isakmpd[8122]: c0a832fd Sep 9 10:36:51 q-dsl > isakmpd[8122]: ike_phase_1_recv_AUTH: computed HASH_R: > Sep 9 10:36:52 q-dsl isakmpd[8122]: 3deb0d42 7f807f4e 538e1cfd 96e78cce > Sep 9 10:36:52 q-dsl isakmpd[8122]: message_free: freeing 0x7e39f400 Sep > 9 10:36:52 q-dsl isakmpd[8122]: sa_release: SA 0x7e39ca00 had 4 references > Sep 9 10:36:52 q-dsl isakmpd[8122]: exchange_finalize: 0x7e39c700 peer- > 217.86.184.8 phase1-peer-217.86.184.8 policy initiator phase 1 doi 1 > exchange 2 step 5 Sep 9 10:36:52 q-dsl isakmpd[8122]: exchange_finalize: > icookie daf885a1cd119c2d rcookie 3264ac29e5082e4c Sep 9 10:36:52 q-dsl > isakmpd[8122]: exchange_finalize: msgid 00000000 Sep 9 10:36:52 q-dsl > isakmpd[8122]: sa_find: no SA matched query Sep 9 10:36:52 q-dsl > isakmpd[8122]: exchange_finalize: phase 1 done: initiator id 217.110.66.79, > responder id 192.168.50.253, src: 217.110.66.79 dst: 217.86.184.8 Sep 9 > 10:36:52 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 4 > references Sep 9 10:36:52 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 > now has 5 references Sep 9 10:36:52 q-dsl isakmpd[8122]: > exchange_establish_finalize: finalizing exchange 0x7e39c700 with arg > 0x85f08f00 (from-129.143.250.128/25-to-192.168.199.0/24) & fail = 0 Sep 9 > 10:36:52 q-dsl isakmpd[8122]: exchange_lookup_by_name: from- > 129.143.250.128/25-to-192.168.199.0/24 == peer-217.86.184.8 && 2 == 1? > Sep 9 10:36:52 q-dsl isakmpd[8122]: sa_find: return SA 0x7e39ca00 Sep 9 > 10:36:52 q-dsl isakmpd[8122]: exchange_establish_p2: 0x7e39c600 from- > 129.143.250.128/25-to-192.168.199.0/24 phase2-from-129.143.250.128/25-to- > 192.168.199.0/24 policy initiator phase 2 doi 1 exchange 32 step 0 Sep 9 > 10:36:52 q-dsl isakmpd[8122]: exchange_establish_p2: icookie > daf885a1cd119c2d rcookie 3264ac29e5082e4c Sep 9 10:36:52 q-dsl > isakmpd[8122]: exchange_establish_p2: msgid 15222280 sa_list Sep 9 > 10:36:52 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39c800 now has 1 > references Sep 9 10:36:52 q-dsl isakmpd[8122]: sa_enter: SA 0x7e39c800 > added to SA list Sep 9 10:36:52 q-dsl isakmpd[8122]: sa_reference: SA > 0x7e39c800 now has 2 references Sep 9 10:36:52 q-dsl isakmpd[8122]: > sa_create: sa 0x7e39c800 phase 2 added to exchange 0x7e39c600 (from- > 129.143.250.128/25-to-192.168.199.0/24) > Sep 9 10:36:52 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 6 > references Sep 9 10:36:52 q-dsl isakmpd[8122]: exchange_nonce: NONCE_i: > Sep 9 10:36:52 q-dsl isakmpd[8122]: 168c87e4 d36c1705 2104c48d 9afb55a6 > Sep 9 10:36:52 q-dsl isakmpd[8122]: initiator_send_HASH_SA_NONCE: IDic: > Sep 9 10:36:52 q-dsl isakmpd[8122]: 00000000 04000000 818ffa80 ffffff80 Sep > 9 10:36:52 q-dsl isakmpd[8122]: initiator_send_HASH_SA_NONCE: IDrc: > Sep 9 10:36:52 q-dsl isakmpd[8122]: 01000000 04000000 c0a8c700 ffffff00 Sep > 9 10:36:52 q-dsl isakmpd[8122]: exchange_validate: checking for required > HASH Sep 9 10:36:52 q-dsl isakmpd[8122]: exchange_validate: checking for > required SA Sep 9 10:36:52 q-dsl isakmpd[8122]: exchange_validate: > checking for required NONCE Sep 9 10:36:52 q-dsl isakmpd[8122]: > exchange_run: exchange 0x7e39c600 finished step 0, advancing... > Sep 9 10:36:52 q-dsl isakmpd[8122]: sa_find: no SA matched query Sep 9 > 10:36:52 q-dsl isakmpd[8122]: sa_release: SA 0x7e39ca00 had 6 references > Sep 9 10:36:52 q-dsl isakmpd[8122]: exchange_free_aux: freeing exchange > 0x7e39c700 Sep 9 10:36:52 q-dsl isakmpd[8122]: message_free: freeing > 0x83340b80 Sep 9 10:36:52 q-dsl isakmpd[8122]: sa_release: SA 0x7e39ca00 > had 5 references Sep 9 10:36:52 q-dsl isakmpd[8122]: > virtual_send_message: enabling NAT-T encapsulation for this exchange Sep > 9 10:36:59 q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 5 > references Sep 9 10:36:59 q-dsl isakmpd[8122]: message_recv: phase 1 > message after ISAKMP SA is ready Sep 9 10:36:59 q-dsl isakmpd[8122]: > message_free: freeing 0x7e39fb00 Sep 9 10:36:59 q-dsl isakmpd[8122]: > sa_release: SA 0x7e39ca00 had 5 references Sep 9 10:37:08 q-dsl > isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 5 references Sep 9 > 10:37:08 q-dsl isakmpd[8122]: message_recv: phase 1 message after ISAKMP > SA is ready Sep 9 10:37:08 q-dsl isakmpd[8122]: message_free: freeing > 0x7e39f100 Sep 9 10:37:08 q-dsl isakmpd[8122]: sa_release: SA 0x7e39ca00 > had 5 references Sep 9 10:37:19 q-dsl isakmpd[8122]: > transport_send_messages: giving up on exchange from-129.143.250.128/25- > to-192.168.199.0/24, no response from peer 217.86.184.8:4500 Sep 9 10:37:19 > q-dsl isakmpd[8122]: message_free: freeing 0x7e39f680 Sep 9 10:37:19 q-dsl > isakmpd[8122]: sa_release: SA 0x7e39ca00 had 4 references Sep 9 10:37:19 > q-dsl isakmpd[8122]: sa_reference: SA 0x7e39ca00 now has 4 references Sep > 9 10:37:19 q-dsl isakmpd[8122]: message_recv: phase 1 message after > ISAKMP SA is ready Sep 9 10:37:19 q-dsl isakmpd[8122]: message_free: > freeing 0x7e39f900 Sep 9 10:37:19 q-dsl isakmpd[8122]: sa_release: SA > 0x7e39ca00 had 4 references Sep 9 10:37:51 q-dsl isakmpd[8122]: sa_find: no > SA matched query Sep 9 10:37:51 q-dsl isakmpd[8122]: > exchange_lookup_by_name: from-129.143.250.128/25-to-192.168.199.0/24 > == from-129.143.250.128/25-to-192.168.199.0/24 && 2 == 2? > Sep 9 10:37:51 q-dsl isakmpd[8122]: exchange_establish: from- > 129.143.250.128/25-to-192.168.199.0/24 exchange already exists as > 0x7e39c600 > > > > And here is dmesg.boot: > > OpenBSD 5.4 (GENERIC) #30: Sat Jul 20 22:58:41 MDT 2013 > dera...@i386.openbsd.org:/usr/src/sys/arch/i386/compile/GENERIC > cpu0: Geode(TM) Integrated Processor by AMD PCS ("AuthenticAMD" 586- > class) 500 MHz > cpu0: > FPU,DE,PSE,TSC,MSR,CX8,SEP,PGE,CMOV,CFLUSH,MMX,MMXX,3DNOW2,3D > NOW > real mem = 536408064 (511MB) > avail mem = 516194304 (492MB) > mainbus0 at root > bios0 at mainbus0: AT/286+ BIOS, date 20/71/05, BIOS32 rev. 0 @ 0xfac40 > pcibios0 at bios0: rev 2.0 @ 0xf0000/0x10000 > pcibios0: pcibios_get_intr_routing - function not supported > pcibios0: PCI IRQ Routing information unavailable. > pcibios0: PCI bus #0 is the last bus > bios0: ROM list: 0xc8000/0xa800 > cpu0 at mainbus0: (uniprocessor) > amdmsr0 at mainbus0 > pci0 at mainbus0 bus 0: configuration mode 1 (bios) > 0:20:0: io address conflict 0x6100/0x100 > 0:20:0: io address conflict 0x6200/0x200 > pchb0 at pci0 dev 1 function 0 "AMD Geode LX" rev 0x31 > glxsb0 at pci0 dev 1 function 2 "AMD Geode LX Crypto" rev 0x00: RNG AES > vr0 at pci0 dev 6 function 0 "VIA VT6105M RhineIII" rev 0x96: irq 11, address > 00:00:24:c9:59:24 > ukphy0 at vr0 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI > 0x004063, model 0x0034 > vr1 at pci0 dev 7 function 0 "VIA VT6105M RhineIII" rev 0x96: irq 5, address > 00:00:24:c9:59:25 > ukphy1 at vr1 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI > 0x004063, model 0x0034 > vr2 at pci0 dev 8 function 0 "VIA VT6105M RhineIII" rev 0x96: irq 9, address > 00:00:24:c9:59:26 > ukphy2 at vr2 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI > 0x004063, model 0x0034 > vr3 at pci0 dev 9 function 0 "VIA VT6105M RhineIII" rev 0x96: irq 12, address > 00:00:24:c9:59:27 > ukphy3 at vr3 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI > 0x004063, model 0x0034 > glxpcib0 at pci0 dev 20 function 0 "AMD CS5536 ISA" rev 0x03: rev 3, 32-bit > 3579545Hz timer, watchdog, gpio, i2c > gpio0 at glxpcib0: 32 pins > iic0 at glxpcib0 > pciide0 at pci0 dev 20 function 2 "AMD CS5536 IDE" rev 0x01: DMA, channel 0 > wired to compatibility, channel 1 wired to compatibility > wd0 at pciide0 channel 0 drive 0: <SanDisk SDCFH2-004G> > wd0: 4-sector PIO, LBA, 3919MB, 8027712 sectors > wd0(pciide0:0:0): using PIO mode 4, DMA mode 2 > pciide0: channel 1 ignored (disabled) > ohci0 at pci0 dev 21 function 0 "AMD CS5536 USB" rev 0x02: irq 15, version > 1.0, legacy support > ehci0 at pci0 dev 21 function 1 "AMD CS5536 USB" rev 0x02: irq 15 > usb0 at ehci0: USB revision 2.0 > uhub0 at usb0 "AMD EHCI root hub" rev 2.00/1.00 addr 1 > isa0 at glxpcib0 > isadma0 at isa0 > com0 at isa0 port 0x3f8/8 irq 4: ns16550a, 16 byte fifo > com0: console > com1 at isa0 port 0x2f8/8 irq 3: ns16550a, 16 byte fifo > pckbc0 at isa0 port 0x60/5 > pckbd0 at pckbc0 (kbd slot) > pckbc0: using irq 1 for kbd slot > wskbd0 at pckbd0: console keyboard > pcppi0 at isa0 port 0x61 > spkr0 at pcppi0 > nsclpcsio0 at isa0 port 0x2e/2: NSC PC87366 rev 10: GPIO VLM TMS > gpio1 at nsclpcsio0: 29 pins > npx0 at isa0 port 0xf0/16: reported by CPUID; using exception 16 > usb1 at ohci0: USB revision 1.0 > uhub1 at usb1 "AMD OHCI root hub" rev 1.00/1.00 addr 1 > mtrr: K6-family MTRR support (2 registers) > vscsi0 at root > scsibus0 at vscsi0: 256 targets > softraid0 at root > scsibus1 at softraid0: 256 targets > root on wd0a (5acd6c91162ffb03.a) swap on wd0b dump on wd0b > > > Please also note the message in the debug output: > > Sep 9 10:36:51 q-dsl isakmpd[8122]: nat_t_exchange_check_nat_d: NAT > detected, we're behind it > > > Which seems either wrong or at least misleading: we are directly connect to > the internet, it is the other side that is behind a NAT. > > > What also strikes me is that the 'Next Proposal' fields at byte offset 005c > and 0068 are zero instead of 02 (PROPOSAL) and 03 (TRANSFORM) as the > figure ant page of rfc 2408 suggests. > > Please let me know how you read this matter. > > Thanks > > Christoph Leser