I have two bsd firewall / routers that have a vpn between them ...
sometimes. They have a late May build of 4.0 386, they have been
working well until a few days ago, and we of course all swear that
nothing was changed... they just started failing.
I left last night with tunnels up and running, came in this morning and
found them down again. Isakmpd is running on both ends, on my 'client
network' end the I started it with " isakmpd -TLv -D A=40 " , below is
some log.
I had found that if I restarted the daemon on the 'server network' side
that I could get the tunnels to come up, but it might require a couple
of attempts, so I really can not prove it was merely a coincidence that
were starting. This morning I found that the clocks were off between
the fws and synched them, then restarted isakmpd on the client net side
the tunnels came right up.
I claim that pf is configured properly, else the tunnels would never
come up. I use preshared keys, I know they match again because the
tunnels work for a while.
I have never really seen tunnels "just go down" once running, so what
would you do to isolate the cause?
Any help would be appreciated.
-------------snip with tunnels down ------
Jul 12 06:31:29 mz1000wa isakmpd[13493]: timer_handle_expirations: event
message_send_expire(0x87234480)
Jul 12 06:31:29 mz1000wa isakmpd[13493]: timer_add_event: event
message_send_expire(0x87234480) added before
exchange_free_aux(0x7ed17700), expiration in 11s
Jul 12 06:31:29 mz1000wa isakmpd[13493]: timer_add_event: event
exchange_free_aux(0x7ed17a00) added last, expiration in 120s
Jul 12 06:31:29 mz1000wa isakmpd[13493]: exchange_setup_p1: 0x7ed17a00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 06:31:29 mz1000wa isakmpd[13493]: exchange_setup_p1: icookie
987bc831de38f5d4 rcookie 93d3d4c89d53786b
Jul 12 06:31:29 mz1000wa isakmpd[13493]: exchange_setup_p1: msgid 00000000
Jul 12 06:31:29 mz1000wa isakmpd[13493]: isakmp_responder: got NOTIFY of
type INVALID_COOKIE, ignoring
Jul 12 06:31:29 mz1000wa isakmpd[13493]: exchange_finalize: 0x7ed17a00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 06:31:29 mz1000wa isakmpd[13493]: exchange_finalize: icookie
987bc831de38f5d4 rcookie 93d3d4c89d53786b
Jul 12 06:31:29 mz1000wa isakmpd[13493]: exchange_finalize: msgid 00000000
Jul 12 06:31:29 mz1000wa isakmpd[13493]: timer_remove_event: removing
event exchange_free_aux(0x7ed17a00)
Jul 12 06:31:29 mz1000wa isakmpd[13493]: message_free: freeing 0x87234500
Jul 12 06:31:33 mz1000wa isakmpd[13493]: message_free: freeing 0x87234500
Jul 12 06:31:40 mz1000wa isakmpd[13493]: timer_handle_expirations: event
message_send_expire(0x87234480)
Jul 12 06:31:40 mz1000wa isakmpd[13493]: timer_add_event: event
message_send_expire(0x87234480) added before
exchange_free_aux(0x7ed17700), expiration in 13s
Jul 12 06:31:40 mz1000wa isakmpd[13493]: timer_add_event: event
exchange_free_aux(0x7ed17a00) added last, expiration in 120s
Jul 12 06:31:40 mz1000wa isakmpd[13493]: exchange_setup_p1: 0x7ed17a00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 06:31:40 mz1000wa isakmpd[13493]: exchange_setup_p1: icookie
b65fccde1f52143b rcookie fee87d767fbe664b
Jul 12 06:31:40 mz1000wa isakmpd[13493]: exchange_setup_p1: msgid 00000000
Jul 12 06:31:40 mz1000wa isakmpd[13493]: isakmp_responder: got NOTIFY of
type INVALID_COOKIE, ignoring
Jul 12 06:31:40 mz1000wa isakmpd[13493]: exchange_finalize: 0x7ed17a00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 06:31:40 mz1000wa isakmpd[13493]: exchange_finalize: icookie
b65fccde1f52143b rcookie fee87d767fbe664b
Jul 12 06:31:40 mz1000wa isakmpd[13493]: exchange_finalize: msgid 00000000
Jul 12 06:31:40 mz1000wa isakmpd[13493]: timer_remove_event: removing
event exchange_free_aux(0x7ed17a00)
Jul 12 06:31:40 mz1000wa isakmpd[13493]: message_free: freeing 0x87234500
Jul 12 06:31:46 mz1000wa isakmpd[13493]: message_free: freeing 0x87234500
Jul 12 06:31:53 mz1000wa isakmpd[13493]: timer_handle_expirations: event
message_send_expire(0x87234480)
Jul 12 06:31:53 mz1000wa isakmpd[13493]: timer_add_event: event
message_send_expire(0x87234480) added before
exchange_free_aux(0x7ed17700), expiration in 15s
Jul 12 06:31:53 mz1000wa isakmpd[13493]: timer_add_event: event
exchange_free_aux(0x7ed17a00) added last, expiration in 120s
Jul 12 06:31:53 mz1000wa isakmpd[13493]: exchange_setup_p1: 0x7ed17a00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 06:31:53 mz1000wa isakmpd[13493]: exchange_setup_p1: icookie
6de5b4121e72cece rcookie 33e61848a188464b
Jul 12 06:31:53 mz1000wa isakmpd[13493]: exchange_setup_p1: msgid 00000000
Jul 12 06:31:53 mz1000wa isakmpd[13493]: isakmp_responder: got NOTIFY of
type INVALID_COOKIE, ignoring
Jul 12 06:31:53 mz1000wa isakmpd[13493]: exchange_finalize: 0x7ed17a00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 06:31:53 mz1000wa isakmpd[13493]: exchange_finalize: icookie
6de5b4121e72cece rcookie 33e61848a188464b
Jul 12 06:31:53 mz1000wa isakmpd[13493]: exchange_finalize: msgid 00000000
Jul 12 06:31:53 mz1000wa isakmpd[13493]: timer_remove_event: removing
event exchange_free_aux(0x7ed17a00)
Jul 12 06:31:53 mz1000wa isakmpd[13493]: message_free: freeing 0x87234500
Jul 12 06:32:01 mz1000wa isakmpd[13493]: message_free: freeing 0x87234500
------------ end snip with tunnels down -
------------snip with tunnels up-
Jul 12 07:21:49 mz1000wa isakmpd[27815]: timer_add_event: event
exchange_free_aux(0x80928b00) added before sa_soft_expire(0x8ab11400),
expiration in 120s
Jul 12 07:21:49 mz1000wa isakmpd[27815]: exchange_setup_p1: 0x80928b00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 07:21:49 mz1000wa isakmpd[27815]: exchange_setup_p1: icookie
df0ccaeb24fcadff rcookie 9c289e7ed853fd2d
Jul 12 07:21:49 mz1000wa isakmpd[27815]: exchange_setup_p1: msgid 00000000
Jul 12 07:21:49 mz1000wa isakmpd[27815]: isakmp_responder: got NOTIFY of
type INVALID_COOKIE, ignoring
Jul 12 07:21:49 mz1000wa isakmpd[27815]: exchange_finalize: 0x80928b00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 07:21:49 mz1000wa isakmpd[27815]: exchange_finalize: icookie
df0ccaeb24fcadff rcookie 9c289e7ed853fd2d
Jul 12 07:21:49 mz1000wa isakmpd[27815]: exchange_finalize: msgid 00000000
Jul 12 07:21:49 mz1000wa isakmpd[27815]: timer_remove_event: removing
event exchange_free_aux(0x80928b00)
Jul 12 07:21:49 mz1000wa isakmpd[27815]: message_free: freeing 0x84ebf500
Jul 12 07:21:58 mz1000wa isakmpd[27815]: timer_handle_expirations: event
message_send_expire(0x84ebf480)
Jul 12 07:21:58 mz1000wa isakmpd[27815]: transport_send_messages:
message 0x84ebf480 scheduled for retransmission 3 in 11 secs
Jul 12 07:21:58 mz1000wa isakmpd[27815]: timer_add_event: event
message_send_expire(0x84ebf480) added before
exchange_free_aux(0x80928700), expiration in 11s
Jul 12 07:21:58 mz1000wa isakmpd[27815]: timer_add_event: event
exchange_free_aux(0x80928b00) added before sa_soft_expire(0x8ab11400),
expiration in 120s
Jul 12 07:21:58 mz1000wa isakmpd[27815]: exchange_setup_p1: 0x80928b00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 07:21:58 mz1000wa isakmpd[27815]: exchange_setup_p1: icookie
eb4b177fc46f76ce rcookie 6d8e42753b791fa8
Jul 12 07:21:58 mz1000wa isakmpd[27815]: exchange_setup_p1: msgid 00000000
Jul 12 07:21:58 mz1000wa isakmpd[27815]: isakmp_responder: got NOTIFY of
type INVALID_COOKIE, ignoring
Jul 12 07:21:58 mz1000wa isakmpd[27815]: exchange_finalize: 0x80928b00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 07:21:58 mz1000wa isakmpd[27815]: exchange_finalize: icookie
eb4b177fc46f76ce rcookie 6d8e42753b791fa8
Jul 12 07:21:58 mz1000wa isakmpd[27815]: exchange_finalize: msgid 00000000
Jul 12 07:21:58 mz1000wa isakmpd[27815]: timer_remove_event: removing
event exchange_free_aux(0x80928b00)
Jul 12 07:21:58 mz1000wa isakmpd[27815]: message_free: freeing 0x84ebf500
Jul 12 07:21:58 mz1000wa isakmpd[27815]: message_free: freeing 0x84ebf500
Jul 12 07:22:09 mz1000wa isakmpd[27815]: timer_handle_expirations: event
message_send_expire(0x84ebf480)
Jul 12 07:22:09 mz1000wa isakmpd[27815]: transport_send_messages:
message 0x84ebf480 scheduled for retransmission 4 in 13 secs
Jul 12 07:22:09 mz1000wa isakmpd[27815]: timer_add_event: event
message_send_expire(0x84ebf480) added before
exchange_free_aux(0x80928700), expiration in 13s
Jul 12 07:22:09 mz1000wa isakmpd[27815]: timer_add_event: event
exchange_free_aux(0x80928b00) added before sa_soft_expire(0x8ab11400),
expiration in 120s
Jul 12 07:22:09 mz1000wa isakmpd[27815]: exchange_setup_p1: 0x80928b00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 07:22:09 mz1000wa isakmpd[27815]: exchange_setup_p1: icookie
8abc474c9644eec8 rcookie 984438e69c259dd5
Jul 12 07:22:09 mz1000wa isakmpd[27815]: exchange_setup_p1: msgid 00000000
Jul 12 07:22:09 mz1000wa isakmpd[27815]: isakmp_responder: got NOTIFY of
type INVALID_COOKIE, ignoring
Jul 12 07:22:09 mz1000wa isakmpd[27815]: exchange_finalize: 0x80928b00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 07:22:09 mz1000wa isakmpd[27815]: exchange_finalize: icookie
8abc474c9644eec8 rcookie 984438e69c259dd5
Jul 12 07:22:09 mz1000wa isakmpd[27815]: exchange_finalize: msgid 00000000
Jul 12 07:22:09 mz1000wa isakmpd[27815]: timer_remove_event: removing
event exchange_free_aux(0x80928b00)
Jul 12 07:22:09 mz1000wa isakmpd[27815]: message_free: freeing 0x84ebf500
Jul 12 07:22:09 mz1000wa isakmpd[27815]: message_free: freeing 0x84ebf500
Jul 12 07:22:22 mz1000wa isakmpd[27815]: timer_handle_expirations: event
message_send_expire(0x84ebf480)
Jul 12 07:22:22 mz1000wa isakmpd[27815]: transport_send_messages:
message 0x84ebf480 scheduled for retransmission 5 in 15 secs
Jul 12 07:22:22 mz1000wa isakmpd[27815]: timer_add_event: event
message_send_expire(0x84ebf480) added before
exchange_free_aux(0x80928700), expiration in 15s
Jul 12 07:22:22 mz1000wa isakmpd[27815]: timer_add_event: event
exchange_free_aux(0x80928b00) added before sa_soft_expire(0x8ab11400),
expiration in 120s
Jul 12 07:22:22 mz1000wa isakmpd[27815]: exchange_setup_p1: 0x80928b00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 07:22:22 mz1000wa isakmpd[27815]: exchange_setup_p1: icookie
9cc6869172f9236b rcookie 249e6b49d550c149
Jul 12 07:22:22 mz1000wa isakmpd[27815]: exchange_setup_p1: msgid 00000000
Jul 12 07:22:22 mz1000wa isakmpd[27815]: isakmp_responder: got NOTIFY of
type INVALID_COOKIE, ignoring
Jul 12 07:22:22 mz1000wa isakmpd[27815]: exchange_finalize: 0x80928b00
<unnamed> <no policy> policy responder phase 1 doi 0 exchange 5 step 0
Jul 12 07:22:22 mz1000wa isakmpd[27815]: exchange_finalize: icookie
9cc6869172f9236b rcookie 249e6b49d550c149
Jul 12 07:22:22 mz1000wa isakmpd[27815]: exchange_finalize: msgid 00000000
Jul 12 07:22:22 mz1000wa isakmpd[27815]: timer_remove_event: removing
event exchange_free_aux(0x80928b00)
------------ end snip with tunnels up-
-----------pcap with tunnels down ---------
06:54:09.171399 10.120.10.50.500 > 1.1.19.253.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: b4d01d2c55c161ef->0000000000000000 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
06:54:16.188520 10.120.10.50.500 > 1.1.19.253.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: b4d01d2c55c161ef->0000000000000000 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
06:54:25.199187 10.120.10.50.500 > 1.1.19.253.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: b4d01d2c55c161ef->0000000000000000 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
06:54:36.219754 10.120.10.50.500 > 1.1.19.253.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: b4d01d2c55c161ef->0000000000000000 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
06:54:49.240491 10.120.10.50.500 > 1.1.19.253.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: b4d01d2c55c161ef->0000000000000000 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
06:55:04.261721 10.120.10.50.500 > 1.1.19.253.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: b4d01d2c55c161ef->0000000000000000 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
06:55:07.116586 10.120.10.50.500 > 1.1.19.253.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: ea75144bdf0f2de0->0000000000000000 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
06:55:14.123097 10.120.10.50.500 > 1.1.19.253.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: ea75144bdf0f2de0->0000000000000000 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
06:55:14.123340 1.1.19.253.500 > 10.120.10.50.500: [udp sum ok] isakmp
v1.0 exchange ID_PROT
cookie: ea75144bdf0f2de0->57db114ef6f3d3b3 msgid: 00000000 len: 120
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 = 3600
payload: VENDOR len: 20 (supports OpenBSD-4.0)
payload: VENDOR len: 20 (supports DPD v1.0) [ttl 0] (id 1, len 148)
--------------------end pcap with tunnels down
