Hans-Joerg Hoexer wrote:
On Thu, Aug 02, 2007 at 10:23:59PM +0200, Sven Ulland wrote:
I'm very (that's putting it mildly) interested in the issues with 4.0
that you mention. Would you be able to shed some more light on which
issues they were, or point me to references? It would be most
interesting.
I'm not sure, but I think there was an issued caused by that [1] commit
which we backed out some time later [2]. This means it should be fixed in
4.0, however, it is obviously not. I'll try to reproduce this.
[1]
http://www.openbsd.org/cgi-bin/cvsweb/src/sbin//isakmpd/sa.c?rev=1.104&content-type=text/x-cvsweb-markup
[2]
http://www.openbsd.org/cgi-bin/cvsweb/src/sbin//isakmpd/sa.c?rev=1.109&content-type=text/x-cvsweb-markup
Thanks. Yes, seems to be fixed in 4.0.
I have enabled isakmpd clear-text packet capture, and I can see that our end
tries to establish a new phase 1 tunnel exactly every 30 seconds. The tunnel is
established correctly, with key exchange and all.
Below I have the isakmpd packet exchange [1] and the /var/log/daemon
output for that packet exchange with debug levels all set to 99 [2]. I'm not
sure if it's any help, but I included it just in case. The output is for
a single phase 1 connection establishment, as shown by the cookies.
[1: isakmpd clear-text packet capture for one tunnel-establishment]
12:49:56.952681 129.240.64.2.500 > 213.98.7.53.500: [udp sum ok] isakmp v1.0
exchange ID_PROT
cookie: 1aa459c4ff9d83dc->0000000000000000 msgid: 00000000 len: 180
payload: SA len: 52 DOI: 1(IPSEC) situation: IDENTITY_ONLY
payload: PROPOSAL len: 40 proposal: 1 proto: ISAKMP spisz: 0 xforms: 1
payload: TRANSFORM len: 32
transform: 0 ID: ISAKMP
attribute ENCRYPTION_ALGORITHM = 3DES_CBC
attribute HASH_ALGORITHM = SHA
attribute AUTHENTICATION_METHOD = PRE_SHARED
attribute GROUP_DESCRIPTION = MODP_1024
attribute LIFE_TYPE = SECONDS
attribute LIFE_DURATION = 28800
payload: VENDOR len: 20 (supports OpenBSD-4.0)
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 208)
12:49:57.617188 213.98.7.53.500 > 129.240.64.2.500: [udp sum ok] isakmp v1.0
exchange ID_PROT
cookie: 1aa459c4ff9d83dc->dd04fc2fbc38c9eb msgid: 00000000 len: 100
payload: SA len: 52 DOI: 1(IPSEC) situation: IDENTITY_ONLY
payload: PROPOSAL len: 40 proposal: 1 proto: ISAKMP spisz: 0 xforms: 1
payload: TRANSFORM len: 32
transform: 1 ID: ISAKMP
attribute ENCRYPTION_ALGORITHM = 3DES_CBC
attribute HASH_ALGORITHM = SHA
attribute GROUP_DESCRIPTION = MODP_1024
attribute AUTHENTICATION_METHOD = PRE_SHARED
attribute LIFE_TYPE = SECONDS
attribute LIFE_DURATION = 28800
payload: VENDOR len: 20 (supports v3 NAT-T,
draft-ietf-ipsec-nat-t-ike-03) [ttl 0] (id 1, len 128)
12:49:57.629442 129.240.64.2.500 > 213.98.7.53.500: [udp sum ok] isakmp v1.0
exchange ID_PROT
cookie: 1aa459c4ff9d83dc->dd04fc2fbc38c9eb msgid: 00000000 len: 228
payload: KEY_EXCH len: 132
payload: NONCE len: 20
payload: NAT-D-DRAFT len: 24
payload: NAT-D-DRAFT len: 24 [ttl 0] (id 1, len 256)
12:49:59.131134 213.98.7.53.500 > 129.240.64.2.500: [udp sum ok] isakmp v1.0
exchange ID_PROT
cookie: 1aa459c4ff9d83dc->dd04fc2fbc38c9eb msgid: 00000000 len: 304
payload: KEY_EXCH len: 132
payload: NONCE len: 24
payload: VENDOR len: 20
payload: VENDOR len: 20 (supports DPD v1.0)
payload: VENDOR len: 20
payload: VENDOR len: 12 (supports draft-ietf-ipsra-isakmp-xauth-06.txt)
payload: NAT-D-DRAFT len: 24
payload: NAT-D-DRAFT len: 24 [ttl 0] (id 1, len 332)
12:49:59.176547 129.240.64.2.500 > 213.98.7.53.500: [udp sum ok] isakmp v1.0
exchange ID_PROT
cookie: 1aa459c4ff9d83dc->dd04fc2fbc38c9eb msgid: 00000000 len: 64
payload: ID len: 12 type: IPV4_ADDR = 129.240.64.2
payload: HASH len: 24 [ttl 0] (id 1, len 92)
12:50:00.906697 213.98.7.53.500 > 129.240.64.2.500: [udp sum ok] isakmp v1.0
exchange ID_PROT
cookie: 1aa459c4ff9d83dc->dd04fc2fbc38c9eb msgid: 00000000 len: 68
payload: ID len: 12 proto: 17 port: 500 type: IPV4_ADDR = 213.98.7.53
payload: HASH len: 24 [ttl 0] (id 1, len 96)
[end of isakmpd packet capture]
[2: /var/log/daemon excerpt with full debugging for all classes]
[lots of transport_release messages]
12:49:56 transport_release: transport 0x47531a00 had 2 references
12:49:56 transport_release: transport 0x47b91180 had 3 references
12:49:56 transport_release: transport 0x47b91180 had 2 references
12:49:56 timer_handle_expirations: event connection_checker(0x4c111260)
12:49:56 conf_get_str: [General]:check-interval->30
12:49:56 timer_add_event: event connection_checker(0x4c111260) added before
sa_soft_expire(0x48f6ce00), expiration in 30s
12:49:56 sa_find: no SA matched query
12:49:56 pf_key_v2_connection_check: SA for WANLINK missing
12:49:56 conf_get_str: [WANLINK]:Phase->1
12:49:56 exchange_lookup_by_name: WANLINK == UIO-EXTNET9 && 1 == 2?
12:49:56 exchange_lookup_by_name: WANLINK == UIO-EXTNET15 && 1 == 2?
12:49:56 exchange_lookup_by_name: WANLINK == UIO-EXTNET21 && 1 == 2?
12:49:56 exchange_lookup_by_name: WANLINK == UIO-EXTNET19 && 1 == 2?
12:49:56 exchange_lookup_by_name: WANLINK == UIO-EXTNET3 && 1 == 2?
12:49:56 exchange_lookup_by_name: WANLINK == UIO-EXTNET22 && 1 == 2?
12:49:56 conf_get_str: [WANLINK]:Transport->udp
12:49:56 conf_get_str: configuration value not found [WANLINK]:Port
12:49:56 conf_get_str: [WANLINK]:Address->213.98.7.53
12:49:56 conf_get_str: [WANLINK]:Local-address->129.240.64.2
12:49:56 transport_setup: added 0x4777d980 to transport list
12:49:56 conf_get_str: configuration value not found [WANLINK]:Port
12:49:56 conf_get_str: [WANLINK]:Address->213.98.7.53
12:49:56 conf_get_str: [WANLINK]:Local-address->129.240.64.2
12:49:56 transport_setup: added 0x476a4900 to transport list
12:49:56 transport_setup: virtual transport 0x476a4a00
12:49:56 conf_get_str: [WANLINK]:Configuration->Default-main-mode
12:49:56 conf_get_str: [Default-main-mode]:DOI->IPSEC
12:49:56 conf_get_str: [Default-main-mode]:EXCHANGE_TYPE->ID_PROT
12:49:56 conf_get_str: [General]:Exchange-max-time->120
12:49:56 timer_add_event: event exchange_free_aux(0x48a5ce00) added before
sa_hard_expire(0x487d3e00), expiration in 120s
12:49:56 conf_get_str: [WANLINK]:Configuration->Default-main-mode
12:49:56 conf_get_str: configuration value not found [WANLINK]:Flags
12:49:56 hash_get: requested algorithm 1
12:49:56 exchange_establish_p1: 0x48a5ce00 WANLINK Default-main-mode policy
initiator phase 1 doi 1 exchange 2 step 0
12:49:56 exchange_establish_p1: icookie 1aa459c4ff9d83dc rcookie
0000000000000000
12:49:56 exchange_establish_p1: msgid 00000000
12:49:56 transport_reference: transport 0x476a4a00 now has 1 references
12:49:56 message_alloc: allocated 0x4fb44e00
12:49:56 sa_reference: SA 0x4acb7800 now has 1 references
12:49:56 sa_enter: SA 0x4acb7800 added to SA list
12:49:56 sa_reference: SA 0x4acb7800 now has 2 references
12:49:56 sa_create: sa 0x4acb7800 phase 1 added to exchange 0x48a5ce00 (WANLINK)
12:49:56 sa_reference: SA 0x4acb7800 now has 3 references
12:49:56 conf_get_str: [Default-main-mode]:Transforms->3DES-SHA
12:49:56 conf_get_str: [3DES-SHA]:ENCRYPTION_ALGORITHM->3DES_CBC
12:49:56 conf_get_str: [3DES-SHA]:HASH_ALGORITHM->SHA
12:49:56 conf_get_str: [3DES-SHA]:AUTHENTICATION_METHOD->PRE_SHARED
12:49:56 conf_get_str: [3DES-SHA]:GROUP_DESCRIPTION->MODP_1024
12:49:56 conf_get_str: [3DES-SHA]:Life->LIFE_28800
12:49:56 conf_get_str: [LIFE_28800]:LIFE_TYPE->SECONDS
12:49:56 conf_get_str: [LIFE_28800]:LIFE_DURATION->28800,60:86400
12:49:56 conf_get_str: configuration value not found [3DES-SHA]:PRF
12:49:56 attribute_set_constant: no PRF in the 3DES-SHA section
12:49:56 conf_get_str: configuration value not found [3DES-SHA]:KEY_LENGTH
12:49:56 conf_get_str: configuration value not found [3DES-SHA]:FIELD_SIZE
12:49:56 conf_get_str: configuration value not found [3DES-SHA]:GROUP_ORDER
12:49:56 hash_get: requested algorithm 1
12:49:56 exchange_validate: checking for required SA
12:49:56 message_send: message 0x4fb44e00
12:49:56 ICOOKIE: 1aa459c4ff9d83dc
12:49:56 RCOOKIE: 0000000000000000
12:49:56 NEXT_PAYLOAD: SA
12:49:56 VERSION: 16
12:49:56 EXCH_TYPE: ID_PROT
12:49:56 FLAGS: [ ]
12:49:56 MESSAGE_ID: 00000000
12:49:56 LENGTH: 180
12:49:56 message_send: [removed]
12:49:56 exchange_run: exchange 0x48a5ce00 finished step 0, advancing...
12:49:56 transport_fd_set: transport 0x47b91300 (virtual 0x47b91180) fd 11
12:49:56 transport_fd_set: transport 0x47b91280 (virtual 0x47b91180) fd 10
12:49:56 transport_pending_wfd_set: transport 0x476a4900 (virtual 0x476a4a00)
fd 11 pending
12:49:56 transport_pending_wfd_set: transport 0x4777d980 (virtual 0x476a4a00)
fd 10 pending
12:49:56 transport_reference: transport 0x476a4a00 now has 2 references
12:49:56 transport_reference: transport 0x476a4a00 now has 3 references
[...]
[lots of transport_release messages]
[...]
12:49:57 transport_release: transport 0x47531a00 had 2 references
12:49:57 transport_release: transport 0x47b91180 had 3 references
12:49:57 transport_release: transport 0x47b91180 had 2 references
12:49:57 transport_fd_set: transport 0x47b91300 (virtual 0x47b91180) fd 11
12:49:57 transport_fd_set: transport 0x47b91280 (virtual 0x47b91180) fd 10
12:49:57 transport_setup: added 0x476a4e80 to transport list
12:49:57 transport_setup: added 0x476a4f00 to transport list
12:49:57 virtual_clone: old 0x47b91180 new 0x476a4e00 (main is 0x476a4e80)
12:49:57 transport_setup: virtual transport 0x476a4e00
12:49:57 transport_reference: transport 0x476a4e00 now has 1 references
12:49:57 message_alloc: allocated 0x4d9c6000
12:49:57 message_recv: message 0x4d9c6000
12:49:57 ICOOKIE: 1aa459c4ff9d83dc
12:49:57 RCOOKIE: dd04fc2fbc38c9eb
12:49:57 NEXT_PAYLOAD: SA
12:49:57 VERSION: 16
12:49:57 EXCH_TYPE: ID_PROT
12:49:57 FLAGS: [ ]
12:49:57 MESSAGE_ID: 00000000
12:49:57 LENGTH: 100
12:49:57 message_recv: [removed]
12:49:57 sa_remove: SA 0x4acb7800 removed from SA list
12:49:57 sa_release: SA 0x4acb7800 had 3 references
12:49:57 transport_reference: transport 0x476a4e00 now has 2 references
12:49:57 sa_reference: SA 0x4acb7800 now has 3 references
12:49:57 sa_enter: SA 0x4acb7800 added to SA list
12:49:57 message_check_duplicate: last_received 0x0
12:49:57 message_free: freeing 0x4fb44e00
12:49:57 timer_remove_event: removing event message_send_expire(0x4fb44e00)
12:49:57 transport_release: transport 0x476a4a00 had 1 references
12:49:57 transport_release: freeing 0x476a4a00
12:49:57 udp_remove: removed transport 0x476a4900
12:49:57 udp_remove: removed transport 0x4777d980
12:49:57 virtual_remove: removed 0x476a4a00
12:49:57 sa_release: SA 0x4acb7800 had 3 references
12:49:57 message_parse_payloads: offset 28 payload SA
12:49:57 message_parse_payloads: offset 80 payload VENDOR
12:49:57 message_validate_payloads: payload SA at 0x476a4f9c of message
0x4d9c6000
12:49:57 DOI: 1
12:49:57 SIT:
12:49:57 sa_reference: SA 0x4acb7800 now has 3 references
12:49:57 message_parse_payloads: offset 40 payload PROPOSAL
12:49:57 message_parse_payloads: offset 48 payload TRANSFORM
12:49:57 Transform 1's attributes
12:49:57 Attribute ENCRYPTION_ALGORITHM value 5
12:49:57 Attribute HASH_ALGORITHM value 2
12:49:57 Attribute GROUP_DESCRIPTION value 2
12:49:57 Attribute AUTHENTICATION_METHOD value 1
12:49:57 Attribute LIFE_TYPE value 1
12:49:57 Attribute LIFE_DURATION value 28800
12:49:57 message_validate_payloads: payload PROPOSAL at 0x476a4fa8 of message
0x4d9c6000
12:49:57 NO: 1
12:49:57 PROTO: ISAKMP
12:49:57 SPI_SZ: 0
12:49:57 NTRANSFORMS: 1
12:49:57 SPI:
12:49:57 message_validate_payloads: payload TRANSFORM at 0x476a4fb0 of message
0x4d9c6000
12:49:57 NO: 1
12:49:57 ID: 1
12:49:57 SA_ATTRS:
12:49:57 message_validate_payloads: payload VENDOR at 0x476a4fd0 of message
0x4d9c6000
12:49:57 ID:
12:49:57 nat_t_check_vendor_payload: NAT-T capable peer detected
12:49:57 transport_reference: transport 0x476a4e00 now has 3 references
12:49:57 transport_release: transport 0x476a4e00 had 3 references
12:49:57 exchange_validate: checking for required SA
12:49:57 hash_get: requested algorithm 1
12:49:57 message_negotiate_sa: transform 1 proto 1 proposal 1 ok
12:49:57 sa_validate_xf_attrs: phase 1 mode 0 type 1 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 0 type 2 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 0 type 4 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 0 type 3 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 0 type 11 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 0 type 12 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 1 type 1 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 1 type 2 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 1 type 3 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 1 type 4 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 1 type 11 len 2
12:49:57 sa_validate_xf_attrs: phase 1 mode 1 type 12 len 2
12:49:57 sa_validate_proto_xf: attr_map xf 0x4744d3c0 proto 0x476a4d00 pa
0x43373c20 found 1
12:49:57 sa_validate_proto_xf: req_attr xf 0x4744d3c0 proto 0x476a4d00 pa
0x43373c20 found 1
12:49:57 sa_add_transform: proto 0x476a4d00 no 1 proto 1 chosen 0x4744d3c0 sa
0x4acb7800 id 1
12:49:57 conf_get_str: [Default-main-mode]:Transforms->3DES-SHA
12:49:57 conf_get_str: [3DES-SHA]:ENCRYPTION_ALGORITHM->3DES_CBC
12:49:57 conf_get_str: [3DES-SHA]:HASH_ALGORITHM->SHA
12:49:57 conf_get_str: [3DES-SHA]:GROUP_DESCRIPTION->MODP_1024
12:49:57 conf_get_str: [3DES-SHA]:AUTHENTICATION_METHOD->PRE_SHARED
12:49:57 conf_get_str: [3DES-SHA]:Life->LIFE_28800
12:49:57 conf_get_str: [3DES-SHA]:Life->LIFE_28800
12:49:57 conf_get_str: [LIFE_28800]:LIFE_TYPE->SECONDS
12:49:57 conf_get_str: [3DES-SHA]:Life->LIFE_28800
12:49:57 conf_get_str: [3DES-SHA]:Life->LIFE_28800
12:49:57 conf_get_str: [LIFE_28800]:LIFE_DURATION->28800,60:86400
12:49:57 conf_get_str: [LIFE_28800]:LIFE_DURATION->28800,60:86400
12:49:57 conf_match_num: LIFE_28800:LIFE_DURATION 60<=28800<=86400?
12:49:57 ike_phase_1_validate_prop: success
12:49:57 message_negotiate_sa: proposal 1 succeeded
12:49:57 ipsec_decode_transform: transform 1 chosen
12:49:57 hash_get: requested algorithm 1
12:49:57 group_get: returning 0x476a4900 of group 2
12:49:57 exchange_run: exchange 0x48a5ce00 finished step 1, advancing...
12:49:57 transport_reference: transport 0x476a4e00 now has 3 references
12:49:57 message_alloc: allocated 0x4fb44f00
12:49:57 sa_reference: SA 0x4acb7800 now has 4 references
12:49:57 ipsec_g_x: g^xi:
12:49:57 09e56596 0623a97b be4c9a09 bf442e79 1a48bea8 97e1d542 2f2ecf7a 61596e2b
12:49:57 [rest removed]
12:49:57 exchange_nonce: NONCE_i:
12:49:57 41ab567b [rest removed]
12:49:57 hash_get: requested algorithm 1
12:49:57 hash_get: requested algorithm 1
12:49:57 exchange_validate: checking for required KEY_EXCH
12:49:57 exchange_validate: checking for required NONCE
12:49:57 message_send: message 0x4fb44f00
12:49:57 ICOOKIE: 1aa459c4ff9d83dc
12:49:57 RCOOKIE: dd04fc2fbc38c9eb
12:49:57 NEXT_PAYLOAD: KEY_EXCH
12:49:57 VERSION: 16
12:49:57 EXCH_TYPE: ID_PROT
12:49:57 FLAGS: [ ]
12:49:57 MESSAGE_ID: 00000000
12:49:57 LENGTH: 228
12:49:57 message_send: [removed]
12:49:57 exchange_run: exchange 0x48a5ce00 finished step 2, advancing...
12:49:57 transport_reference: transport 0x476a4e00 now has 4 references
12:49:57 transport_reference: transport 0x476a4e00 now has 5 references
12:49:57 transport_reference: transport 0x44980d00 now has 3 references
12:49:57 transport_reference: transport 0x44980d00 now has 4 references
12:49:57 transport_reference: transport 0x476a4700 now has 2 references
12:49:57 transport_reference: transport 0x476a4700 now has 3 references
12:49:57 transport_reference: transport 0x44591680 now has 3 references
[...]
[lots of transport_release messages]
[...]
12:49:59 transport_release: transport 0x4777d680 had 2 references
12:49:59 transport_release: transport 0x47531a00 had 3 references
12:49:59 transport_release: transport 0x47531a00 had 2 references
12:49:59 transport_release: transport 0x47b91180 had 3 references
12:49:59 transport_release: transport 0x47b91180 had 2 references
12:49:59 transport_fd_set: transport 0x47b91300 (virtual 0x47b91180) fd 11
12:49:59 transport_fd_set: transport 0x47b91280 (virtual 0x47b91180) fd 10
12:49:59 transport_setup: added 0x48542180 to transport list
12:49:59 transport_setup: added 0x46cd4b00 to transport list
12:49:59 virtual_clone: old 0x47b91180 new 0x4777d980 (main is 0x48542180)
12:49:59 transport_setup: virtual transport 0x4777d980
12:49:59 transport_reference: transport 0x4777d980 now has 1 references
12:49:59 message_alloc: allocated 0x4d9c6200
12:49:59 message_recv: message 0x4d9c6200
12:49:59 ICOOKIE: 1aa459c4ff9d83dc
12:49:59 RCOOKIE: dd04fc2fbc38c9eb
12:49:59 NEXT_PAYLOAD: KEY_EXCH
12:49:59 VERSION: 16
12:49:59 EXCH_TYPE: ID_PROT
12:49:59 FLAGS: [ ]
12:49:59 MESSAGE_ID: 00000000
12:49:59 LENGTH: 304
12:49:59 message_recv: [removed]
2:49:59 sa_reference: SA 0x4acb7800 now has 5 references
12:49:59 message_check_duplicate: last_received 0x4d9c6000
12:49:59 message_check_duplicate: last_received:
12:49:59 [removed]
12:49:59 message_free: freeing 0x4fb44f00
12:49:59 timer_remove_event: removing event message_send_expire(0x4fb44f00)
12:49:59 transport_release: transport 0x476a4e00 had 3 references
12:49:59 sa_release: SA 0x4acb7800 had 5 references
12:49:59 message_parse_payloads: offset 28 payload KEY_EXCH
12:49:59 message_parse_payloads: offset 160 payload NONCE
12:49:59 message_parse_payloads: offset 184 payload VENDOR
12:49:59 message_parse_payloads: offset 204 payload VENDOR
12:49:59 message_parse_payloads: offset 224 payload VENDOR
12:49:59 message_parse_payloads: offset 244 payload VENDOR
12:49:59 message_parse_payloads: offset 256 payload NAT_D_DRAFT
12:49:59 message_parse_payloads: offset 280 payload NAT_D_DRAFT
12:49:59 message_validate_payloads: payload KEY_EXCH at 0x4b60a61c of message
0x4d9c6200
12:49:59 DATA:
12:49:59 message_validate_payloads: payload NONCE at 0x4b60a6a0 of message
0x4d9c6200
12:49:59 DATA:
12:49:59 message_validate_payloads: payload VENDOR at 0x4b60a6b8 of message
0x4d9c6200
12:49:59 ID:
12:49:59 message_validate_payloads: payload VENDOR at 0x4b60a6cc of message
0x4d9c6200
12:49:59 ID:
12:49:59 dpd_check_vendor_payload: DPD capable peer detected
12:49:59 message_validate_payloads: payload VENDOR at 0x4b60a6e0 of message
0x4d9c6200
12:49:59 ID:
12:49:59 message_validate_payloads: payload VENDOR at 0x4b60a6f4 of message
0x4d9c6200
12:49:59 ID:
12:49:59 check_vendor_openbsd: bad size 8 != 16
12:49:59 nat_t_check_vendor_payload: bad size 8 != 16
12:49:59 last message repeated 2 times
12:49:59 message_validate_payloads: payload NAT_D_DRAFT at 0x4b60a700 of
message 0x4d9c6200
12:49:59 DATA:
12:49:59 message_validate_payloads: payload NAT_D_DRAFT at 0x4b60a718 of
message 0x4d9c6200
12:49:59 DATA:
12:49:59 transport_reference: transport 0x4777d980 now has 2 references
12:49:59 transport_release: transport 0x476a4e00 had 2 references
12:49:59 exchange_validate: checking for required KEY_EXCH
12:49:59 exchange_validate: checking for required NONCE
12:49:59 ipsec_g_x: g^xr:
12:49:59 a67fb8c9 b1330747 fa7d7146 9cbcb49c a37cd98c 86b3d52e fa3666dd ad47f6ef
12:49:59 [rest removed]
12:49:59 exchange_nonce: NONCE_r:
12:49:59 abe486a6 75c4418c 20ab5c36 2264ac68 dc25f31f
12:49:59 hash_get: requested algorithm 1
12:49:59 hash_get: requested algorithm 1
12:49:59 nat_t_exchange_check_nat_d: no NAT
12:49:59 ike_phase_1_post_exchange_KE_NONCE: g^xy:
12:49:59 073fd08b becbdd0d 11c0419d 06f072a4 589b715e f40cb30a 3f576b4b 7248efc0
12:49:59 [rest removed]
12:49:59 conf_get_str: [WANLINK]:Authentication->OurSharedSecret
12:49:59 hash_get: requested algorithm 1
12:49:59 ike_phase_1_post_exchange_KE_NONCE: SKEYID:
12:49:59 eb8f3c01 [rest removed]
12:49:59 hash_get: requested algorithm 1
12:49:59 ike_phase_1_post_exchange_KE_NONCE: SKEYID_d:
12:49:59 13d469ee [rest removed]
12:49:59 ike_phase_1_post_exchange_KE_NONCE: SKEYID_a:
12:49:59 d097c223 [rest removed]
12:49:59 ike_phase_1_post_exchange_KE_NONCE: SKEYID_e:
12:49:59 54f51114 [rest removed]
12:49:59 hash_get: requested algorithm 1
12:49:59 crypto_init: key:
12:49:59 7ca52cc7 [rest removed]
12:49:59 crypto_init_iv: initialized IV:
12:49:59 f3332561 [rest removed]
12:49:59 message_free: freeing 0x4d9c6000
12:49:59 transport_release: transport 0x476a4e00 had 1 references
12:49:59 transport_release: freeing 0x476a4e00
12:49:59 udp_remove: removed transport 0x476a4f00
12:49:59 udp_remove: removed transport 0x476a4e80
12:49:59 virtual_remove: removed 0x476a4e00
12:49:59 sa_release: SA 0x4acb7800 had 4 references
12:49:59 exchange_run: exchange 0x48a5ce00 finished step 3, advancing...
12:49:59 transport_reference: transport 0x4777d980 now has 3 references
12:49:59 message_alloc: allocated 0x4d9c6000
12:49:59 sa_reference: SA 0x4acb7800 now has 4 references
12:49:59 conf_get_str: configuration value not found [WANLINK]:ID
12:49:59 conf_get_str: configuration value not found
[General]:Default-phase-1-ID
12:49:59 ike_phase_1_send_ID: IPV4_ADDR:
12:49:59 81f04002
12:49:59 hash_get: requested algorithm 1
12:49:59 pre_shared_encode_hash: HASH_I:
12:49:59 bb3b1e98 [rest removed]
12:49:59 exchange_validate: checking for required ID
12:49:59 exchange_validate: checking for required AUTH
12:49:59 crypto_encrypt: before encryption:
12:49:59 0800000c [rest removed]
12:49:59 crypto_encrypt: after encryption:
12:49:59 3af791fb [rest removed]
12:49:59 crypto_update_iv: updated IV:
12:49:59 2529452d [rest removed]
12:49:59 message_send: message 0x4d9c6000
12:49:59 ICOOKIE: 1aa459c4ff9d83dc
12:49:59 RCOOKIE: dd04fc2fbc38c9eb
12:49:59 NEXT_PAYLOAD: ID
12:49:59 VERSION: 16
12:49:59 EXCH_TYPE: ID_PROT
12:49:59 FLAGS: [ ENC ]
12:49:59 MESSAGE_ID: 00000000
12:49:59 LENGTH: 68
12:49:59 message_send: 1aa459c4 [rest removed]
12:49:59 exchange_run: exchange 0x48a5ce00 finished step 4, advancing...
12:49:59 transport_reference: transport 0x4777d980 now has 4 references
12:49:59 transport_reference: transport 0x4777d980 now has 5 references
12:49:59 transport_reference: transport 0x44980d00 now has 3 references
[...]
[lots of transport_release messages]
[...]
12:50:00 transport_release: transport 0x4777d680 had 3 references
12:50:00 transport_release: transport 0x4777d680 had 2 references
12:50:00 transport_release: transport 0x47531a00 had 3 references
12:50:00 transport_release: transport 0x47531a00 had 2 references
12:50:00 transport_release: transport 0x47b91180 had 3 references
12:50:00 transport_release: transport 0x47b91180 had 2 references
12:50:00 transport_fd_set: transport 0x47b91300 (virtual 0x47b91180) fd 11
12:50:00 transport_fd_set: transport 0x47b91280 (virtual 0x47b91180) fd 10
12:50:00 transport_setup: added 0x476a4e80 to transport list
12:50:00 transport_setup: added 0x476a4f00 to transport list
12:50:00 virtual_clone: old 0x47b91180 new 0x476a4e00 (main is 0x476a4e80)
12:50:00 transport_setup: virtual transport 0x476a4e00
12:50:00 transport_reference: transport 0x476a4e00 now has 1 references
12:50:00 message_alloc: allocated 0x4d9c6100
12:50:00 message_recv: message 0x4d9c6100
12:50:00 ICOOKIE: 1aa459c4ff9d83dc
12:50:00 RCOOKIE: dd04fc2fbc38c9eb
12:50:00 NEXT_PAYLOAD: ID
12:50:00 VERSION: 16
12:50:00 EXCH_TYPE: ID_PROT
12:50:00 FLAGS: [ ENC ]
12:50:00 MESSAGE_ID: 00000000
12:50:00 LENGTH: 68
12:50:00 message_recv: 1aa459c4 [rest removed]
12:50:00 sa_reference: SA 0x4acb7800 now has 5 references
12:50:00 message_check_duplicate: last_received 0x4d9c6200
12:50:00 message_check_duplicate: last_received:
12:50:00 1aa459c4 [removed]
12:50:00 message_free: freeing 0x4d9c6000
12:50:00 timer_remove_event: removing event message_send_expire(0x4d9c6000)
12:50:00 transport_release: transport 0x4777d980 had 3 references
12:50:00 sa_release: SA 0x4acb7800 had 5 references
12:50:00 crypto_decrypt: before decryption:
12:50:00 51613c49 [rest removed]
12:50:00 crypto_decrypt: after decryption:
12:50:00 0800000c [rest removed]
12:50:00 message_parse_payloads: offset 28 payload ID
12:50:00 message_parse_payloads: offset 40 payload HASH
12:50:00 message_validate_payloads: payload ID at 0x476a4f9c of message
0x4d9c6100
12:50:00 TYPE: 1
12:50:00 DOI_DATA: 1101f4
12:50:00 DATA:
12:50:00 ipsec_validate_id_information: proto 17 port 500 type 1
12:50:00 ipsec_validate_id_information: IPv4:
12:50:00 d5620735
12:50:00 message_validate_payloads: payload HASH at 0x476a4fa8 of message
0x4d9c6100
12:50:00 DATA:
12:50:00 transport_reference: transport 0x476a4e00 now has 2 references
12:50:00 transport_release: transport 0x4777d980 had 2 references
12:50:00 exchange_validate: checking for required ID
12:50:00 exchange_validate: checking for required AUTH
12:50:00 conf_get_str: configuration value not found [WANLINK]:Remote-ID
12:50:00 ike_phase_1_recv_ID: IPV4_ADDR:
12:50:00 d5620735
12:50:00 pre_shared_decode_hash: HASH_R:
12:50:00 4b4428fb [rest removed]
12:50:00 hash_get: requested algorithm 1
12:50:00 ike_phase_1_recv_AUTH: computed HASH_R:
12:50:00 4b4428fb [rest removed]
12:50:00 message_free: freeing 0x4d9c6200
12:50:00 transport_release: transport 0x4777d980 had 1 references
12:50:00 transport_release: freeing 0x4777d980
12:50:00 udp_remove: removed transport 0x46cd4b00
12:50:00 udp_remove: removed transport 0x48542180
12:50:00 virtual_remove: removed 0x4777d980
12:50:00 sa_release: SA 0x4acb7800 had 4 references
12:50:00 crypto_update_iv: updated IV:
12:50:00 ba04dc55 [rest removed]
12:50:00 exchange_finalize: 0x48a5ce00 WANLINK Default-main-mode policy
initiator phase 1 doi 1 exchange 2 step 5
12:50:00 exchange_finalize: icookie 1aa459c4ff9d83dc rcookie dd04fc2fbc38c9eb
12:50:00 exchange_finalize: msgid 00000000
12:50:00 checking whether new SA replaces existing SA with IDs 81f04002:
129.240.64.2 d5620735: 213.98.7.53
12:50:00 sa_find: return SA 0x4aa1fc00
12:50:00 sa_mark_replaced: SA 0x4aa1fc00 (WANLINK) marked as replaced
12:50:00 sa_find: no SA matched query
12:50:00 conf_get_str: configuration value not found [WANLINK]:Flags
12:50:00 exchange_finalize: phase 1 done: initiator id 81f04002: 129.240.64.2,
responder id d5620735: 213.98.7.53, src: 129.240.64.2 dst: 213.98.7.53
12:50:00 sa_setup_expirations: SA 0x4acb7800 soft timeout in 24969 seconds
12:50:00 timer_add_event: event sa_soft_expire(0x4acb7800) added before
sa_hard_expire(0x4948fc00), expiration in 24969s
12:50:00 sa_reference: SA 0x4acb7800 now has 4 references
12:50:00 sa_setup_expirations: SA 0x4acb7800 hard timeout in 28800 seconds
12:50:00 timer_add_event: event sa_hard_expire(0x4acb7800) added before
sa_soft_expire(0x4acb7e00), expiration in 28800s
12:50:00 sa_reference: SA 0x4acb7800 now has 5 references
12:50:00 sa_find: no SA matched query
12:50:00 sa_release: SA 0x4acb7800 had 5 references
12:50:00 conf_get_str: configuration value not found
[General]:DPD-check-interval
12:50:00 timer_remove_event: removing event exchange_free_aux(0x48a5ce00)
12:50:00 exchange_free_aux: freeing exchange 0x48a5ce00
12:50:00 message_free: freeing 0x4d9c6100
12:50:00 transport_release: transport 0x476a4e00 had 2 references
12:50:00 sa_release: SA 0x4acb7800 had 4 references
12:50:00 transport_reference: transport 0x476a4e00 now has 2 references
12:50:00 transport_reference: transport 0x476a4e00 now has 3 references
12:50:00 transport_reference: transport 0x44980d00 now has 3 references
[...]
[lots of transport_release messages]
[...]
Sven
