Hello everyone,
I am experiencing a problem here which - despite of deep analysis,
RTFMing and trying to understand some portions of isakmpd code -
seems impossible to solve for me. I am trying to establish a simple
IPsec tunnel between two computers - a Soekris net5501 running
OpenBSD 4.3 and a MacBook running OS X 10.4.11 with IPsecuritas. I
already learned a huge amount about IPsec and its basics thanks to
the excellent documentation, but it seems this is really beyond my
comprehension (as of now, at least) - thus I kindly ask for your help.
First off, the OS X side worked and still works perfectly in other
configurations (establishing tunnels to a slightly different OpenBSD
4.3 machine). I'll try to describe what happens:
On the IPsecuritas side the tunnel is established perfectly. The
connection manager shows a green LED. If I try to ping the OpenBSD
machine, ESP packets are sent over the wire/air (tried both) and
arrive at the interface of the OpenBSD machine. So far so good.
On the OpenBSD machine, things look like this (isakmpd debuglevel ALL
is set to 60). Phases 1 and 2 seem to be established, but when it
comes to pass the information about the established tunnel to the
kernel, an error occurs:
pf_key_v2_write: writev (8, 0x88a3f680, 16) failed: Invalid argument
"ipsecctl -sa" shows neither flows, nor SAD entries.
"ipsecctl -m" during tunnel establishment shows nothing. Although,
when I order IPsecuritas to tear down the tunnel, it yields:
sadb_delflow: satype esp vers 2 len 16 seq 9 pid 16638
src_mask: 0.0.0.0
dst_mask: 255.255.255.255
protocol: proto 0 flags 0
flow_type: type require direction out
src_flow: 0.0.0.0
dst_flow: 10.2.0.4
sadb_delflow: satype esp vers 2 len 2 seq 9 pid 16638
errno 3: No such process
sadb_delete: satype esp vers 2 len 10 seq 10 pid 16638
sa: spi 0x091f6215 auth none enc none
state larval replay 0 flags 0
address_src: 10.2.0.1
address_dst: 10.2.0.4
sadb_delete: satype esp vers 2 len 2 seq 10 pid 16638
errno 3: No such process
sadb_delflow: satype esp vers 2 len 16 seq 11 pid 16638
src_mask: 255.255.255.255
dst_mask: 0.0.0.0
protocol: proto 0 flags 0
flow_type: type use direction in
src_flow: 10.2.0.4
dst_flow: 0.0.0.0
sadb_delflow: satype esp vers 2 len 2 seq 11 pid 16638
errno 3: No such process
sadb_delete: satype esp vers 2 len 10 seq 12 pid 16638
sa: spi 0x06e0f06e auth none enc none
state larval replay 0 flags 0
address_src: 10.2.0.4
address_dst: 10.2.0.1
sadb_delete: satype esp vers 2 len 2 seq 12 pid 16638
errno 3: No such process
sadb_getspi: satype esp vers 2 len 10 seq 13 pid 16638
address_src: 10.2.0.4
address_dst: 10.2.0.1
spirange: min 0x00000100 max 0xffffffff
sadb_getspi: satype esp vers 2 len 10 seq 13 pid 16638
sa: spi 0x9f37b12e auth none enc none
state mature replay 0 flags 0
address_src: 10.2.0.4
address_dst: 10.2.0.1
sadb_add: satype esp vers 2 len 49 seq 14 pid 16638
sa: spi 0x075f3e1e auth hmac-sha1 enc aes
state mature replay 16 flags 4
lifetime_hard: alloc 0 bytes 0 add 1800 first 0
lifetime_soft: alloc 0 bytes 0 add 1620 first 0
address_src: 10.2.0.1
address_dst: 10.2.0.4
key_auth: bits 160: b3dd92e5008ba542a1444ce948b1bbbe644d4c8f
key_encrypt: bits 256:
c5fc5aae3c2d3be536b2b688192fd4340d06930b6647cc0cf60a7c5a018b305d
identity_src: type prefix id 0: 10.2.0.1/32
identity_dst: type prefix id 0: 10.2.0.4/32
src_mask: 0.0.0.0
dst_mask: 255.255.255.255
protocol: proto 0 flags 0
flow_type: type unknown direction out
src_flow: 0.0.0.0
dst_flow: 10.2.0.4
"route show" (encap section) shows nothing
"route monitor" during tunnel establishment also yields no
information, it seems that nothing is getting touched at all.
I've googled already, and found only references to an old bug in 2.x
times which yielded the same error. No occurrence of this error in
relation to further OpenBSD releases. My version is a fresh over-the-
net installation of 4.3. On a different box (similar to the Soekris)
I experienced no such problems. Kernel and userland are perfectly
synchronized, no tweaking involved.
The error occurs both when using X.509 certificates and pre-shared
keys (PSK in this particular case below).
Sep 19 00:22:07 nimrod isakmpd[16638]: virtual_clone: old 0x81462680
new 0x81462c80 (main is 0x81462cc0)
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
28 payload SA
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
84 payload VENDOR
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
108 payload VENDOR
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload SA at 0x88a3f39c of message 0x88a3f300
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_add_event: event
exchange_free_aux(0x7c346000) added before sa_soft_expire
(0x7ed16c00), expiration in 120s
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_setup_p1: 0x7c346000
peer-10.2.0.4 mm-10.2.0.4 policy responder phase 1 doi 1 exchange 2
step 0
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_setup_p1: icookie
67f082dbdfc878a9 rcookie b859951ea7ae284e
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_setup_p1: msgid 00000000
Sep 19 00:22:07 nimrod isakmpd[16638]: sa_create: sa 0x7c346100 phase
1 added to exchange 0x7c346000 (peer-10.2.0.4)
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
40 payload PROPOSAL
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
48 payload TRANSFORM
Sep 19 00:22:07 nimrod isakmpd[16638]: Transform 1's attributes
Sep 19 00:22:07 nimrod isakmpd[16638]: Attribute LIFE_TYPE value 1
Sep 19 00:22:07 nimrod isakmpd[16638]: Attribute LIFE_DURATION value
1800
Sep 19 00:22:07 nimrod isakmpd[16638]: Attribute ENCRYPTION_ALGORITHM
value 7
Sep 19 00:22:07 nimrod isakmpd[16638]: Attribute KEY_LENGTH value 256
Sep 19 00:22:07 nimrod isakmpd[16638]: Attribute
AUTHENTICATION_METHOD value 1
Sep 19 00:22:07 nimrod isakmpd[16638]: Attribute HASH_ALGORITHM value 2
Sep 19 00:22:07 nimrod isakmpd[16638]: Attribute GROUP_DESCRIPTION
value 2
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload PROPOSAL at 0x88a3f3a8 of message 0x88a3f300
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload TRANSFORM at 0x88a3f3b0 of message 0x88a3f300
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload VENDOR at 0x88a3f3d4 of message 0x88a3f300
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_vendor:
vendor ID seen
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload VENDOR at 0x88a3f3ec of message 0x88a3f300
Sep 19 00:22:07 nimrod isakmpd[16638]: dpd_check_vendor_payload: DPD
capable peer detected
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_responder: phase 1
exchange 2 step 0
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod isakmpd[16638]: message_negotiate_sa:
transform 1 proto 1 proposal 1 ok
Sep 19 00:22:07 nimrod isakmpd[16638]: ike_phase_1_validate_prop:
success
Sep 19 00:22:07 nimrod isakmpd[16638]: message_negotiate_sa: proposal
1 succeeded
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_decode_transform:
transform 1 chosen
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod isakmpd[16638]:
exchange_handle_leftover_payloads: unexpected payload VENDOR
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_run: exchange
0x7c346000 finished step 0, advancing...
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_responder: phase 1
exchange 2 step 1
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_run: exchange
0x7c346000 finished step 1, advancing...
Sep 19 00:22:07 nimrod isakmpd[16638]: transport_send_messages:
message 0x88a3f280 scheduled for retransmission 1 in 7 secs
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_add_event: event
message_send_expire(0x88a3f280) added before exchange_free_aux
(0x7c346000), expiration in 7s
Sep 19 00:22:07 nimrod isakmpd[16638]: virtual_clone: old 0x81462680
new 0x7d740680 (main is 0x7d740700)
Sep 19 00:22:07 nimrod isakmpd[16638]: message_free: freeing 0x88a3f280
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_remove_event: removing
event message_send_expire(0x88a3f280)
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
28 payload KEY_EXCH
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
160 payload NONCE
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload KEY_EXCH at 0x7c34631c of message 0x88a3f400
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload NONCE at 0x7c3463a0 of message 0x88a3f400
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_responder: phase 1
exchange 2 step 2
Sep 19 00:22:07 nimrod isakmpd[16638]: message_free: freeing 0x88a3f300
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_run: exchange
0x7c346000 finished step 2, advancing...
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_responder: phase 1
exchange 2 step 3
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_run: exchange
0x7c346000 finished step 3, advancing...
Sep 19 00:22:07 nimrod isakmpd[16638]: transport_send_messages:
message 0x88a3f280 scheduled for retransmission 1 in 7 secs
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_add_event: event
message_send_expire(0x88a3f280) added before exchange_free_aux
(0x7c346000), expiration in 7s
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod last message repeated 2 times
Sep 19 00:22:07 nimrod isakmpd[16638]: crypto_init: key:
Sep 19 00:22:07 nimrod isakmpd[16638]: ddef3fe1 6d48b6c2 d28ee0f0
c796d52b 840cc96e a21595a1 3f2ebb5d 193d3478
Sep 19 00:22:07 nimrod isakmpd[16638]: crypto_init_iv: initialized IV:
Sep 19 00:22:07 nimrod isakmpd[16638]: 77164812 577951a9 dcacf00c
30183c40
Sep 19 00:22:07 nimrod isakmpd[16638]: virtual_clone: old 0x81462680
new 0x81462cc0 (main is 0x81462d40)
Sep 19 00:22:07 nimrod isakmpd[16638]: message_free: freeing 0x88a3f280
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_remove_event: removing
event message_send_expire(0x88a3f280)
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
28 payload ID
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
40 payload HASH
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload ID at 0x88a3f81c of message 0x88a3f700
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_validate_id_information:
proto 17 port 500 type 1
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_validate_id_information:
IPv4:
Sep 19 00:22:07 nimrod isakmpd[16638]: 0a020004
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload HASH at 0x88a3f828 of message 0x88a3f700
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_responder: phase 1
exchange 2 step 4
Sep 19 00:22:07 nimrod isakmpd[16638]: ike_phase_1_recv_ID: IPV4_ADDR:
Sep 19 00:22:07 nimrod isakmpd[16638]: 0a020004
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod isakmpd[16638]: message_free: freeing 0x88a3f400
Sep 19 00:22:07 nimrod isakmpd[16638]: crypto_update_iv: updated IV:
Sep 19 00:22:07 nimrod isakmpd[16638]: 2c74cfbc 9ac31920 1ad3313a
0f7e56f6
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_run: exchange
0x7c346000 finished step 4, advancing...
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_responder: phase 1
exchange 2 step 5
Sep 19 00:22:07 nimrod isakmpd[16638]: ike_phase_1_send_ID: IPV4_ADDR:
Sep 19 00:22:07 nimrod isakmpd[16638]: 0a020001
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod isakmpd[16638]: crypto_update_iv: updated IV:
Sep 19 00:22:07 nimrod isakmpd[16638]: 0ad2c723 db5cd746 7c4d7fcc
195d25fe
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_run: exchange
0x7c346000 finished step 5, advancing...
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_finalize: 0x7c346000
peer-10.2.0.4 mm-10.2.0.4 policy responder phase 1 doi 1 exchange 2
step 6
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_finalize: icookie
67f082dbdfc878a9 rcookie b859951ea7ae284e
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_finalize: msgid 00000000
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_finalize: phase 1
done: initiator id 0a020004: 10.2.0.4, responder id 0a020001:
10.2.0.1, src: 10.2.0.1 dst: 10.2.0.4
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_add_event: event
sa_soft_expire(0x7c346100) added last, expiration in 1699s
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_add_event: event
sa_hard_expire(0x7c346100) added last, expiration in 1800s
Sep 19 00:22:07 nimrod isakmpd[16638]: virtual_clone: old 0x81462680
new 0x7d740440 (main is 0x7d740680)
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod isakmpd[16638]: crypto_init_iv: initialized IV:
Sep 19 00:22:07 nimrod isakmpd[16638]: 72fc0f57 9cb7f6cc 82bcb7c1
5449c18d
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
28 payload HASH
Sep 19 00:22:07 nimrod isakmpd[16638]: message_parse_payloads: offset
52 payload NOTIFY
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload HASH at 0x88a3f91c of message 0x88a3f680
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:07 nimrod isakmpd[16638]: message_validate_payloads:
payload NOTIFY at 0x88a3f934 of message 0x88a3f680
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_add_event: event
exchange_free_aux(0x7ed16800) added before sa_soft_expire
(0x7ed16c00), expiration in 120s
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_setup_p2: 0x7ed16800
<unnamed> <no policy> policy responder phase 2 doi 1 exchange 5 step 0
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_setup_p2: icookie
67f082dbdfc878a9 rcookie b859951ea7ae284e
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_setup_p2: msgid
cfc707d1 sa_list
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_responder: phase 2
exchange 5 step 0
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_responder: got NOTIFY of
type <Unknown 24578>
Sep 19 00:22:07 nimrod isakmpd[16638]: ipsec_handle_leftover_payload:
INITIAL-CONTACT made us delete SA 0x7ed16c00
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_remove_event: removing
event sa_hard_expire(0x7ed16c00)
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_remove_event: removing
event sa_soft_expire(0x7ed16c00)
Sep 19 00:22:07 nimrod isakmpd[16638]: sa_release: freeing SA 0x7ed16c00
Sep 19 00:22:07 nimrod isakmpd[16638]: pf_key_v2_flow: src 0.0.0.0
0.0.0.0 dst 10.2.0.4 255.255.255.255 proto 0 sport 0 dport 0
Sep 19 00:22:07 nimrod isakmpd[16638]: pf_key_v2_flow: DELFLOW: No
such process
Sep 19 00:22:07 nimrod isakmpd[16638]: pf_key_v2_delete_spi: removing
configuration IPsec-0.0.0.0/0-0.0.0.0/0
Sep 19 00:22:07 nimrod isakmpd[16638]: pf_key_v2_delete_spi: DELETE:
No such process
Sep 19 00:22:07 nimrod isakmpd[16638]: pf_key_v2_flow: src 10.2.0.4
255.255.255.255 dst 0.0.0.0 0.0.0.0 proto 0 sport 0 dport 0
Sep 19 00:22:07 nimrod isakmpd[16638]: pf_key_v2_flow: DELFLOW: No
such process
Sep 19 00:22:07 nimrod isakmpd[16638]: pf_key_v2_delete_spi: removing
configuration IPsec-0.0.0.0/0-0.0.0.0/0
Sep 19 00:22:07 nimrod isakmpd[16638]: pf_key_v2_delete_spi: DELETE:
No such process
Sep 19 00:22:07 nimrod isakmpd[16638]: crypto_update_iv: updated IV:
Sep 19 00:22:07 nimrod isakmpd[16638]: de704980 aea8fa2d c215d01f
c7609423
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_finalize: 0x7ed16800
<unnamed> <no policy> policy responder phase 2 doi 1 exchange 5 step 0
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_finalize: icookie
67f082dbdfc878a9 rcookie b859951ea7ae284e
Sep 19 00:22:07 nimrod isakmpd[16638]: exchange_finalize: msgid
cfc707d1 sa_list
Sep 19 00:22:07 nimrod isakmpd[16638]: timer_remove_event: removing
event exchange_free_aux(0x7ed16800)
Sep 19 00:22:07 nimrod isakmpd[16638]: message_free: freeing 0x88a3f680
Sep 19 00:22:08 nimrod isakmpd[16638]: virtual_clone: old 0x81462680
new 0x81462f00 (main is 0x81462f40)
Sep 19 00:22:08 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:08 nimrod isakmpd[16638]: crypto_init_iv: initialized IV:
Sep 19 00:22:08 nimrod isakmpd[16638]: 335c9201 89d5dab4 fe6e201b
d3121515
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
28 payload HASH
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
52 payload SA
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
108 payload NONCE
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
128 payload KEY_EXCH
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
260 payload ID
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
272 payload ID
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload SA at 0x85239a34 of message 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: timer_add_event: event
exchange_free_aux(0x7ed16900) added before sa_soft_expire
(0x7c346100), expiration in 120s
Sep 19 00:22:08 nimrod isakmpd[16638]: exchange_setup_p2: 0x7ed16900
<unnamed> <no policy> policy responder phase 2 doi 1 exchange 32 step 0
Sep 19 00:22:08 nimrod isakmpd[16638]: exchange_setup_p2: icookie
67f082dbdfc878a9 rcookie b859951ea7ae284e
Sep 19 00:22:08 nimrod isakmpd[16638]: exchange_setup_p2: msgid
cf25fd37 sa_list
Sep 19 00:22:08 nimrod isakmpd[16638]: sa_create: sa 0x7ed16a00 phase
2 added to exchange 0x7ed16900 (<unnamed>)
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
64 payload PROPOSAL
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
76 payload TRANSFORM
Sep 19 00:22:08 nimrod isakmpd[16638]: Transform 1's attributes
Sep 19 00:22:08 nimrod isakmpd[16638]: Attribute SA_LIFE_TYPE value 1
Sep 19 00:22:08 nimrod isakmpd[16638]: Attribute SA_LIFE_DURATION
value 1800
Sep 19 00:22:08 nimrod isakmpd[16638]: Attribute ENCAPSULATION_MODE
value 1
Sep 19 00:22:08 nimrod isakmpd[16638]: Attribute KEY_LENGTH value 256
Sep 19 00:22:08 nimrod isakmpd[16638]: Attribute
AUTHENTICATION_ALGORITHM value 2
Sep 19 00:22:08 nimrod isakmpd[16638]: Attribute GROUP_DESCRIPTION
value 2
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload PROPOSAL at 0x85239a40 of message 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload TRANSFORM at 0x85239a4c of message 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload KEY_EXCH at 0x85239a80 of message 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload ID at 0x85239b04 of message 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: ipsec_validate_id_information:
proto 0 port 0 type 1
Sep 19 00:22:08 nimrod isakmpd[16638]: ipsec_validate_id_information:
IPv4:
Sep 19 00:22:08 nimrod isakmpd[16638]: 0a020004
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload ID at 0x85239b10 of message 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: ipsec_validate_id_information:
proto 0 port 0 type 4
Sep 19 00:22:08 nimrod isakmpd[16638]: ipsec_validate_id_information:
IPv4 network/netmask:
Sep 19 00:22:08 nimrod isakmpd[16638]: 00000000 00000000
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload HASH at 0x85239a1c of message 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload NONCE at 0x85239a6c of message 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: ipsec_responder: phase 2
exchange 32 step 0
Sep 19 00:22:08 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:08 nimrod isakmpd[16638]: message_negotiate_sa:
transform 1 proto 3 proposal 1 ok
Sep 19 00:22:08 nimrod isakmpd[16638]: message_negotiate_sa: proposal
1 succeeded
Sep 19 00:22:08 nimrod isakmpd[16638]: ipsec_decode_transform:
transform 1 chosen
Sep 19 00:22:08 nimrod isakmpd[16638]:
connection_passive_lookup_by_ids: returned
"IPsec-0.0.0.0/0-0.0.0.0/0" only matched local id
Sep 19 00:22:08 nimrod isakmpd[16638]: crypto_update_iv: updated IV:
Sep 19 00:22:08 nimrod isakmpd[16638]: a7d05731 875bc928 c4cdca20
92ee0867
Sep 19 00:22:08 nimrod isakmpd[16638]: exchange_run: exchange
0x7ed16900 finished step 0, advancing...
Sep 19 00:22:08 nimrod isakmpd[16638]: ipsec_responder: phase 2
exchange 32 step 1
Sep 19 00:22:08 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:08 nimrod isakmpd[16638]: pf_key_v2_get_spi: spi:
Sep 19 00:22:08 nimrod isakmpd[16638]: 9f37b12e
Sep 19 00:22:08 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:08 nimrod isakmpd[16638]: crypto_update_iv: updated IV:
Sep 19 00:22:08 nimrod isakmpd[16638]: bb30d943 bff0e4a7 301d8e8a
3401e87e
Sep 19 00:22:08 nimrod isakmpd[16638]: exchange_run: exchange
0x7ed16900 finished step 1, advancing...
Sep 19 00:22:08 nimrod isakmpd[16638]: transport_send_messages:
message 0x88a3f900 scheduled for retransmission 1 in 7 secs
Sep 19 00:22:08 nimrod isakmpd[16638]: timer_add_event: event
message_send_expire(0x88a3f900) added before exchange_free_aux
(0x7c346000), expiration in 7s
Sep 19 00:22:08 nimrod isakmpd[16638]: virtual_clone: old 0x81462680
new 0x7d740680 (main is 0x7d740700)
Sep 19 00:22:08 nimrod isakmpd[16638]: message_free: freeing 0x88a3f900
Sep 19 00:22:08 nimrod isakmpd[16638]: timer_remove_event: removing
event message_send_expire(0x88a3f900)
Sep 19 00:22:08 nimrod isakmpd[16638]: message_parse_payloads: offset
28 payload HASH
Sep 19 00:22:08 nimrod isakmpd[16638]: message_validate_payloads:
payload HASH at 0x7d74079c of message 0x88a3fa00
Sep 19 00:22:08 nimrod isakmpd[16638]: ipsec_responder: phase 2
exchange 32 step 2
Sep 19 00:22:08 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:08 nimrod last message repeated 2 times
Sep 19 00:22:08 nimrod isakmpd[16638]: message_free: freeing 0x88a3f400
Sep 19 00:22:08 nimrod isakmpd[16638]: crypto_update_iv: updated IV:
Sep 19 00:22:08 nimrod isakmpd[16638]: 2160a119 0b4df9a1 cfdd01aa
1748fced
Sep 19 00:22:08 nimrod isakmpd[16638]: exchange_finalize: 0x7ed16900
IPsec-0.0.0.0/0-0.0.0.0/0 <no policy> policy responder phase 2 doi 1
exchange 32 step 2
Sep 19 00:22:08 nimrod isakmpd[16638]: exchange_finalize: icookie
67f082dbdfc878a9 rcookie b859951ea7ae284e
Sep 19 00:22:08 nimrod isakmpd[16638]: exchange_finalize: msgid
cf25fd37 sa_list 0x7ed16a00
Sep 19 00:22:08 nimrod isakmpd[16638]: pf_key_v2_convert_id: IPv4
address 10.2.0.4/32
Sep 19 00:22:08 nimrod isakmpd[16638]: pf_key_v2_convert_id: IPv4
address 10.2.0.1/32
Sep 19 00:22:08 nimrod isakmpd[16638]: pf_key_v2_set_spi: satype 2
dst 10.2.0.4 SPI 0x75f3e1e
Sep 19 00:22:08 nimrod isakmpd[16638]: timer_add_event: event
sa_soft_expire(0x7ed16a00) added before sa_soft_expire(0x7c346100),
expiration in 1549s
Sep 19 00:22:08 nimrod isakmpd[16638]: timer_add_event: event
sa_hard_expire(0x7ed16a00) added last, expiration in 1800s
Sep 19 00:22:08 nimrod isakmpd[16638]: pf_key_v2_write: writev (8,
0x88a3f880, 16) failed: Invalid argument
Sep 19 00:22:08 nimrod isakmpd[16638]: timer_remove_event: removing
event exchange_free_aux(0x7ed16900)
Sep 19 00:22:08 nimrod isakmpd[16638]: message_free: freeing 0x88a3fa00
Sep 19 00:22:12 nimrod isakmpd[16638]: virtual_clone: old 0x81462680
new 0x7d740700 (main is 0x7d740740)
Sep 19 00:22:12 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:12 nimrod isakmpd[16638]: crypto_init_iv: initialized IV:
Sep 19 00:22:12 nimrod isakmpd[16638]: c43f6855 e196269d b0a2ea47
ef3af516
Sep 19 00:22:12 nimrod isakmpd[16638]: message_parse_payloads: offset
28 payload HASH
Sep 19 00:22:12 nimrod isakmpd[16638]: message_parse_payloads: offset
52 payload DELETE
Sep 19 00:22:12 nimrod isakmpd[16638]: message_validate_payloads:
payload HASH at 0x88a3f51c of message 0x88a3f400
Sep 19 00:22:12 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:12 nimrod isakmpd[16638]: hash_get: requested algorithm 1
Sep 19 00:22:12 nimrod isakmpd[16638]: message_validate_payloads:
payload DELETE at 0x88a3f534 of message 0x88a3f400
Sep 19 00:22:12 nimrod isakmpd[16638]: timer_add_event: event
exchange_free_aux(0x7ed16800) added before sa_soft_expire
(0x7ed16a00), expiration in 120s
Sep 19 00:22:12 nimrod isakmpd[16638]: exchange_setup_p2: 0x7ed16800
<unnamed> <no policy> policy responder phase 2 doi 1 exchange 5 step 0
Sep 19 00:22:12 nimrod isakmpd[16638]: exchange_setup_p2: icookie
67f082dbdfc878a9 rcookie b859951ea7ae284e
Sep 19 00:22:12 nimrod isakmpd[16638]: exchange_setup_p2: msgid
c7b9837e sa_list
Sep 19 00:22:12 nimrod isakmpd[16638]: ipsec_responder: phase 2
exchange 5 step 0
Sep 19 00:22:12 nimrod isakmpd[16638]: ipsec_delete_spi_list: DELETE
made us delete SA 0x7c346100 (6 references) for proto 1
Sep 19 00:22:12 nimrod isakmpd[16638]: timer_remove_event: removing
event sa_hard_expire(0x7c346100)
Sep 19 00:22:12 nimrod isakmpd[16638]: timer_remove_event: removing
event sa_soft_expire(0x7c346100)
Sep 19 00:22:12 nimrod isakmpd[16638]: crypto_update_iv: updated IV:
Sep 19 00:22:12 nimrod isakmpd[16638]: f2913fba 16d29e14 0c3c9568
01e167ec
Sep 19 00:22:12 nimrod isakmpd[16638]: exchange_finalize: 0x7ed16800
<unnamed> <no policy> policy responder phase 2 doi 1 exchange 5 step 0
Sep 19 00:22:12 nimrod isakmpd[16638]: exchange_finalize: icookie
67f082dbdfc878a9 rcookie b859951ea7ae284e
Sep 19 00:22:12 nimrod isakmpd[16638]: exchange_finalize: msgid
c7b9837e sa_list
Sep 19 00:22:12 nimrod isakmpd[16638]: timer_remove_event: removing
event exchange_free_aux(0x7ed16800)
Sep 19 00:22:12 nimrod isakmpd[16638]: message_free: freeing 0x88a3f400
/etc/ipsec.conf:
ike passive esp from any to any peer 10.2.0.4 main auth hmac-sha1 enc
aes-256 group modp1024 quick auth hmac-sha1 enc aes-256 psk MY_PSK_KEY
Interface configurations:
/etc/hostname.vr0 (local wired network):
inet 10.2.0.1 255.255.255.0 NONE
/etc/hostname.ral0
inet 10.2.1.1 255.255.255.0 NONE media autoselect mediaopt hostap
mode 11a nwid "myssid" chan 112
-powersave
up
/etc/sysctl.conf: only net.inet.ip.forwarding set to 1, the rest is
untouched
dmesg:
OpenBSD 4.3 (GENERIC) #698: Wed Mar 12 11:07:05 MDT 2008
[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
real mem = 536440832 (511MB)
avail mem = 510664704 (487MB)
mainbus0 at root
bios0 at mainbus0: AT/286+ BIOS, date 20/70/03, 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
pci0 at mainbus0 bus 0: configuration mode 1 (bios)
pchb0 at pci0 dev 1 function 0 "AMD Geode LX" rev 0x33
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:ca:da:c4
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:ca:da:c5
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:ca:da:c6
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:ca:da:c7
ukphy3 at vr3 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI
0x004063, model 0x0034
ral0 at pci0 dev 17 function 0 "Ralink RT2561S" rev 0x00: irq 15,
address 00:12:0e:61:49:1c
ral0: MAC/BBP RT2561C, RF RT5225
glxpcib0 at pci0 dev 20 function 0 "AMD CS5536 ISA" rev 0x03: rev 0,
32-bit 3579545Hz timer, watchdog, gpio
gpio0 at glxpcib0: 32 pins
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: <TRANSCEND>
wd0: 1-sector PIO, LBA, 488MB, 1000944 sectors
wd0(pciide0:0:0): using PIO mode 4
pciide0: channel 1 ignored (disabled)
ohci0 at pci0 dev 21 function 0 "AMD CS5536 USB" rev 0x02: irq 7,
version 1.0, legacy support
ehci0 at pci0 dev 21 function 1 "AMD CS5536 USB" rev 0x02: irq 7
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
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
midi0 at pcppi0: <PC speaker>
spkr0 at pcppi0
nsclpcsio0 at isa0 port 0x2e/2: NSC PC87366 rev 9: GPIO VLM TMS
gpio1 at nsclpcsio0: 29 pins
npx0 at isa0 port 0xf0/16: reported by CPUID; using exception 16
pccom0 at isa0 port 0x3f8/8 irq 4: ns16550a, 16 byte fifo
pccom0: console
pccom1 at isa0 port 0x2f8/8 irq 3: ns16550a, 16 byte fifo
usb1 at ohci0: USB revision 1.0
uhub1 at usb1 "AMD OHCI root hub" rev 1.00/1.00 addr 1
biomask 65c5 netmask ffe5 ttymask ffe7
mtrr: K6-family MTRR support (2 registers)
umass0 at uhub0 port 1 configuration 1 interface 0 "vendor 0x0930 USB
Flash Memory" rev 2.00/1.00 addr 2
umass0: using SCSI over Bulk-Only
scsibus0 at umass0: 2 targets
sd0 at scsibus0 targ 1 lun 0: <, USB Flash Memory, 5.00> SCSI0 0/
direct removable
sd0: 983MB, 125 cyl, 255 head, 63 sec, 512 bytes/sec, 2013184 sec total
softraid0 at root
root on wd0a swap on wd0b dump on wd0b
Any help or idea would be appreciated. Just in case, thank you for
your time!
Lukas
