>Synopsis: <synopsis of the problem (one line)>
>Category: supected bug in ipsec/isakmpd implementation of NAT-rfc3947
>Environment:
System : OpenBSD 5.4
Details : OpenBSD 5.4 (GENERIC) #30: Sat Jul 20 22:58:41 MDT 2013
[email protected]:/usr/src/sys/arch/i386/compile/GENERIC
Architecture: OpenBSD.i386
Machine : i386
>Description:
The system is unable to establish an ipsec tunnel to a Sonic-Wall
device behind a remote NAT gateway when the tunnel is configured with ipsecctl.
This is my setup:
openBSD has direct access to the internet with IP address 217.110.66.79
SonicWall is behind IP address 217.86.184.8
/etc/ipsec.conf
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 seems special in this setup is that the Sonic Wall only advertises
only support for NAT-T, RFC 3947, no support for the ietf-draft NAT-Tversions.
The exchange fails after openBSD sends its phase 2 proposal. The remote
side complains about 'invalid encapsulation mode'.
I include a tcpdump of the failing exchange ( including a hexdump for
the last message ), an excerpt from /var/log/daemon and the dmesg file.
>How-To-Repeat:
Set up a tunnel as shown above
>Fix:
Crafting an isakmpd.conf entry for this tunnel with a phase 2 transform
with an explicit ENCAPSULATION_MODE=UDP_ENCAP_TUNNEL will work.
Here is the tcpdump showing the problem ( please watch out for the 80040001 in
the tcpdump of the last packet: attribute 4 is encapulation_mode, value 1 is
'tunnel', should be 80040003, i.e. value should be 'udp_encap_tunnel=3
according to rfc3947 )
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 [email protected]
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 generated with isakmpd -K -L -D0=29 -D1=49 -D2=10 -D3=30 -D6=99
-D7=99 -D8=99 -D9=30 -D10=20
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...
And here is dmesg.boot:
OpenBSD 5.4 (GENERIC) #30: Sat Jul 20 22:58:41 MDT 2013
[email protected]:/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,3DNOW
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.
